tcp端口探测脚本问题分析

【背景】

最近在优化一个监控模块里面的dns解析功能,原来的做法是用旁路线程调用getaddrinfo去同步解析,解析实时性非常差,所以决定将解析改成异步执行。网上搜索了一些dns异步解析的库/接口大致有:getaddrinfo_a adnsc-aresudns等等。这些库虽然功能相对比较全,但是在我的场景各种别扭或者低效,不能很好地满足我的需求:其实需求很简单,我就需要解析ipv4的协议编解码接口就行了,然后结合epoll完成异步解析。在纠结了很久之后,决定按照dns协议自己实现解析ipv4的协议编解码接口,然后结合epoll完成异步解析。

 

【问题表现】

优化后的程序dns解析功能一切正常,之前扫描一遍hash表(共享内存里面)并解析完需要几分钟甚至几个小时,优化后解析完整个hash表只需要几秒钟。可另外一个跟优化“完全无关”的功能却受了影响,调用tcp.py(tcp端口探测的python脚本)总是报错:

2014-09-03 17:19:53,645 ERROR cmp_tcp.py:26 connect(10.190.164.92, 8001) ret: 114, cost: 0ms, err: EALREADY

显示为连接已经在建立中

 

【问题分析】

一.  分析c++代码

 

因为之前就遇到过因为SIGCHLD信号导致程序不能正常工作的情况,毕竟在优化前后没有对tcp.py做过任何改动,第一感觉又是因为某个信号问题导致的。仔细diff了几遍修改前后的c++代码,没有任何跟信号打交道的地方。除了之前调用getaddrinfo,而现在不调用这个接口以外,没有其他特别之处。难道是getaddrinfo里面会打开或者屏蔽某个信号?为了验证是不是getaddrinfo导致的,在main函数创建工作线程以前显式地调用了一次getaddrinfo,发现问题依旧,确定跟c++里面是否调用getaddrinfo无关。

 

回到python源码本身,核心代码就下面几行:

sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)

sock.settimeout(10) # 10 seconds

ecode = sock.connect_ex((ip, port))

sock.close()

 

ecode总是为EALREADY,英文注解为:Operation already in progress,意思是当前这个socket已经在异步连接中,如果在这个socket上面调用第二次connect会导致返回EALREADY。可是python代码里面明明只调用了一次connect_ex(返回错误码的版本,connect为抛异常的版本),而且socket也是临时创建的,没有复用任何之前创建的socket,感觉非常的匪夷所思。

 

二.找到出问题的环节

 

为了验证问题出现在哪个环节,试着将上面的几行代码拷贝到脚本的不同地方,因为脚本可以支持直接探测域名,所以python脚本里面会调用getaddrinfo先进行域名解析,如果将以上几行python代码拷贝到调用getaddrinfo之前的地方,需要将域名对应的ip直接写死。结果发现在调用getaddrinfo之前的connect_ex调用都是正常的,在getaddrinfo之后的调用都返回EALREADY错误。于是怀疑是python里面的getaddrinfo里面做了什么事情,回到一开始对信号的怀疑,感觉可能是getaddrinfo里面处理了跟信号有关的东西。猜测终归只是猜测,于是决定用神器strace一看究竟:

 

strace片段1. 第一处connect:

18:35:20.759017 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1043 <0.000007>

18:35:20.759056 connect(1043, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16)         = 0 <0.032906>

 

connect完全正常,第二处connect表现跟上面一样,不单独列出。

 

strace片段2. 第三处connect:

18:35:20.854934 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1045 <0.000007>

18:35:20.854959 fcntl(1045, F_GETFL)    = 0x2 (flags O_RDWR) <0.000004>

