记录一次KeyDB缓慢的定位过程
这个问题出现在一套搭建在虚拟机上的Kubernetes 1.18集群上。集群有三个节点：
|
1 2 3 4 5 |
# kubectl get node -o wide NAME STATUS VERSION INTERNAL-IP OS-IMAGE KERNEL-VERSION CONTAINER-RUNTIME 192.168.104.51 Ready v1.18.3 192.168.104.51 CentOS Linux 7 (Core) 3.10.0-862.3.2.el7.x86_64 docker://19.3.9 192.168.104.72 Ready v1.18.3 192.168.104.72 CentOS Linux 7 (Core) 3.10.0-862.3.2.el7.x86_64 docker://19.3.9 192.168.104.108 Ready v1.18.3 192.168.104.108 CentOS Linux 7 (Core) 3.10.0-862.3.2.el7.x86_64 docker://19.3.9 |
KeyDB通过StatefulSet管理，一共有三个实例：
|
1 2 3 4 5 |
# kubectl -n default get pod -o wide -l app.kubernetes.io/name=keydb NAME READY STATUS RESTARTS IP NODE keydb-0 1/1 Running 0 172.29.2.63 192.168.104.108 keydb-1 1/1 Running 0 172.29.1.69 192.168.104.72 keydb-2 1/1 Running 0 172.29.1.121 192.168.104.51 |
这三个实例：
- 由于反亲和设置，会在每个节点上各运行一个实例
- 启用Active - Active（--active-replica）模式的多主（--multi-master）复制 ：每个实例都是另外两个的Slave，每个实例都支持读写
出现一个节点宕机的情况，就可能出现此故障。经过一段时间以后，会出现GET/PUT或者任何其它请求处理缓慢的情况。
此故障有两个明显的特征：
- 故障出现前需要等待的时间，随机性很强，有时甚至测试了数小时都没有发现请求缓慢的情况。常常发生的情况是，宕机后剩下的两个实例，一个很快出现缓慢问题，另外一个却还能运行较长时间
- 请求处理延缓的时长不定，有时候没有明显延缓，有时候长达10+秒。而且一次缓慢请求后，可以跟着10多次正常速度处理的请求。这个特征提示故障和某种周期性的、长时间占用的锁有关。在锁被释放的间隙，请求可以被快速处理
我们将节点192.168.104.108强制关闭，这样实例keydb-0无法访问，另外两个节点无法和它进行Replication。
分别登录另外两个节点，监控GET/SET操作的性能：
|
1 2 3 4 5 |
kubectl -n default exec -it keydb-1 -- bash -c \ 'while true; do key=keydb-1-$(date +%s); keydb-cli set $key $key-val; keydb-cli get $key; done' kubectl -n default exec -it keydb-2 -- bash -c \ 'while true; do key=keydb-2-$(date +%s); keydb-cli set $key $key-val; keydb-cli get $key; done' |
监控Replication相关信息：
|
1 2 3 |
watch -- kubectl -n default exec -i keydb-1 -- keydb-cli info replication watch -- kubectl -n default exec -i keydb-2 -- keydb-cli info replication |
监控KeyDB日志：
|
1 2 3 |
kubectl -n default logs keydb-1 -f kubectl -n default logs keydb-2 -f |
经过一段时间，keydb-1请求处理随机延缓的情况出现：
|
1 2 3 4 5 6 7 8 9 10 11 12 |
127.0.0.1:6379> set hello world OK (1.24s) 127.0.0.1:6379> set hello world OK (8.96s) 127.0.0.1:6379> get hello "world" (5.99s) 127.0.0.1:6379> get hello "world" (9.44s) |
此时keydb-2仍然正常运行，请求处理速度正常
获取keydb-1的慢查询，没有发现有价值的信息。而且延缓的时间没有计算在内：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
127.0.0.1:6379> slowlog get 10 1) 1) (integer) 7 2) (integer) 1611833042 3) (integer) 14431 # 最慢的查询才耗时14ms 4) 1) "set" 2) "keydb-1-1611833042" 3) "keydb-1-1611833042-val" 5) "127.0.0.1:38488" 6) "" 2) 1) (integer) 6 2) (integer) 1611831322 3) (integer) 14486 4) 1) "get" 2) "keydb-1-1611831312" 5) "127.0.0.1:51680" 6) "" |
部署KeyDB已经设置 --loglevel debug，以获得尽可能详尽的日志。
由于正在运行不间断执行SET/GET操作的脚本，因此日志量很大而刷屏，但是每隔一段时间就会出现卡顿。下面是keydb-1的日志片段：
|
1 2 3 4 5 6 7 8 9 10 |
7:11:S 28 Jan 2021 08:57:51.233 - Client closed connection 7:11:S 28 Jan 2021 08:57:51.251 - Accepted 127.0.0.1:44224 7:11:S 28 Jan 2021 08:57:51.252 - Client closed connection 7:12:S 28 Jan 2021 08:57:51.276 - Accepted 127.0.0.1:44226 7:11:S 28 Jan 2021 08:57:51.277 - Client closed connection # 这一行日志之后，卡顿了10s。没有任何日志输出 7:11:S 28 Jan 2021 08:57:51.279 * Connecting to MASTER keydb-0.keydb:6379 7:11:S 28 Jan 2021 08:58:01.290 * Unable to connect to MASTER: Resource temporarily unavailable 7:11:S 28 Jan 2021 08:58:01.290 - Accepted 127.0.0.1:44228 7:11:S 28 Jan 2021 08:58:01.290 - Accepted 127.0.0.1:44264 |
从日志信息上可以看到，卡顿前keydb-1正在尝试连接到已经宕机的keydb-0，这个连接尝试被阻塞10秒后报 EAGAIN错误。
阻塞期间SET/GET请求得不到处理，猜测原因包括：
- 连接keydb-0的时候，占用了某种全局的锁，SET/GET请求也需要持有该锁
- 连接keydb-0、处理SET/GET请求，由同一线程负责
第2种猜测应该不大可能，因为KeyDB宣称的优势之一就是，支持多线程处理请求。并且我们设置了参数 --server-threads 2，也就是有两个线程用于处理请求。
EAGAIN这个报错也没有参考价值，因为目前不卡顿的实例keydb-2输出的日志是一样的，只是没有任何卡顿：
|
1 2 3 |
7:11:S 28 Jan 2021 08:19:22.624 * Connecting to MASTER keydb-0.keydb:6379 # 仅仅耗时5ms即检测到连接失败 7:11:S 28 Jan 2021 08:19:22.629 * Unable to connect to MASTER: Resource temporarily unavailable |
我们使用的KeyDB版本是5.3.3，尝试用关键字“Connecting to MASTER”搜索，发现只有一个匹配，位于 replicationCron函数中。从函数名称上就可以看到，它是和复制（Replication）有关的定时任务。
KeyDB启动时会调用 initServer进行初始化，后者会在事件循环中每1ms调度一次 serverCron。serverCron负责后台任务的总体调度，它的一个职责就是，每1s调度一次replicationCron函数。
下面看一下replicationCron的源码：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 |
/* Replication cron function, called 1 time per second. */ void replicationCron(void) { static long long replication_cron_loops = 0; serverAssert(GlobalLocksAcquired()); listIter liMaster; listNode *lnMaster; listRewind(g_pserver->masters, &liMaster); // 遍历当前实例的每一个Master while ((lnMaster = listNext(&liMaster))) { redisMaster *mi = (redisMaster*)listNodeValue(lnMaster); std::unique_lock<decltype(mi->master->lock)> ulock; // 获得 Master的 客户端的 锁 if (mi->master != nullptr) ulock = decltype(ulock)(mi->master->lock); /* Non blocking connection timeout? */ // 如果当前复制状态为：正在连接到Master // 或者复制状态处于握手阶段（包含多个状态）且超时了 if (mi->masterhost && (mi->repl_state == REPL_STATE_CONNECTING || slaveIsInHandshakeState(mi)) && (time(NULL)-mi->repl_transfer_lastio) > g_pserver->repl_timeout) { // 那么取消握手 —— 取消进行中的非阻塞连接尝试，或者取消进行中的RDB传输 serverLog(LL_WARNING,"Timeout connecting to the MASTER..."); cancelReplicationHandshake(mi); } /* Bulk transfer I/O timeout? */ // 如果当前正在接收来自Master的RDB文件且超时了 if (mi->masterhost && mi->repl_state == REPL_STATE_TRANSFER && (time(NULL)-mi->repl_transfer_lastio) > g_pserver->repl_timeout) { serverLog(LL_WARNING,"Timeout receiving bulk data from MASTER... If the problem persists try to set the 'repl-timeout' parameter in keydb.conf to a larger value."); // 那么取消握手 cancelReplicationHandshake(mi); } /* Timed out master when we are an already connected replica? */ // 如果当前复制状态为：已连接。而且超时之前没有活动（正常情况下有心跳维持） if (mi->masterhost && mi->master && mi->repl_state == REPL_STATE_CONNECTED && (time(NULL)-mi->master->lastinteraction) > g_pserver->repl_timeout) { // 那么释放掉客户端资源 serverLog(LL_WARNING,"MASTER timeout: no data nor PING received..."); if (FCorrectThread(mi->master)) freeClient(mi->master); else freeClientAsync(mi->master); } /* Check if we should connect to a MASTER */ // 上面几个分支都不会匹配我们的场景，因为keydb-0已经宕机，因此 // 状态必然是REPL_STATE_CONNECT if (mi->repl_state == REPL_STATE_CONNECT) { // 这一行就是卡顿前的日志 serverLog(LL_NOTICE,"Connecting to MASTER %s:%d", mi->masterhost, mi->masterport); // 发起连接 if (connectWithMaster(mi) == C_OK) { serverLog(LL_NOTICE,"MASTER <-> REPLICA sync started"); } } // 每秒钟发送心跳给Master if (mi->masterhost && mi->master && !(mi->master->flags & CLIENT_PRE_PSYNC)) replicationSendAck(mi); } // 后面处理和本实例的Slave有关的逻辑，例如发送心跳。和我们的场景无关，略... } |
很明显，卡顿是因为调用 connectWithMaster导致的。从代码注释也可以看到，KeyDB期望这个连接操作是非阻塞的，但是不知道为何，在我们的场景中严重的阻塞了。
进一步查看connectWithMaster的代码：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 |
int connectWithMaster(redisMaster *mi) { int fd; fd = anetTcpNonBlockBestEffortBindConnect(NULL, mi->masterhost,mi->masterport,NET_FIRST_BIND_ADDR); if (fd == -1) { int sev = g_pserver->enable_multimaster ? LL_NOTICE : LL_WARNING; // 这一行是卡顿10s后的日志，因此阻塞发生在anetTcpNonBlockBestEffortBindConnect函数中 serverLog(sev,"Unable to connect to MASTER: %s", strerror(errno)); return C_ERR; } // ... } int anetTcpNonBlockBestEffortBindConnect(char *err, char *addr, int port, char *source_addr) { return anetTcpGenericConnect(err,addr,port,source_addr, // 非阻塞 + BestEffort绑定 ANET_CONNECT_NONBLOCK|ANET_CONNECT_BE_BINDING); } static int anetTcpGenericConnect(char *err, char *addr, int port, char *source_addr, int flags) { int s = ANET_ERR, rv; char portstr[6]; /* strlen("65535") + 1; */ struct addrinfo hints, *servinfo, *bservinfo, *p, *b; snprintf(portstr,sizeof(portstr),"%d",port); memset(&hints,0,sizeof(hints)); // 不指定地址族，这会触发getaddrinfo同时进行A/AAAA查询 hints.ai_family = AF_UNSPEC; hints.ai_socktype = SOCK_STREAM; // 根据Master的主机名查找得到IP地址信息（addrinfo）列表 if ((rv = getaddrinfo(addr,portstr,&hints,&servinfo)) != 0) { anetSetError(err, "%s", gai_strerror(rv)); return ANET_ERR; } // 遍历Master的IP地址列表 for (p = servinfo; p != NULL; p = p->ai_next) { // 创建套接字，如果socket/connect调用失败，则尝试下一个 if ((s = socket(p->ai_family,p->ai_socktype,p->ai_protocol)) == -1) continue; // 设置套接字选项SO_REUSEADDR if (anetSetReuseAddr(err,s) == ANET_ERR) goto error; // 设置套接字选项 SO_REUSEPORT if (flags & ANET_CONNECT_REUSEPORT && anetSetReusePort(err, s) != ANET_OK) goto error; // 调用fcntl设置 O_NONBLOCK if (flags & ANET_CONNECT_NONBLOCK && anetNonBlock(err,s) != ANET_OK) goto error; if (source_addr) { int bound = 0; /* Using getaddrinfo saves us from self-determining IPv4 vs IPv6 */ // 解析源地址 if ((rv = getaddrinfo(source_addr, NULL, &hints, &bservinfo)) != 0) { anetSetError(err, "%s", gai_strerror(rv)); goto error; } for (b = bservinfo; b != NULL; b = b->ai_next) { // 绑定到第一个源地址 if (bind(s,b->ai_addr,b->ai_addrlen) != -1) { bound = 1; break; } } freeaddrinfo(bservinfo); if (!bound) { // 绑定源地址失败，跳转到Best Effort绑定 anetSetError(err, "bind: %s", strerror(errno)); goto error; } } // 发起连接 if (connect(s,p->ai_addr,p->ai_addrlen) == -1) { // 我们的场景下套接字是非阻塞的，因此这里会立即返回EINPROGRESS，属于预期行为 if (errno == EINPROGRESS && flags & ANET_CONNECT_NONBLOCK) goto end; // 其它错误均认为失败，尝试连接下一个Master地址 close(s); s = ANET_ERR; continue; } goto end; } if (p == NULL) anetSetError(err, "creating socket: %s", strerror(errno)); error: if (s != ANET_ERR) { close(s); s = ANET_ERR; } end: freeaddrinfo(servinfo); // 上面指定源地址，绑定失败时跳转到此处。尝试不指定源地址来连接 if (s == ANET_ERR && source_addr && (flags & ANET_CONNECT_BE_BINDING)) { return anetTcpGenericConnect(err,addr,port,NULL,flags); } else { return s; } } |
尽管可以确定connectWithMaster调用的anetTcpGenericConnect就是发生阻塞的地方，但是从代码上看不出什么问题，就是简单的socket、bind，外加一个非阻塞的connect操作。
从现象上我们已经看到了，复制定时器卡顿的时候，请求处理也无法进行。通过代码分析，也明确了卡顿期间，复制定时器持有Master的客户端的锁。
那么，关于请求处理（线程？）会和复制定时器产生锁争用的猜测是否正确呢？
为了精确定位阻塞的代码，我们使用GDB进行单步跟踪：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
# 需要特权模式，否则无法加载符号表 docker run -it --rm --name gdb --privileged --net=host --pid=host --entrypoint gdb docker.gmem.cc/debug (gdb) attach 449 (gdb) break replication.cpp:3084 # 连续执行s，以step into anet.c (gdb) s # 连续执行n命令 (gdb) n # 卡顿后，查看变量 # 解析的地址 (gdb) p addr $2 = 0x7f2f31411281 "keydb-0.keydb" # getaddrinfo的返回值 (gdb) p rv $3 = -3 |
进入anetTcpGenericConnect后，逐行执行，多次测试，均在 anet.c的291行出现卡顿：
|
291 292 293 294 |
if ((rv = getaddrinfo(addr,portstr,&hints,&servinfo)) != 0) { anetSetError(err, "%s", gai_strerror(rv)); return ANET_ERR; } |
也就是说，调用getaddrinfo函数耗时可能长达数秒。这是来自glibc的标准函数，用于将主机名解析为IP地址。
调试过程中发现此函数的返回值是-3，我们的场景中，需要解析的地址是keydb-0.keydb，卡顿时函数的返回值是-3， man getaddrinfo可以了解到此返回值的意义：
EAI_AGAIN The name server returned a temporary failure indication. Try again later.
乍看起来，好像是DNS服务器，也就是K8S的CoreDNS存在问题。但无法解释此时keydb-2.keydb没有受到影响？
为了确认CoreDNS是否存在问题，我们分别在宿主机上、两个实例的网络命名空间中进行验证：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
# nslookup keydb-0.keydb.default.svc.cluster.local 10.96.0.10 Server: 10.96.0.10 Address: 10.96.0.10#53 ** server can't find keydb-0.keydb.default.svc.cluster.local: NXDOMAIN # nslookup keydb-0.keydb.svc.cluster.local 10.96.0.10 Server: 10.96.0.10 Address: 10.96.0.10#53 ** server can't find keydb-0.keydb.svc.cluster.local: NXDOMAIN # nslookup keydb-0.keydb.cluster.local 10.96.0.10 Server: 10.96.0.10 Address: 10.96.0.10#53 ** server can't find keydb-0.keydb.cluster.local: NXDOMAIN # nslookup keydb-0.keydb 10.96.0.10 Server: 10.96.0.10 Address: 10.96.0.10#53 ** server can't find keydb-0.keydb: SERVFAIL |
反复测试循环测试，没有任何解析缓慢的现象。此外，查看CoreDNS的日志，我们也发现了来自keydb-1.keydb和keydb-2.keydb的查询请求，请求都是通过UDP协议发送的，处理耗时都是亚毫秒级别。
也就是说，从KeyDB实例所在宿主机/命名空间到CoreDNS的网络链路、CoreDNS服务器自身，都没有问题。
这就让人头疼了……难道问题出在getaddrinfo函数内部？或者在单步跟踪时判断错误，问题和DNS无关？为了确认，我们在CoreDNS上动了点手脚，强制将keydb-0.keydb解析到一个不存在的IP地址：
|
1 2 3 4 5 6 7 |
.:53 { # ... hosts { 192.168.144.51 keydb-1.keydb } # ... } |
结果很快，卡顿的问题就消失了。所以，我们更加怀疑问题出在getaddrinfo函数上了。
查看文件/etc/lsb-release，可以看到KeyDB镜像是基于Ubuntu 18.04.4 LTS构建的，使用的libc6版本是2.27-3ubuntu1。
在launchpad.net找到了它的调试文件和源码。下载deb包，解压后复制到GDB容器，然后设置一下调试文件目录，就可以step into到glibc的代码进行跟踪了：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
ar x libc6-dbg_2.27-3ubuntu1_amd64.deb tar -xf data.tar.xz # 拷贝到我们正在运行GDB的容器 docker cp usr gdb:/root # 修改调试文件搜索目录 (gdb) set debug-file-directory /root/usr/lib/debug # 打断点，下面是缓慢的执行路径 (gdb) b anet.c:291 (gdb) b getaddrinfo.c:342 (gdb) b getaddrinfo.c:786 # (gdb) print fct4 # $2 = (nss_gethostbyname4_r) 0x7f32f97e9a70 <_nss_dns_gethostbyname4_r> (gdb) b dns-host.c:317 (gdb) b res_query.c:336 (gdb) b res_query.c:495 # invoke __res_context_querydomain (gdb) b res_query.c:601 # invoke __res_context_query (gdb) b res_query.c:216 # invoke __res_context_send (gdb) b res_send.c:1066 if buflen==45 # send_dg |
通过调试，我们发现getaddrinfo会依次对4个名字进行DNS查询：
keydb-0.keydb.default.svc.cluster.local.
keydb-0.keydb.svc.cluster.local.
keydb-0.keydb.cluster.local.
keydb-0.keydb.
CoreDNS的日志显示，所有请求都快速的处理完毕：
|
1 2 3 4 5 6 7 8 9 10 11 |
4242 "A IN keydb-0.keydb.default.svc.cluster.local. udp 68 false 512" NXDOMAIN qr,aa,rd 161 0.000215337s 38046 "AAAA IN keydb-0.keydb.default.svc.cluster.local. udp 68 false 512" NXDOMAIN qr,aa,rd 161 0.000203934s 23194 "A IN keydb-0.keydb.svc.cluster.local. udp 63 false 512" NXDOMAIN qr,aa,rd 156 0.000301011s 23722 "AAAA IN keydb-0.keydb.svc.cluster.local. udp 63 false 512" NXDOMAIN qr,aa,rd 156 0.000125386s 36552 "A IN keydb-0.keydb.cluster.local. udp 59 false 512" NXDOMAIN qr,aa,rd 152 0.000281247s 217 "AAAA IN keydb-0.keydb.cluster.local. udp 59 false 512" NXDOMAIN qr,aa,rd 152 0.000150689s 6776 "A IN keydb-0.keydb. udp 45 false 512" NOERROR - 0 0.000196686s 6776 "A IN keydb-0.keydb. udp 45 false 512" NOERROR - 0 0.000157011s |
最后一个名字，也就是传递给getaddrinfo的原始请求keydb-0.keydb.的处理过程有以下值得注意的点：
- 从GDB角度来看，卡顿就是在解析该名字时出现
- 从CoreDNS日志上看，没有AAAA请求。由于KeyDB指定了AF_UNSPEC，getaddrinfo会同时发送并等待A/AAAA应答。可能因为某种原因，该名字的AAAA解析过程没有完成，导致getaddrinfo一直等待到超时。作为对比，没有卡顿的keydb-2的A/AAAA查询处理过程都是正常的
- 其它名字是一次A请求，一次AAAA请求。该名字却是两次A请求，而且，第一次A请求日志出现了数秒后，第二次日志才出现。有可能第二次是getaddrinfo没有收到应答而进行的重试
- 前三个名字分别的错误码是NXDOMAIN，该名字的错误码却是NOERROR。通过nslookup/dig查询，错误码却是SERVFAIL，难道是CoreDNS日志有BUG？尽管如此，是否不同的错误码影响了getaddrinfo的行为
glibc的代码是优化过（也必须优化）的，GDB跟踪起来相当耗时，因此我们打算换一个角度来定位问题。基于上一节的分析，我们相信实例keydb-1.keydb在发送DNS请求的时候存在超时或丢包的情况，可以抓包来证实：
|
1 2 3 4 |
# 进入keydb-1.keydb的网络命名空间 nsenter -t 449 --net # 抓包 tcpdump -i any -vv -nn udp port 53 |
抓包的结果如下：
对 keydb-0.keydb.default.svc.cluster.local. 的A请求
172.29.1.69.42083 > 10.96.0.10.53: [bad udp cksum 0xb829 -> 0x95aa!] 22719+ A? keydb-0.keydb.default.svc.cluster.local. (68)
CoreDNS应答NXDomain
10.96.0.10.53 > 172.29.1.69.42083: [bad udp cksum 0xb886 -> 0x3f57!] 22719 NXDomain*- q: A? keydb-0.keydb.default.svc.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (161)
对keydb-0.keydb.default.svc.cluster.local. 的AAAA请求，注意，仍然使用之前的UDP套接字
172.29.1.69.42083 > 10.96.0.10.53: [bad udp cksum 0xb829 -> 0x4d76!] 41176+ AAAA? keydb-0.keydb.default.svc.cluster.local. (68)
CoreDNS应答NXDomain
10.96.0.10.53 > 172.29.1.69.42083: [bad udp cksum 0xb886 -> 0xf722!] 41176 NXDomain*- q: AAAA? keydb-0.keydb.default.svc.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (161)
对 keydb-0.keydb.svc.cluster.local. 的A请求，注意，这里使用了新的UDP套接字
172.29.1.69.45508 > 10.96.0.10.53: [bad udp cksum 0xb824 -> 0x3b5e!] 45156+ A? keydb-0.keydb.svc.cluster.local. (63)
CoreDNS应答NXDomain
10.96.0.10.53 > 172.29.1.69.45508: [bad udp cksum 0xb881 -> 0x21ce!] 45156 NXDomain*- q: A? keydb-0.keydb.svc.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (156)
对keydb-0.keydb.svc.cluster.local. 的AAAA请求
172.29.1.69.45508 > 10.96.0.10.53: [bad udp cksum 0xb824 -> 0x8a4e!] 18036+ AAAA? keydb-0.keydb.svc.cluster.local. (63)
CoreDNS应答NXDomain
10.96.0.10.53 > 172.29.1.69.45508: [bad udp cksum 0xb881 -> 0x70be!] 18036 NXDomain*- q: AAAA? keydb-0.keydb.svc.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (156)
对 keydb-0.keydb.cluster.local. 的A请求
172.29.1.69.48243 > 10.96.0.10.53: [bad udp cksum 0xb820 -> 0x5054!] 2718+ A? keydb-0.keydb.cluster.local. (59)
CoreDNS应答NXDomain
10.96.0.10.53 > 172.29.1.69.48243: [bad udp cksum 0xb87d -> 0x36c4!] 2718 NXDomain*- q: A? keydb-0.keydb.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (152)
对 keydb-0.keydb.cluster.local. 的AAAA请求
172.29.1.69.48243 > 10.96.0.10.53: [bad udp cksum 0xb820 -> 0x5147!] 61098+ AAAA? keydb-0.keydb.cluster.local. (59)
CoreDNS应答NXDomain，这里开始，我们保留时间戳那一行日志
14:42:15.028168 IP (tos 0x0, ttl 63, id 44636, offset 0, flags [DF], proto UDP (17), length 180)
10.96.0.10.53 > 172.29.1.69.48243: [bad udp cksum 0xb87d -> 0x37b7!] 61098 NXDomain*- q: AAAA? keydb-0.keydb.cluster.local. 0/1/0 ns: cluster.local. SOA ns.dns.cluster.local. hostmaster.cluster.local. 1612073759 7200 1800 86400 30 (152)
对keydb-0.keydb的A请求，这里还没有出现卡顿
14:42:15.028328 IP (tos 0x0, ttl 64, id 30583, offset 0, flags [DF], proto UDP (17), length 73)
172.29.1.69.47652 > 10.96.0.10.53: [bad udp cksum 0xb812 -> 0x181e!] 26682+ A? keydb-0.keydb. (45)
很快接收到CoreDNS的ServFail应答，抓包和我们nslookup/dig的错误码一致，CoreDNS日志显示的应该不正常
猜测“有可能第二次是getaddrinfo没有收到应答而进行的重试”被排除，至少说没收到应答不是网络层面的原因
14:42:15.028651 IP (tos 0x0, ttl 63, id 44637, offset 0, flags [DF], proto UDP (17), length 73)
10.96.0.10.53 > 172.29.1.69.47652: [bad udp cksum 0xb812 -> 0x981b!] 26682 ServFail- q: A? keydb-0.keydb. 0/0/0 (45)
再一次对keydb-0.keydb.的A请求，注意时间戳，刚好5秒之后，这是默认DNS请求超时。还是使用之前的套接字
14:42:20.029271 IP (tos 0x0, ttl 64, id 33006, offset 0, flags [DF], proto UDP (17), length 73)
172.29.1.69.47652 > 10.96.0.10.53: [bad udp cksum 0xb812 -> 0x181e!] 26682+ A? keydb-0.keydb. (45)
很快接收到CoreDNS的ServFail应答
14:42:20.029812 IP (tos 0x0, ttl 63, id 46397, offset 0, flags [DF], proto UDP (17), length 73)
10.96.0.10.53 > 172.29.1.69.47652: [bad udp cksum 0xb812 -> 0x981b!] 26682 ServFail- q: A? keydb-0.keydb. 0/0/0 (45)
通过上述分析我们可以相信，keydb-1.keydb容器到CoreDNS之间的DNS通信是没有问题的。但是，getaddrinfo似乎没有收到keydb-0.keydb的第一次应答，并且在超时（5s）之后进行重试
tcpdump和应用程序之间，还有个netfilter框架。回想起之前阅读过的文章：Kubernetes上和DNS相关的问题，conntrack相关的竞态条件可能导致DNS查询5秒超时。遗憾的是，这里的故障和此竞态条件无关：
- 通过 conntrack -S看到的 insert_failed是0
- 故障一旦出现，就每次都会超时5s，没有竞态条件的随机性
- 如果是conntrack竞态条件导致，无法解释为什么前面3个名字解析正常，也无法解释为什么CoreDNS中配置一个静态解析故障就消失
在IPv4中，我们使用 gethostbyname实现主机名到地址的解析。 getaddrinfo也用于地址解析，而且它是协议无关的，既可用于IPv4也可用于IPv6。它的原型如下：
|
1 2 3 4 |
int getaddrinfo(const char* hostname, // 主机名，可以使用IP地址或者DNS名称 const char* service, // 服务名，可以使用端口号或者/etc/services中的服务名 const struct addrinfo* hints, // 可以NULL，或者一个addrinfo，提示调用者想得到的信息类型 struct addrinfo** res); // 解析得到的addrinfo，地址的链表 |
此函数返回的是套接字地址信息的链表，地址信息存储在下面的addrinfo结构中。参数 hints会影响getaddrinfo的行为，提示信息同样存放在addrinfo结构中：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
struct addrinfo { // 额外的提示标记 int ai_flags; // 提示需要查询哪些地址族，默认AF_UNSPEC，这意味着同时查询IPv4和IPv6地址 // 也就是同时发起A/AAAA查询 int ai_family; // 提示偏好的套接字类型，例如SOCK_STREAM|SOCK_DGRAM，默认可以返回任何套接字类型 int ai_socktype; // 提示返回的套接字地址的协议类型 int ai_protocol; // 套接字地址 socklen_t ai_addrlen; struct sockaddr *ai_addr; // ... // 指向链表的下一条目 struct addrinfo *ai_next; }; |
很多软件调用getaddrinfo的时候，都会指定AF_UNSPEC（或者不提供hints，效果一样），例如KeyDB。但是，很多运行环境根本没有IPv6支持，这就凭白的给DNS服务器增加了负担。这也是在K8S中查看CoreDNS日志，总是会发现很多AAAA记录的原因。
KeyDB 5.3.3使用的glibc版本是2.27。函数getaddrinfo过于冗长，这里就不贴出来了，大概梳理一下：
- 如果可能，它会通过/var/run/nscd/socket访问DNS缓存服务，我们没有这个服务
- 初始化NSS的hosts数据库，如果没有在文件中配置，则默认使用 hosts: dns [!UNAVAIL=return] files，我们的环境下配置是 hosts: files dns
- 通过NSS进行名字查询，实际上是调用
gethostbyname4_r函数：
- 查找files源，调用 _nss_files_gethostbyname4_r函数，也就是打开/etc/hosts查找。K8S容器中，/etc/hosts中仅仅存在当前Pod的条目，因此files源不会匹配
- 查找dns源，调用
_nss_dns_gethostbyname4_r函数：
- 读取/etc/resolv.conf构建
resolv_context。我们的环境下，配置文件内容为：
123nameserver 10.96.0.10search default.svc.cluster.local svc.cluster.local cluster.localoptions ndots:5 -
调用 __res_context_search， 执行DNS查找逻辑。它会将上面的search domain作为域名后缀，产生多个名字，逐个尝试。每个名字查询失败时都会重试，重试时尽可能选择不同的DNS服务器。可能同时发起A/AAA查询
- 读取/etc/resolv.conf构建
resolv_context。我们的环境下，配置文件内容为：
__res_context_search()首先会计算一下，待查找名字中的dot的数量。如果名字以dot结尾，或者dot数量大于等于ndots，则直接调用 __res_context_querydomain向DNS服务器发请求，该函数会同时发起A/AAAA查询。
否则，它会根据/etc/resolv.conf中的search domain列表，给待查找的名字加后缀，然后多次向DNS服务器发请求。我们的环境下，待查找名字为keydb-0.keydb，getaddrinfo函数会依次尝试：
keydb-0.keydb.default.svc.cluster.local.
keydb-0.keydb.svc.cluster.local.
keydb-0.keydb.cluster.local.
keydb-0.keydb.
需要注意：
- 向DNS服务器发请求，仍然是由__res_context_querydomain()负责
- 一旦查找成功，就立即返回不再尝试其它search domain
- 不加修饰的原始名字，会放在最后尝试
在K8S中，*.cluster.local一般都由CoreDNS自身负责，处理速度会很快。至于keydb-0.keydb.的处理速度，如果为CoreDNS配置了上游DNS，则处理速度依赖于外部环境。
__res_context_querydomain仅仅是在domain参数不为空的时候，将name和domain连接起来，然后调用 __res_context_query函数。
__res_context_query负责和DNS服务器的交互，完成单个名字的DNS查询。它会调用 __res_context_mkquery构建一个查询请求（对应DNS报文），然后发送，然后等待应答。这是一个阻塞的过程，KeyDB在期望非阻塞的代码路径下调用getaddrinfo且没有任何缓存机制，同时还加了锁，我觉得是不妥的。这导致DNS缓慢/不可用会极大的影响KeyDB的服务质量。
发送DNS请求的代码在 __res_context_send中，重试逻辑发生在该函数中，我们的环境下重试次数为2，这解释了两次keydb-0.keydb. A查询：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 |
// 重试次数，statp->retry为2 for (try = 0; try < statp->retry; try++) { // 如果有多个DNS服务器，重试时会轮询它们 for (unsigned ns_shift = 0; ns_shift < statp->nscount; ns_shift++) { unsigned int ns = ns_shift + ns_offset; if (ns >= statp->nscount) ns -= statp->nscount; same_ns: if (__glibc_unlikely (v_circuit)) { // ... } else { // 使用UDP方式发送请求 n = send_dg(statp, buf, buflen, buf2, buflen2, &ans, &anssiz, &terrno, ns, &v_circuit, &gotsomewhere, ansp, ansp2, nansp2, resplen2, ansp2_malloced); if (n < 0) return (-1); if (n == 0 && (buf2 == NULL || *resplen2 == 0)) // 如果有多个DNS服务器的时候，会尝试下一个 goto next_ns; // ... } return (resplen); next_ns: ; } /*foreach ns*/ } /*foreach retry*/ |
通常情况下，都是通过UDP协议进行DNS查询的，因此会调用 send_dg函数。在我们的场景中，两次尝试均5秒超时（尽管抓包显示应答报文很快就收到），__res_context_send设置错误码ETIMEDOUT，返回-1：
|
1 2 3 4 5 6 7 8 9 |
__res_iclose(statp, false); if (!v_circuit) { if (!gotsomewhere) __set_errno (ECONNREFUSED); /* no nameservers found */ else __set_errno (ETIMEDOUT); /* no answer obtained */ } else __set_errno (terrno); return (-1); |
而它的调用者__res_context_query则在返回值是-1的时候，设置错误码TRY_AGAIN，这就是我们从KeyDB日志上看到报错The name server returned a temporary failure indication的原因：
|
1 2 3 4 |
if (n < 0) { RES_SET_H_ERRNO(statp, TRY_AGAIN); return (n); } |
缓慢的根源是send_dg函数，它阻塞了5秒。该函数的原型如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 |
// 如果没有错误，返回第一个应答的字节数 // 对于可恢复错误，返回0；对于不可恢复错误，返回负数 static int send_dg( // 各种选项、DNS服务器列表、指向DNS服务器的套接字（文件描述符） res_state statp, // 查询请求1的缓冲区 和 长度 const u_char *buf, int buflen, // 查询请求2的缓冲区 和 长度 const u_char *buf2, int buflen2, // 收到的第1个应答 和 最大长度 u_char **ansp, int *anssizp, // 出现错误时，将errno设置到此字段 int *terrno, // 使用的DNS服务器的序号 int ns, // 如果由于UDP数据报的限制而导致截断，则v_circuit设置为1，提示调用者使用TCP方式重试 int *v_circuit, // 提示访问DNS服务器时，是拒绝服务还是超时。如果是超时则设置为1 int *gotsomewhere, // 提示遇到超长应答的时候，是否重新分配缓冲区 u_char **anscp, // 收到的第2个应答 和 最大长度 u_char **ansp2, int *anssizp2, // 第2个应答的实际长度 是否为第2个应答重新分配了缓冲区 int *resplen2, int *ansp2_malloced); |
该函数会向指定序号的DNS服务器发送DNS查询。它同时支持IPv4/IPv6查询，你可以传递两个查询请求，分别放在buf和buf2参数中。如果提供了两个查询请求，默认使用并行方式发送查询。设置选项 RES_SINGLKUP可以强制串行发送；设置选项 RES_SNGLKUPREOP可以强制串行发送，同时总是关闭并重新打开套接字，这样可以和某些行为异常的DNS服务器一起工作。
由于请求可以并行发送，因此应答到达的顺序是不确定的。先收到的应答会存放在ansp中，入参最大长度anssizp。入参anscp用于提示，应答过长的时候的处理方式：
- 如果anscp不为空：则自动分配新的缓冲区，并且ansp、anscp都被修改为指向该缓冲区
- 如果anscp为空：则过长的部分被截断，DNS包头的TC字段被设置为1
glibc的2.27-3ubuntu1版本中send_dg的完整实现如下：
|
1042 1043 1044 1045 1046 1047 1048 1049 1050 1051 1052 1053 1054 1055 1056 1057 1058 1059 1060 1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071 1072 1073 1074 1075 1076 1077 1078 1079 1080 1081 1082 1083 1084 1085 1086 1087 1088 1089 1090 1091 1092 1093 1094 1095 1096 1097 1098 1099 1100 1101 1102 1103 1104 1105 1106 1107 1108 1109 1110 1111 1112 1113 1114 1115 1116 1117 1118 1119 1120 1121 1122 1123 1124 1125 1126 1127 1128 1129 1130 1131 1132 1133 1134 1135 1136 1137 1138 1139 1140 1141 1142 1143 1144 1145 1146 1147 1148 1149 1150 1151 1152 1153 1154 1155 1156 1157 1158 1159 1160 1161 1162 1163 1164 1165 1166 1167 1168 1169 1170 1171 1172 1173 1174 1175 1176 1177 1178 1179 1180 1181 1182 1183 1184 1185 1186 1187 1188 1189 1190 1191 1192 1193 1194 1195 1196 1197 1198 1199 1200 1201 1202 1203 1204 1205 1206 1207 1208 1209 1210 1211 1212 1213 1214 1215 1216 1217 1218 1219 1220 1221 1222 1223 1224 1225 1226 1227 1228 1229 1230 1231 1232 1233 1234 1235 1236 1237 1238 1239 1240 1241 1242 1243 1244 1245 1246 1247 1248 1249 1250 1251 1252 1253 1254 1255 1256 1257 1258 1259 1260 1261 1262 1263 1264 1265 1266 1267 1268 1269 1270 1271 1272 1273 1274 1275 1276 1277 1278 1279 1280 1281 1282 1283 1284 1285 1286 1287 1288 1289 1290 1291 1292 1293 1294 1295 1296 1297 1298 1299 1300 1301 1302 1303 1304 1305 1306 1307 1308 1309 1310 1311 1312 1313 1314 1315 1316 1317 1318 1319 1320 1321 1322 1323 1324 1325 1326 1327 1328 1329 1330 1331 1332 1333 1334 1335 1336 1337 1338 1339 1340 1341 1342 1343 1344 1345 1346 1347 1348 1349 1350 1351 1352 1353 1354 1355 1356 1357 1358 1359 1360 1361 1362 1363 1364 1365 1366 1367 1368 1369 1370 1371 1372 1373 1374 1375 1376 1377 1378 1379 1380 1381 1382 1383 1384 1385 1386 1387 1388 1389 1390 1391 1392 1393 1394 1395 1396 1397 1398 1399 1400 1401 1402 1403 1404 1405 1406 1407 1408 1409 1410 1411 1412 1413 1414 1415 1416 1417 1418 1419 1420 1421 |
static int send_dg(res_state statp, const u_char *buf, int buflen, const u_char *buf2, int buflen2, u_char **ansp, int *anssizp, int *terrno, int ns, int *v_circuit, int *gotsomewhere, u_char **anscp, u_char **ansp2, int *anssizp2, int *resplen2, int *ansp2_malloced) { const HEADER *hp = (HEADER *) buf; const HEADER *hp2 = (HEADER *) buf2; struct timespec now, timeout, finish; struct pollfd pfd[1]; int ptimeout; struct sockaddr_in6 from; int resplen = 0; int n; /* * Compute time for the total operation. */ int seconds = (statp->retrans << ns); // 0. 计算超时 if (ns > 0) seconds /= statp->nscount; if (seconds <= 0) seconds = 1; bool single_request_reopen = (statp->options & RES_SNGLKUPREOP) != 0; // 0. 确定是否并行请求 bool single_request = (((statp->options & RES_SNGLKUP) != 0) | single_request_reopen); int save_gotsomewhere = *gotsomewhere; int retval; retry_reopen: // tx1. 如果套接字没有创建，则创建， SOCK_DGRAM | SOCK_NONBLOCK | SOCK_CLOEXEC，非阻塞 retval = reopen (statp, terrno, ns); // tx1. 然后调用一下connect操作，不发数据 if (retval <= 0) { if (resplen2 != NULL) *resplen2 = 0; return retval; } retry: evNowTime(&now); evConsTime(&timeout, seconds, 0); evAddTime(&finish, &now, &timeout); int need_recompute = 0; int nwritten = 0; int recvresp1 = 0; // 用于标记请求1的应答是否接收到 /* Skip the second response if there is no second query. To do that we mark the second response as received. */ int recvresp2 = buf2 == NULL; // 用于标记请求2的应答是否接收到，如果buf2为空则立即标记为1 pfd[0].fd = EXT(statp).nssocks[ns]; pfd[0].events = POLLOUT; // tx2. 准备监听可写事件 wait: if (need_recompute) { recompute_resend: evNowTime(&now); if (evCmpTime(finish, now) <= 0) { poll_err_out: return close_and_return_error (statp, resplen2); } evSubTime(&timeout, &finish, &now); need_recompute = 0; } /* Convert struct timespec in milliseconds. */ ptimeout = timeout.tv_sec * 1000 + timeout.tv_nsec / 1000000; n = 0; if (nwritten == 0) n = __poll (pfd, 1, 0); // tx2. 等待套接字可写 if (__glibc_unlikely (n == 0)) { n = __poll (pfd, 1, ptimeout); // rx1. 等待套接字可读，5秒超时 need_recompute = 1; } if (n == 0) { if (resplen > 1 && (recvresp1 || (buf2 != NULL && recvresp2))) { // 处理某些DNS服务器不支持处理并行请求的场景 /* There are quite a few broken name servers out there which don't handle two outstanding requests from the same source. There are also broken firewall settings. If we time out after having received one answer switch to the mode where we send the second request only once we have received the first answer. */ if (!single_request) { statp->options |= RES_SNGLKUP; // 这里永久改变为串行发送请求。statp是线程本地变量， single_request = true; // KeyDB复制定时任务总是在同一线程中运行 *gotsomewhere = save_gotsomewhere; goto retry; } else if (!single_request_reopen) { statp->options |= RES_SNGLKUPREOP; single_request_reopen = true; *gotsomewhere = save_gotsomewhere; __res_iclose (statp, false); goto retry_reopen; } *resplen2 = 1; return resplen; } *gotsomewhere = 1; if (resplen2 != NULL) *resplen2 = 0; return 0; } if (n < 0) { if (errno == EINTR) goto recompute_resend; goto poll_err_out; } __set_errno (0); if (pfd[0].revents & POLLOUT) { // tx3. 监听到可写事件 #ifndef __ASSUME_SENDMMSG static int have_sendmmsg; #else # define have_sendmmsg 1 #endif if (have_sendmmsg >= 0 && nwritten == 0 && buf2 != NULL // 查询请求2不为空 && !single_request) // 且允许并行发送 { struct iovec iov[2]; struct mmsghdr reqs[2]; reqs[0].msg_hdr.msg_name = NULL; reqs[0].msg_hdr.msg_namelen = 0; reqs[0].msg_hdr.msg_iov = &iov[0]; reqs[0].msg_hdr.msg_iovlen = 1; iov[0].iov_base = (void *) buf; iov[0].iov_len = buflen; reqs[0].msg_hdr.msg_control = NULL; reqs[0].msg_hdr.msg_controllen = 0; reqs[1].msg_hdr.msg_name = NULL; reqs[1].msg_hdr.msg_namelen = 0; reqs[1].msg_hdr.msg_iov = &iov[1]; reqs[1].msg_hdr.msg_iovlen = 1; iov[1].iov_base = (void *) buf2; iov[1].iov_len = buflen2; reqs[1].msg_hdr.msg_control = NULL; reqs[1].msg_hdr.msg_controllen = 0; // 发送消息，注意这里同时发送2个查询请求，返回值是实际发送的数量 int ndg = __sendmmsg (pfd[0].fd, reqs, 2, MSG_NOSIGNAL); if (__glibc_likely (ndg == 2)) { if (reqs[0].msg_len != buflen || reqs[1].msg_len != buflen2) goto fail_sendmmsg; pfd[0].events = POLLIN; nwritten += 2; } else if (ndg == 1 && reqs[0].msg_len == buflen) goto just_one; else if (ndg < 0 && (errno == EINTR || errno == EAGAIN)) goto recompute_resend; else { #ifndef __ASSUME_SENDMMSG if (__glibc_unlikely (have_sendmmsg == 0)) { if (ndg < 0 && errno == ENOSYS) { have_sendmmsg = -1; goto try_send; } have_sendmmsg = 1; } #endif fail_sendmmsg: return close_and_return_error (statp, resplen2); } } else { // 不支持并行发送 ssize_t sr; #ifndef __ASSUME_SENDMMSG try_send: #endif if (nwritten != 0) sr = send (pfd[0].fd, buf2, buflen2, MSG_NOSIGNAL); else sr = send (pfd[0].fd, buf, buflen, MSG_NOSIGNAL); // tx4. 发送查询请求1 if (sr != (nwritten != 0 ? buflen2 : buflen)) { // 发送长度和缓冲区长度不匹配 if (errno == EINTR || errno == EAGAIN) // 如果原因是EINTR或EAGAIN，则尝试重发 goto recompute_resend; return close_and_return_error (statp, resplen2); } just_one: if (nwritten != 0 || buf2 == NULL || single_request) pfd[0].events = POLLIN; // 串行模式下，后续只需监听可读时间 else pfd[0].events = POLLIN | POLLOUT; // 并行发送，如果实际仅发送1个消息，跳转到这里。后续需要继续写入发送失败的那个消息 ++nwritten; } goto wait; // tx4. 发送完毕，回到上面的wait分支等待应答 } else if (pfd[0].revents & POLLIN) { // rx2. 监听到套接字可读 int *thisanssizp; // 本次读数据到哪个缓冲 u_char **thisansp; int *thisresplenp; if ((recvresp1 | recvresp2) == 0 || buf2 == NULL) { /* We have not received any responses yet or we only have one response to receive. */ thisanssizp = anssizp; thisansp = anscp ?: ansp; assert (anscp != NULL || ansp2 == NULL); thisresplenp = &resplen; } else { thisanssizp = anssizp2; thisansp = ansp2; thisresplenp = resplen2; } if (*thisanssizp < MAXPACKET /* If the current buffer is not the the static user-supplied buffer then we can reallocate it. */ && (thisansp != NULL && thisansp != ansp) #ifdef FIONREAD /* Is the size too small? */ && (ioctl (pfd[0].fd, FIONREAD, thisresplenp) < 0 || *thisanssizp < *thisresplenp) #endif ) { /* Always allocate MAXPACKET, callers expect this specific size. */ u_char *newp = malloc (MAXPACKET); if (newp != NULL) { *thisanssizp = MAXPACKET; *thisansp = newp; if (thisansp == ansp2) *ansp2_malloced = 1; } } /* We could end up with truncation if anscp was NULL (not allowed to change caller's buffer) and the response buffer size is too small. This isn't a reliable way to detect truncation because the ioctl may be an inaccurate report of the UDP message size. Therefore we use this only to issue debug output. To do truncation accurately with UDP we need MSG_TRUNC which is only available on Linux. We can abstract out the Linux-specific feature in the future to detect truncation. */ HEADER *anhp = (HEADER *) *thisansp; socklen_t fromlen = sizeof(struct sockaddr_in6); assert (sizeof(from) <= fromlen); *thisresplenp = recvfrom(pfd[0].fd, (char*)*thisansp, // rx3. 读取应答 *thisanssizp, 0, (struct sockaddr *)&from, &fromlen); if (__glibc_unlikely (*thisresplenp <= 0)) { if (errno == EINTR || errno == EAGAIN) { need_recompute = 1; goto wait; // 如果EINTR|EAGAIN则重新等待 } return close_and_return_error (statp, resplen2); } *gotsomewhere = 1; if (__glibc_unlikely (*thisresplenp < HFIXEDSZ)) { // 消息比报文头长度还小，错误 /* * Undersized message. */ *terrno = EMSGSIZE; return close_and_return_error (statp, resplen2); } if ((recvresp1 || hp->id != anhp->id) && (recvresp2 || hp2->id != anhp->id)) { // 查询标识符不匹配，可能服务器缓慢，返回之前查询的应答 /* * response from old query, ignore it. * XXX - potential security hazard could * be detected here. */ goto wait; } if (!(statp->options & RES_INSECURE1) && // 安全性检查type1 !res_ourserver_p(statp, &from)) { /* * response from wrong server? ignore it. * XXX - potential security hazard could * be detected here. */ goto wait; } if (!(statp->options & RES_INSECURE2) // 安全性检查type2 && (recvresp1 || !res_queriesmatch(buf, buf + buflen, *thisansp, *thisansp + *thisanssizp)) && (recvresp2 || !res_queriesmatch(buf2, buf2 + buflen2, *thisansp, *thisansp + *thisanssizp))) { /* * response contains wrong query? ignore it. * XXX - potential security hazard could * be detected here. */ goto wait; } if (anhp->rcode == SERVFAIL || anhp->rcode == NOTIMP || anhp->rcode == REFUSED) { // rx4. 处理服务器不愿意处理请求的情况 next_ns: if (recvresp1 || (buf2 != NULL && recvresp2)) { *resplen2 = 0; return resplen; } if (buf2 != NULL) { /* No data from the first reply. */ resplen = 0; /* We are waiting for a possible second reply. */ if (hp->id == anhp->id) recvresp1 = 1; else recvresp2 = 1; goto wait; // 事件类型仍然是POLLIN，会导致超时 } /* don't retry if called from dig */ if (!statp->pfcode) return close_and_return_error (statp, resplen2); __res_iclose(statp, false); } if (anhp->rcode == NOERROR && anhp->ancount == 0 // rx.4 处理nodata的情况，名字请求，请求的记录类型不存在 && anhp->aa == 0 && anhp->ra == 0 && anhp->arcount == 0) { goto next_ns; } if (!(statp->options & RES_IGNTC) && anhp->tc) { // rx.4 处理应答截断的情况 /* * To get the rest of answer, * use TCP with same server. */ *v_circuit = 1; // 提示使用TCP重发请求 __res_iclose(statp, false); // XXX if we have received one reply we could // XXX use it and not repeat it over TCP... if (resplen2 != NULL) *resplen2 = 0; return (1); } /* Mark which reply we received. */ if (recvresp1 == 0 && hp->id == anhp->id) recvresp1 = 1; else recvresp2 = 1; /* Repeat waiting if we have a second answer to arrive. */ if ((recvresp1 & recvresp2) == 0) { // 如果只有一个查询请求，recvresp2一开始就标记为1，因此不会走到这个分支 if (single_request) { // 如果是串行模式，这里开始处理第2个请求 pfd[0].events = POLLOUT; if (single_request_reopen) { // 如果需要关闭并重新打开套接字 __res_iclose (statp, false); retval = reopen (statp, terrno, ns); if (retval <= 0) { if (resplen2 != NULL) *resplen2 = 0; return retval; } pfd[0].fd = EXT(statp).nssocks[ns]; } } goto wait; // 事件类型已经改为POLLOUT，因此不会发生超时 } /* All is well. We have received both responses (if two responses were requested). */ return (resplen); // rx.5 DNS查询完毕 } else if (pfd[0].revents & (POLLERR | POLLHUP | POLLNVAL)) // poll出现错误 /* Something went wrong. We can stop trying. */ return close_and_return_error (statp, resplen2); else { /* poll should not have returned > 0 in this case. */ abort (); } } |
注释中tx.标注了DNS查询请求发送的基本过程，rx.则标注了DNS查询应答接收的基本过程。调试查询keydb-0.keydb时该函数的行为，发现以下事实：
- 查询时串行发送的，而不是并行。因此正常流程应该是发送A查询，接收A应答，发送AAAA查询，接收AAAA应答
- 仅执行了1225行，没有执行1223行。也就是说仅仅发送了A查询，没有发送AAA查询
- 走到了1241行的分支，也就是说，A请求的应答报文是接收到的：
12941295129612971298// (gdb) i r eax// eax 0x2d 45 A应答长度45*thisresplenp = recvfrom(pfd[0].fd, (char*)*thisansp,*thisanssizp, 0,(struct sockaddr *)&from, &fromlen);由于接收到的应答是servfail，因此走到这个分支：
13451346134713481349135013511352135313541355135613571358135913601361136213631364if (anhp->rcode == SERVFAIL ||anhp->rcode == NOTIMP ||anhp->rcode == REFUSED) {next_ns:if (recvresp1 || (buf2 != NULL && recvresp2)) {*resplen2 = 0;return resplen;}if (buf2 != NULL){/* No data from the first reply. */resplen = 0;/* We are waiting for a possible second reply. */if (hp->id == anhp->id)recvresp1 = 1; // 接收到第一个应答elserecvresp2 = 1;// 由于同时需要进行A和AAAA查询，这里仅仅接收到A应答（串行发送）goto wait; // 因此需要跳转到这里，等待套接字可写，以发送AAAA请求} -
CoreDNS应答A查询SERVFAIL，重新跳转到wait标签：
10931094109510961097109810991100110111021103110411051106110711081109111011111112if (need_recompute) { // 等待A应答的时候，设置了超时 need_recompute，因此再次wait执行这个分支recompute_resend:evNowTime(&now);if (evCmpTime(finish, now) <= 0) {poll_err_out: // 如果超时了，直接关闭套接字并返回错误return close_and_return_error (statp, resplen2);}evSubTime(&timeout, &finish, &now);need_recompute = 0;}/* Convert struct timespec in milliseconds. */ptimeout = timeout.tv_sec * 1000 + timeout.tv_nsec / 1000000;n = 0;if (nwritten == 0)n = __poll (pfd, 1, 0); // 发送A请求的时候在这里pull，等待套接字可写。timeout 0表示立即返回if (__glibc_unlikely (n == 0)) {n = __poll (pfd, 1, ptimeout); // 接收A应答的时候在这里poll，等待套接字可读need_recompute = 1; // 发送AAAA请求时，在这里等待套接字可写} -
这时，由于nwritten已经被设置为1，因此走带有timeout的poll分支。然后在1110行出现5秒超时，并因为poll返回值是0而导致send_dg函数退出。在一次A请求处理过程中，有两次在1110行poll：
- 第一次是尝试A请求的应答，poll前的pollfd是{fd = 87, events = 1, revents = 4}，之后是{fd = 87, events = 1, revents = 1}
- 第二次就是因为这个跳转，poll前的pollfd是{fd = 87, events = 1, revents = 1}，超时之后是{fd = 87, events = 1, revents = 0}
poll函数原型： int poll(struct pollfd *fds, nfds_t nfds, int timeout);，它等待文件描述符集合中的某个可用（可执行I/O）。文件描述符集合由参数fds指定，它是pollfd结构的数组：
|
1 2 3 4 5 6 7 8 |
struct pollfd { // 打开文件的描述符 int fd; // 输入参数，应用程序感兴趣的事件类型。如果置零则revents中仅能返回POLLHUP,POLLERR,POLLNVAL事件 short events; // 输出参数，内核填充实际发生的事件 short revents; }; |
如果文件描述符集中没有任何一个发生了events中指定的事件，则该函数会阻塞，直到超时或者被信号处理器中断。
事件类型1表示POLLIN，即有数据可读；事件类型4表示POLLOUT，即文件描述符可写。正常情况下该函数返回就绪的（revents非零）文件描述符数量，超时返回0，出现错误则返回-1
第2次在1110行的poll行为难以理解：
- A的应答已经接收到，而由于进行的是串行发送A/AAAA，此时尚未发送AAAA请求，因此可以预期后续不会有可读事件
- poll时events设置为POLLIN（肯定会导致超时），难道不是应该设置为POLLOUT，尝试发送AAAA请求或重试A请求么？
为了进行对照，我们由调试了没有发生缓慢问题的keydb-2.keydb。它在第2次执行1110行的poll时没有超时，pollfd的状态是{fd = 88, events = 1, revents = 1}。连续两次poll到可读事件，这提示进行了并行A/AAAA查询。检查变量single_request_reopen、single_request果然都是false，从CoreDNS日志上也可以看到A/AAAA
可能的情况是，keydb-1.keydb最初是并行发送A/AAAA查询的，后来由于某种原因，改为串行发送，从而导致出现5秒超时相关的缓慢现象。根源应该还是在glibc中，因为KeyDB调用getaddrinfo的方式是固定的。
回顾一下send_dg的代码，可以发现 statp->options决定了是否进行串行发送，statp是 resolv_context的一个字段，后者则是一个线程本地变量。如果某次并行发送请求后，可以接收到第一个应答，而在继续等待第二个应答时出现超时（1113行），则send_dg函数会修改statp->options，改为串行发送，这个修改具有全局性影响，以后KeyDB的复制定时任务（总是由同一线程执行）调用getaddrinfo，都会使用串行方式发送请求。
改变为串行方式后，由于CoreDNS应答keydb-0.keydb.以SERVFAIL，导致跳转到wait标签（1363行），进而执行了一次必然超时的poll调用。CoreDNS应答其它（加了search domain后缀的）域名以NXDOMAIN，则不会导致超时的poll调用，因为会在1396行修改事件类型为POLLOUT。
触发本文中的glibc缺陷，需要满足以下条件：
- 出现某个KeyDB节点宕机的情况，并且没有修复。这会导致复制定时任务反复执行DNS查询，从而可能触发缺陷
- 某个DNS查询的应答UDP包丢失，导致当前线程串行发送DNS请求。由于UDP本身的不可靠性，随着程序不断运行，最终会发生
- DNS服务器返回SERVFAIL、NOTIMP或者REFUSED应答
第1、2个条件都是随机性的，我们没法干预，只有从第3个条件入手。作为最快速的解决方案，只需要配置KeyDB，使用全限定域名来指定replicaof即可。
分析的深入透彻。