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

问题表现

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

查证过程

通过tcpdump持续抓包，发现是在通过SysLogHandler向log.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，对 sendto 的 address 以非 block 的方式域名解析（ 参考 issuse ）

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

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

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