18:35:20.854980 fcntl(1045, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000005>

18:35:20.855045 connect(1045, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation no

w in progress) <0.000012>

18:35:20.855079 select(1046, NULL, [1024 1026 1045], NULL, {2097157, 0}) = 2 (out [1026 1045], left {2097156, 999997}) <0.000007>

18:35:20.855131 connect(1045, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EALREADY (Operation alrea

dy in progress) <0.000005>

 

connect开始报错。可以看到python(内核)这里的实现,先将socket设置为非阻塞,然后调用一次connect,发现不能立马连上,所以将fd放入select进行监听,select返回fd可写(可写表示连接建立成功)后,python调用了第二次connect以确保连接真的成功,但是第二次connect返回了EALREADY,表示连接其实还在建立当中,并没有成功。至于getaddrino的调用,对应的系统调用只有创建socket114.114.114.11453通信而已,没有特别之处,可以排除getaddrinfo的影响。

 

问题是为啥第一处connect是阻塞的,而第二处是非阻塞呢?对比代码发现是socket.setdefaulttimeout(5)引起的,只要给socket设置超时,python就会自动将socket设置为非阻塞。为啥select返回连接建立成功,而select后的connect却没有返回0,而是返回EALREADY错误呢?

 

Strace片段3. 为了对比优化前后的具体差异,决定strace一下优化前的c++程序调用tcp.py的执行过程,结果(第三处connect)显示为:

10:21:27.542192 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 20 <0.000008>

10:21:27.542217 fcntl(20, F_GETFL)      = 0x2 (flags O_RDWR) <0.000004>

10:21:27.542239 fcntl(20, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000004>

10:21:27.542305 connect(20, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation now

in progress) <0.000012>

10:21:27.542341 select(21, NULL, [20], NULL, {5, 0}) = 1 (out [20], left {4, 965442}) <0.034567>

10:21:27.576992 connect(20, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = 0 <0.000008>

 

Strace片段2对应出问题的版本,strace片段3对应正常的版本,对比看系统调用的结构完全一样。仔细看会发现,select的返回时延差别很大,问题版本的select只花了7个微秒就返回了,正常版本的select却等了30多个毫秒才返回。203.195.128.189这个ip 正常ping一次要30几个毫秒,所以正常版本的select耗时是符合预期的。问题版本的select其实并没有等到连接真正成功就返回了,可是select并没有报错,而是显示为连接已经成功,从而python调用第二次connect以确认链接是否真的成功,connect理所当然的返回了EALREADY

 

定位到这里,我也没有什么头绪了,既然阻塞版本的socket不会有问题,直接用阻塞版本的socket规避掉这个问题得了。但是不搞定这个问题又会睡不好觉,而且这里的阻塞版没法控制超时,在现网环境是不可取的,tcp自然超时可能得花几十秒,分分钟导致进程被阻死。想到这里还是决定硬着头皮继续定位,既然是select调用出了问题,如果在python代码里面显示调用select看看会怎么样呢?

 

三.Python显式调用select确认

 

修改后的tcp.py代码:

         sock = socket.socket(socket.AF_INET,socket.SOCK_STREAM)

sock.setblocking(0);

ecode= sock.connect_ex(("203.195.128.189", 443));

log.debug("1 errno = %d, sockfd = %d" % (ecode, sock.fileno()));

 

inputs = [sock]

rlist, wlist, xlist = select.select(inputs, inputs, inputs, 5);

log.debug("select %d %d %d" % (len(rlist), len(wlist), len(xlist)));

 

python脚本抛出异常(为了快速调试,没有捕获异常):

$ Traceback (most recent call last):

              File "./cmp_tcp.py", line 92, in ?

              rlist, wlist, xlist = select.select(inputs, inputs, inputs, 5);

ValueError: filedescriptor out of range in select()

 

对应的debug log为:

2014-09-05 11:03:01,767 DEBUG cmp_tcp.py:89 1 errno = 115, sockfd = 1043

因为select直接抛出了异常,所以第二个debug log没有机会执行。

 

四.问题根源分析

 

什么情况?python脚本明明只创建了一个socket,加上打日志的几个fd,冲上天最多有几十个fd吧?!可是异常信息明确显示select中的fd超出了范围,python不至于乱报。这是一个很重要的线索,根据这个线索,对比c++代码的diff,发现了问题的根源:是父进程的大量fdpython子进程继承导致的!具体见下面的分析:

 

Dns解析一般是基于udp协议,c++代码里面为了提高性能,避免反复创建、销毁socket带来的开销,创建了一个udp socket pool,而且预先将这些fdEPOLLIN事件注册到epoll里面(这里的实现不用监听EPOLLOUT事件)。这样有dns请求的时候,直接从udp socket pool取一个fd进行send,然后等待epollinput事件,recv完成后将这个fd归还到udp socket pool。这个poolcapacity计算规则是:capacity = min(1024, getrlimit(RLIMIT_NOFILE) / 4),一般机器的getrlimit(RLIMIT_NOFILE)值都上万,所以capacity一般为1024

 

问题非常清晰了,父进程的dns_resolver子线程创建了一个1024大小的udp sock poolpython子进程继承了这一批fd,然后python子进程新创建的fd必然是>=1024的。加之坑爹的python使用了古董级的select调用,两者“完美”的合作导致了select问题的发生。

 

回顾一下之前的strace片段2,当时没有注意fd的范围,其实当时的sockfd1045,已经超出了select的处理范围,其实从这里已经可以看出问题。另外,我只创建了一个socket,为啥select里面额外监听了10241026,设置的5秒超时也显示为2097157?这里分析应该是fd越了select数组的界,导致内存被写坏引起的。

 

五.解决方法

 

既然找到问题原因了,解决思路自然很清晰了,大概有如下几种解决方法:

1.     阻塞方式不会调用select,可以规避select的问题但是容易造成进程阻塞,在现网环境不宜采用

2.     capacity = min(1024, getrlimit(RLIMIT_NOFILE) / 4)改为capacity = min(512, getrlimit(RLIMIT_NOFILE) / 4),这样不至于继承1024个那么多fdpython子进程,可以解决select的问题。但是除了这个udp socket pool以外,还有一些其他的fd也会被继承,所以这种方式也不是100%安全

3.     既然是继承了大量的fd,而这些fd实际上对于python子进程来说没有实际用处,那我选择close一个1024以下的fdsocket复用就行了。

 

Python代码:

os.close(1023);

sock = socket.socket(socket.AF_INET,socket.SOCK_STREAM)

ecode = sock.connect_ex(("203.195.128.189", 443));

strace跟踪:

12:35:36.752416 close(1023)             = 0 <0.000006>

12:35:36.752448 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1023 <0.000008>

12:35:36.752478 fcntl(1023, F_GETFL)    = 0x2 (flags O_RDWR) <0.000005>

12:35:36.752504 fcntl(1023, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000006>

12:35:36.752581 connect(1023, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation no

w in progress) <0.000016>

12:35:36.752628 select(1024, NULL, [1023], NULL, {5, 0}) = 1 (out [1023], left {4, 967988}) <0.032021>

12:35:36.784727 connect(1023, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = 0 <0.000005>

 

           strace的信息来看确实是管用的。Close1023这个fdsocket复用了,没有超出select的范围,一切正常

 

4. 手工改为poll轮询。

Python代码:

      sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)

    sock.setblocking(0);

    ecode = sock.connect_ex(("203.195.128.189", 443));

    log.debug("1 errno = %d, sockfd = %d" % (ecode, sock.fileno()));

 

    poller = select.poll()

    poller.register(sock, select.POLLOUT);

    events = poller.poll(5000) # 5000ms

    poller.unregister(sock)

    sock.close()

    log.debug("events=%r" % events)

 

    if not events or events[0][1] != select.POLLOUT:

         log.error("connect err")

    else:  

               log.debug("connect succ")

strace跟踪:

              13:30:42.834133 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 1043 <0.000009>

13:30:42.834216 fcntl(1043, F_GETFL)    = 0x2 (flags O_RDWR) <0.000006>

13:30:42.834243 fcntl(1043, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000006>

13:30:42.834283 connect(1043, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("203.195.128.189")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000022>

13:30:42.834695 poll([{fd=1043, events=POLLOUT, revents=POLLOUT}], 1, 5000) = 1 <0.032136>

对应的日志:

               2014-09-05 13:30:42,834 DEBUG cmp_tcp.py:90 1 errno = 115, sockfd = 1043

2014-09-05 13:30:42,866 DEBUG cmp_tcp.py:97 events=[(1043, 4)]

2014-09-05 13:30:42,867 DEBUG cmp_tcp.py:102 connect succ  

 

       改为poll后完全正常

 

【总结】

1.  看似无关的2件事情,可能具有某种深层次的关联,而这种关联可能需要仔细分析才能发现

2.  具体到这件事情,其实本质上c++代码没有bug,但是c++的大量socket fdpython子进程无形地继承了,加之python内核坑爹地调用了古董级的select,而select玩不了1024以上的fd,所以导致fdselect的数组中溢出。更为坑爹的是,内核对select调用还成功返回了。

3.  以上给出的四种解决方法中,后两种方法都可以被最终采用,但是第三种方式怪怪的,第四种才是釜底抽薪的方式。

 

粤ICP备 2020115750号-1

粤公网安备 44030502006476号