记一次 Kubernetes 服务解析问题排查

最近把项目部署从 docker-compose 迁移到 Kubernetes 集群后，遇到了域名解析失败的问题。这个问题不大常见，google 能找到的资料不多，所以在这里记录下排障的思路和方法，供他人参考。

问题症状

Django 应用启动后，日志里有大量数据库域名无法解析的错误:

django.db.utils.OperationalError: could not translate host name "postgres.namespace.svc.cluster.local" to address: No address associated with hostname

应用使用集群DNS 服务 访问数据库（postgres），服务的部署类型是 ClusterIP。

集群的部署情况大致如下：

• 一台 master 节点，3台工作节点，操作系统：ubuntu 18.04

• Kubernetes 版本：v1.15， 使用 Rancher 管理，只用作开发测试，集群负载很低。

问题初查

启动 dnstools pod，通过 nslookup 连续多次测试数据库服务域名，均正常。

$ kubectl run -it --rm --restart=Never --image=infoblox/dnstools:latest dnstools

dnstools# nslookup postgres
Server:         10.43.155.58
Address:        10.43.155.58#53

Name:   postgres.namespace.svc.cluster.local
Address: 10.43.241.110

这样看来，DNS 服务应该没问题。

重新细看了下日志，发现除了数据库，RabbitMQ 服务的域名也无法解析，从错误日志看，是在调用 socket.getaddrinfo 出错。接下来写了个小脚本测试下DNS 连接。

测试脚本

import socket

db = 'postgres'
addr = socket.getaddrinfo(db, 5432, 0, socket.SOCK_STREAM, socket.IPPROTO_TCP)
print(addr)

连续测试几次后，有意思的问题出现了。域名并不是一直无法解析，而是间断性可以解析成功，两次成功中间有30秒无法解析。

root@ubuntu1404-648966b7fd-wx87s:/# python3 sock.py 
[(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('10.43.241.110', 5432))]
root@ubuntu1404-648966b7fd-wx87s:/# python3 sock.py 
Traceback (most recent call last):
  File "sock.py", line 5, in <module>
    addr = socket.getaddrinfo(db, 5432, 0, socket.SOCK_STREAM, socket.IPPROTO_TCP)
  File "/usr/lib/python3.4/socket.py", line 533, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known
root@ubuntu1404-648966b7fd-wx87s:/# python3 sock.py
[(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('10.43.241.110', 5432))]
root@ubuntu1404-648966b7fd-wx87s:/# 

30秒内只能解析成功一次？像是某种缓存之类的，30秒过期。因为应用跑在容器里，没有额外的服务可以缓存 DNS，应用这边也没有缓存，似乎也可以排除客户端的问题。

从个人经验来说，缓存不大可能会影响程序的正确性，还是看看 CoreDNS 的配置和日志吧。

CoreDNS

.:53 {
  errors
  health
  ready
  kubernetes cluster.local in-addr.arpa ip6.arpa {
    pods insecure
    fallthrough in-addr.arpa ip6.arpa
  }
  prometheus :9153
  forward . "/etc/resolv.conf"
  cache 30
  loop
  reload
  loadbalance
}

配置里有 cache 30，查了下coredns cache 文档

With cache enabled, all records except zone transfers and metadata records will be cached for up to 3600s. Caching is mostly useful in a scenario when fetching data from the backend (upstream, database, etc.) is expensive.

cache 插件把从上游组件，数据库之类过来的 dns 记录缓存 30 秒，否则每次都重新去获取数据，很影响应用的性能。 按理说从缓存返回的结果应该和正常返回的没什么不同。

接下来只能看下日志了，如果日志里也没有价值的信息，也可以用 tcpdump 抓下包试试，对比解析成功和失败的响应数据包有没有不同。

coredns 默认不开启日志，如果需要开启，在配置里加上 log 插件就可以了。但是改配置会影响集群里其他的应用，可以新开个 coredns 服务，把应用容器的 /etc/resolv.conf nameserver 指向新的服务。

/etc/resolv.conf

查了下当前的 coredns 版本是 1.3.1, 用 helm 安装该版本：

$ helm install test-coredns --namespace=default stable/coredns --version v1.3.1

然后进入应用容器，修改 /etc/resolv.conf:

nameserver 10.43.155.58
search namespace.svc.cluster.local svc.cluster.local cluster.local
options ndots:5

保存后再运行测试脚本，此时，coredns 里有日志输出：

2019-12-31T06:19:27.566Z [INFO] 10.42.2.16:40232 - 4189 "A IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,aa,rd 114 0.000427746s
2019-12-31T06:19:27.566Z [INFO] 10.42.2.16:40232 - 47817 "AAAA IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,aa,rd 151 0.000625568s

