摘要:Eventlet/Gevent 通过 monkey patch 的方式,让 Python 2 同步代码变成异步协程的方式来运行,但是总有一些意向不到的地方能会 block 住你的整个进程。

问题表现

我们采用 Python 2.7 + Eventlet 异步协程框架来开发微服务,线上微服务偶尔出现连续几次 5s 以上的 HTTP 请求,当出现5s超时期间,服务没有任何日志输出。

查证过程

通过 tcpdump 持续抓包,发现是在通过 SysLogHandlerlog.xxx.com 域名发送 UDP 日志时,调用 socket.sendto 时解析域名卡住了。

重现方法

使用 iptalbes 将域名服务器的返回全部 drop 掉,模拟丢包:

# iptables -I INPUT 1 -p udp -s 192.168.45.50 --sport 53 -j DROP
# iptables -I INPUT 2 -p udp -s 192.168.45.51 --sport 53 -j DROP

然后执行 socket.sendto 方法,不管是否启用了 Eventlet monkey patch,都会卡住 40s 左右(len(nameservers) * attempts * timeout * 2) = 2 * 2 * 5 * 2 = 40):

import socket
import time
# import eventlet
# eventlet.monkey_patch()

start = time.time()
try:
    sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
    sock.sendto('test', ('log.xxx.com', 10516))
finally:
    print 'elapsed', time.time() - start

# elapsed 40.0392360687
# Traceback (most recent call last):
#   File "test_getaddrinfo.py", line 16, in <module>
#     sock.sendto('test', ('log.xxx.com', 10516))
# socket.gaierror: [Errno -3] Temporary failure in name resolution

而测试发现,线上实际情况不会出现持续丢包请求,一般是偶尔丢包,超时一次(5s)后重试一次就可以正常。

使用以下脚本测试线上 DNS 丢包率大概在万分之一(晚上高峰期更高一些)。

import socket
import timeit

def single_dns_lookup():
    start = timeit.default_timer()
    socket.getaddrinfo('stackoverflow.com', 443)
    end = timeit.default_timer()
    return int(end - start)

timings = {}

for _ in range(0, 50000):
    time = single_dns_lookup()
    try:
        timings[time] += 1
    except KeyError:
        timings[time] = 1

print timings
# {0: 49996, 5: 4}

分析原因

由于 docker 部署原因,暂不支持本地持久化存储日志,所以线上暂时使用了 SysLogHandler 将日志通过 UDP 发送到 ELK:

elk:
      address:
        - log.xxx.com
        - 10516
      class: logging.handlers.SysLogHandler
      formatter: elk

SysLogHandler.emit 每次打印日志时,都会调用 socket.sendto 方法,其中 address 就是配置文件中的日志接收地址:

if self.unixsocket:
                try:
                    self.socket.send(msg)
                except socket.error:
                    self.socket.close() # See issue 17981
                    self._connect_unixsocket(self.address)
                    self.socket.send(msg)
            elif self.socktype == socket.SOCK_DGRAM:
                self.socket.sendto(msg, self.address) 
            else:
                self.socket.sendall(msg)

我们再看看 socket.sendto 底层实现:

微服务使用 eventlet.monkey_patch 之后,socket.socket() 创建的是 eventlet.greenio.base.GreenSocket 实例:

>>> import eventlet, socket
>>> eventlet.monkey_patch()
>>> socket.socket
<class 'eventlet.greenio.base.GreenSocket'>

查看 GreenSocket.sendto 内部实现

class GreenSocket(object):

    def __init__(self, family=socket.AF_INET, *args, **kwargs):
        should_set_nonblocking = kwargs.pop('set_nonblocking', True)
        if isinstance(family, six.integer_types):
            fd = _original_socket(family, *args, **kwargs)
        ...
        self.fd = fd  # fd为原始未patch过的socket(_original_socket)

    def sendto(self, data, *args):
        return self._send_loop(self.fd.sendto, data, *args)

可以看到实际调用的是 self.fd.sendto原始 socket 的 sendto 方法):

/* s.sendto(data, [flags,] sockaddr) method */

static PyObject *
sock_sendto(PySocketSockObject *s, PyObject *args)
{
    ...
    if (!getsockaddrarg(s, addro, SAS2SA(&addrbuf), &addrlen)) {
        PyBuffer_Release(&pbuf);
        return NULL;
    }
    ...
}

/* Parse a socket address argument according to the socket object's
   address family.  Return 1 if the address was in the proper format,
   0 of not.  The address is returned through addr_ret, its length
   through len_ret. */

static int
getsockaddrarg(PySocketSockObject *s, PyObject *args,
               struct sockaddr *addr_ret, int *len_ret)
{
    ...
        addr=(struct sockaddr_in*)addr_ret;
        result = setipaddr(host, (struct sockaddr *)addr,
                           sizeof(*addr),  AF_INET);
    ...
}