2019-12-31T06:19:28.193Z [INFO] 10.42.2.16:47156 - 25454 "AAAA IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 151 0.000155542s
2019-12-31T06:19:28.194Z [INFO] 10.42.2.16:47156 - 30511 "A IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 114 0.000374902s
2019-12-31T06:19:28.195Z [INFO] 10.42.2.16:49445 - 20345 "AAAA IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 151 0.00030268s
2019-12-31T06:19:28.195Z [INFO] 10.42.2.16:49445 - 25967 "A IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 114 0.000448206s
2019-12-31T06:19:28.195Z [INFO] 10.42.2.16:44987 - 30511 "A IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 114 0.000720891s
2019-12-31T06:19:28.196Z [INFO] 10.42.2.16:44987 - 25454 "AAAA IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 151 0.001649s
2019-12-31T06:19:28.196Z [INFO] 10.42.2.16:59892 - 25967 "A IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 114 0.000335876s
2019-12-31T06:19:28.197Z [INFO] 10.42.2.16:59892 - 20345 "AAAA IN postgres.namespace.svc.cluster.local. udp 58 false 512" NOERROR qr,rd 151 0.000172475s

前两行是执行第一次成功的日志输出，后面几行是后一次失败的日志结果。 从日志里看，服务端返回的结果都是 NOERROR，也就是说 coredns 都成功返回了。但是客户端似乎不认可从 cache 返回的结果，又重试了3次才放弃。 另外，从 cache 返回的响应头部只有 qr,rd, 没有设置 aa 返回位。

查了下rfc文档和一些博客资料：

Authoritative vs. Non-authoritative Responses Authoritative responses are responses that come directly from a nameserver that has authority over the record in question. Non-authoritative answers come second-hand (or more), i.e., from another server or through a cache.

从 cache 里返回的结果确实不应该设置aa位，所以，DNS 服务端的实现也符合规范，只能再查下是不是客户端的问题。

getaddrinfo

Python Postgres/RabbitMQ 的客户端代码最终都会调用标准库的 socket.getaddrinfo。

看了下 python socket 模块的代码，它实际调用的是系统函数 getaddrinfo。所以，如果确实是客户端的问题，那所有使用 getaddrinfo 这个系统函数的应用都会有问题。

于是写了一段小程序，测试下 getaddrinfo:

#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <netdb.h>
#include <sys/types.h>
#include <sys/socket.h>
#include <arpa/inet.h>

int
lookup_host (const char *host)
{
  struct addrinfo hints, *res;
  int errcode;
  char addrstr[100];
  void *ptr;

  memset (&hints, 0, sizeof (hints));
  hints.ai_family = PF_UNSPEC;
  hints.ai_socktype = SOCK_STREAM;
  hints.ai_flags |= AI_CANONNAME;

  errcode = getaddrinfo (host, NULL, &hints, &res);
  if (errcode != 0)
    {
      printf("err code: %d\n", errcode);
      printf("err: %s\n", gai_strerror(errcode));
      return -1;
    }

  printf ("Host: %s\n", host);
  while (res)
    {
      inet_ntop (res->ai_family, res->ai_addr->sa_data, addrstr, 100);

      switch (res->ai_family)
        {
        case AF_INET:
          ptr = &((struct sockaddr_in *) res->ai_addr)->sin_addr;
          break;
        case AF_INET6:
          ptr = &((struct sockaddr_in6 *) res->ai_addr)->sin6_addr;
          break;
        }
      inet_ntop (res->ai_family, ptr, addrstr, 100);
      printf ("IPv%d address: %s (%s)\n", res->ai_family == PF_INET6 ? 6 : 4,
              addrstr, res->ai_canonname);
      res = res->ai_next;
    }

  return 0;
}

int main (void)
{
  char inbuf[] = "postgres.namespace.svc.cluster.local";

  lookup_host (inbuf);
}

执行结果：

root@ff7587c75-5wllf:/home/ubuntu# ./a.out
Host: postgres.namespace.svc.cluster.local
IPv4 address: 10.43.241.110 (postgres.namespace.svc.cluster.local)
root@ff7587c75-5wllf:/home/ubuntu# ./a.out
err code: -5
err: No address associated with hostname

OK 问题重现了。

由于当前的应用镜像当前是基于 ubuntu 14.04，大概率是系统库的 glibc 版本太老了（当前版本 2.19），于是把基础镜像改成 ubuntu 18.04 后，这个问题就消失了。

额外收获

1. 在测试时候，发现 CoreDNS 最新版（1.7.3）并没有解析失败的问题。后来多次降级后，发现在 1.5.1 里修改了代码，cache 返回的响应里也设置 aa 位，主要为了兼容老的DNS客户端，具体原因可以参考这个PR。 我也顺带帮作者完善了下代码注释。

2. 这篇文章介绍了 ndots:5 对性能的影响。总的来说，如果 /etc/resolv.conf配置了 ndots:5, service name 需要设置为 postgres 或者 postgres.namespace.svc.cluster.local.（注意最后的点），否则系统会进行多次无效的 dns 查询，影响应用的性能。

阅读材料

• https://discover.curve.app/a/mind-of-a-problem-solver

• https://tech.xing.com/a-reason-for-unexplained-connection-timeouts-on-kubernetes-docker-abd041cf7e02

• https://blog.quentin-machu.fr/2018/06/24/5-15s-dns-lookups-on-kubernetes/

• https://sysdig.com/blog/understanding-how-kubernetes-services-dns-work/