/* Convert a string specifying a host name or one of a few symbolic
   names to a numeric IP address.  This usually calls gethostbyname()
   to do the work; the names "" and "<broadcast>" are special.
   Return the length (IPv4 should be 4 bytes), or negative if
   an error occurred; then an exception is raised. */

static int
setipaddr(char *name, struct sockaddr *addr_ret, size_t addr_ret_size, int af)
{
    ...
    error = getaddrinfo(name, NULL, &hints, &res);
    ...
}

该方法没有被 Eventlet green patch,且其内部调用的 getaddrinfo 系统调用恰恰就是一个默认情况下可能 block 5s 的 DNS 查询

# strace -p XXX
connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, 16) = 0
poll([{fd=3, events=POLLOUT}], 1, 0)    = 1 ([{fd=3, revents=POLLOUT}])
sendmmsg(3, {{{msg_name(0)=NULL, msg_iov(1)=[{"\244>\1\0\0\1\0\0\0\0\0\0\6google\3com\0\0\1\0\1", 28}], msg_controllen=0, msg_flags=0}, 28}..., MSG_NOSIGNAL) = 2
poll([{fd=3, events=POLLIN}], 1, 5000)  = 1 ([{fd=3, revents=POLLIN}])             # timeout=5000ms,如果DNS查询丢包,则会卡住5s
ioctl(3, FIONREAD, [44])                = 0
recvfrom(3, "\244>\201\200\0\1\0\1\0\0\0\0\6google\3com\0\0\1\0\1\300\f\0\1"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, [16]) = 44

所以当该方法内部出现卡顿时,整个进程也会卡住。但为什么是卡住 5s 呢,我们来看看 getaddrinfo 域名解析过程,大概如下:

  1. 读取 /etc/gai.conf 配置来修改该函数的一些默认行为(我们没有配置这个)
  2. 首先根据 /etc/nsswitch.conf 中的 hosts 配置加载域名解析顺序

    $ cat /etc/nsswitch.conf
     passwd:         compat
     group:          compat
     shadow:         compat
     gshadow:        files
    
     hosts:          files dns
     networks:       files
    
     protocols:      db files
     services:       db files
     ethers:         db files
     rpc:            db files
    
     netgroup:       nis
    
  3. 如果 nsswitch.hosts 包含 files 则读取 /etc/hosts 中的配置

    $ cat /etc/hosts
     # Kubernetes-managed hosts file.
     127.0.0.1       localhost
     ::1     localhost ip6-localhost ip6-loopback
     fe00::0 ip6-localnet
     fe00::0 ip6-mcastprefix
     fe00::1 ip6-allnodes
     fe00::2 ip6-allrouters
     10.203.20.15    mdockerstress-621667462-tm68n
    

    如果要查的域名在 hosts 文件中,则直接返回(比如 localhost),否则继续下一种查询方法。

  4. 如果 nsswitch.hosts 包含 dns 则读取 /etc/resolv.conf 中的 nameserver 地址

    $ cat /etc/resolv.conf
    nameserver 10.204.2.202
    nameserver 10.120.227.17
    

    轮流向 nameserver 各发送 attempts 次DNS请求,每次请求超时时间默认为5s(可以如下修改DNS超时时间,默认为options timeout:5 attempts:2 rotate)。

    options timeout:2 attempts:2 rotate
    nameserver 10.204.2.202
    nameserver 10.120.227.17
    

    注意,对于微服务使用的 eventlet.greendns,它不会读取 resolve.conf 中的超时配置,而是固定超时时间为30s。它会使用2s的超时时间,循环轮流重试查询所有的 nameserver,直到查询成功或重试时间超过30s报异常。

解决办法

有三种办法:

  1. 使用物理机类似的方式,将日志打印到本地磁盘,然后通过 filebeat 同步到 ELK(绕过 DNS )
  2. 不使用域名打 UDP 日志,或者配置本机 dnsmq(避免 DNS 解析丢包)
  3. 修改 Evenlet,对 sendtoaddress 以非 block 的方式域名解析(参考issuse

这个问题对基于 Eventlet/Gevent 协程类服务影响较大,当出现丢包时,会导致整个进程卡住一段时间。而对于非协程类进程,可能只会导致偶尔某个请求出现超时 5s 的情况。

另外,对于普通的 DNS 解析(比如常用的 socket.getaddrinfo()socket.gethostbyname()调用),Eventlet 已经通过 greendns 来 patch,不会卡住整个进程。

PS. 当出现类似卡住整个 Eventlet 情况,使用 eventlet.debug.hub_blocking_detection 也是无济于事的:(

本文来自《域名解析超时导致卡住整个 Eventlet 协程问题》- 熊清亮的博客。

转载请注明原文链接:https://seealso.cn/debug/dns-resolving-block-eventlet-coroutine