近期遇到一个thrift server方面的问题,记录一下。

Background

server做的事情其实很简单,就是一个图片上传服务,别人把图片传过来,服务器上传到阿里云的云上,再返回一个图片地址。

问题暴露出来的现象是:这个服务每隔一段时间就会“挂掉”,重启服务后会好那么一段时间然后又会“挂掉”。客户端调用返回TSocket: Could read 4 bytes from ....,但去线上ps会发现,server进程其实是在的, 也就是说服务器其实只是不响应了,并没有真正挂掉。

First guess

分析后台日志发现,大量重复的报错信息Connection reset by peer,以及偶尔的错误信息too many open files(其实,这个偶尔也只是猜测,因为并没有完整的确认过),当时看到这个日志后,就猜测 原因是:请求太多,导致该程序打开的文件描述符超过限制,从而拒绝服务。由于是线上服务,出现问题时为了及时恢复服务,当时就重启了服务,因此也并没有验证这个猜测。但看了下操作系统对单个程序 打开文件数的限制:

$ ulimit -n 
65535

基于too many open files这个错误加上这个thrift server使用的ThreadPoolServer类型,google了一番,找到几个类似问题的帖子:

里面讲到,ThreadPoolServer来说,它使用的是定长线程池来服务的,当并发太多时使得现存的线程数无法满足要求时,就会出现很多CLOSE_WAIT状态的连接,最终会 把当前程序的文件描述符占满,从而出现too many open files的错误。正好这个服务用的线程是默认的,只有10个,当时就认为问题就在这里了。

Second guess

然后第二天又问了下服务调用方,其实这个服务的使用频率很低,只有在用户更改头像的时候才会调一下,按理说不会有太多并发量,所以这样看来,上面的猜测就不成立了。然后去线上看了下,该服务一共部署了两台机器, 发现其中一台机器上的服务又“挂了”,抓住这个好机会,看了下这个服务的socket连接情况:

# 先找到程序的进程id
$ ps aux | grep 'xxx'
# 然后再用lsof看
$ lsof -i -P | grep 28719
python  28719  www    4u  IPv4 261027973      0t0  TCP *:9455 (LISTEN)
python  28719  www    5u  IPv4 261328458      0t0  TCP 10.171.20.131:9455->100.109.225.0:45587 (ESTABLISHED)
python  28719  www    6u  IPv4 261327693      0t0  TCP 10.171.20.131:9455->100.109.221.128:23814 (ESTABLISHED)
python  28719  www    7u  IPv4 261429153      0t0  TCP 10.171.20.131:9455->100.109.224.0:17384 (ESTABLISHED)
python  28719  www    8u  IPv4 261717598      0t0  TCP 10.171.20.131:9455->100.109.225.0:23881 (ESTABLISHED)
python  28719  www    9u  IPv4 261429722      0t0  TCP 10.171.20.131:9455->100.109.225.128:19752 (ESTABLISHED)
python  28719  www   10u  IPv4 261470638      0t0  TCP 10.171.20.131:9455->100.109.220.128:14370 (ESTABLISHED)
python  28719  www   11u  IPv4 261456259      0t0  TCP 10.171.20.131:9455->100.109.224.128:24267 (ESTABLISHED)
python  28719  www   12u  IPv4 261714765      0t0  TCP 10.171.20.131:9455->100.109.220.0:8860 (ESTABLISHED)
python  28719  www   13u  IPv4 261470701      0t0  TCP 10.171.20.131:9455->100.109.221.0:42186 (ESTABLISHED)
python  28719  www   14u  IPv4 261717599      0t0  TCP 10.171.20.131:9455->100.109.224.0:3487 (ESTABLISHED)
python  28719  www   98u  IPv4 261718019      0t0  TCP 10.171.20.131:9455->100.109.220.0:37454 (ESTABLISHED)
python  28719  www  827u  IPv4 261722045      0t0  TCP 10.171.20.131:9455->10.44.155.227:24038 (CLOSE_WAIT)
python  28719  www  914u  IPv4 261722497      0t0  TCP 10.171.20.131:9455->10.172.224.17:35876 (CLOSE_WAIT)
python  28719  www 1309u  IPv4 261724582      0t0  TCP 10.171.20.131:9455->10.172.142.166:52953 (CLOSE_WAIT)
python  28719  www 1329u  IPv4 261724675      0t0  TCP 10.171.20.131:9455->10.44.155.227:52921 (CLOSE_WAIT)
python  28719  www 1672u  IPv4 261726365      0t0  TCP 10.171.20.131:9455->10.44.191.118:7070 (CLOSE_WAIT)
python  28719  www 1694u  IPv4 261726531      0t0  TCP 10.171.20.131:9455->10.170.210.248:39802 (CLOSE_WAIT)

可以看到CLOSE_WAIT状态的连接并不多,但此时这台机器上部署的服务已经不能用了。同时又去现在还可用的机器上看了下,发现只有状态为ESTABLISHED的连接,并没有状态为CLOSE_WAIT的连接, 同时发现日志在不停的报错:Connection reset by peer。但并没人反馈服务不可用啊,看了下图片上传还是可用的,正百思不得其解中,运维哥哥说,这不会是阿里云的健康检查导致的吧!于是, 暂停了一下健康检查,果然日志的报错停止了。

然后我的猜测又变成了:由于阿里云的持续不断的健康检查(2秒一次)把服务检查挂了。。显然,运维是不会认可这个猜测的,他们说报这个错是正常的,别的服务也有这个问题,只要不理会它就行了。 说实话,光看这个,确实无法断定服务挂是由于健康检查的原因。况且我也查了下阿里云所谓的健康检查,找到了如下官方资料:

看来阿里云官方确认认为这个错误是正常的。

第二天,又去线上看了下,发现某一台机器上的服务又“挂了”,看了下这次的“车祸现场”,注意到了一点上次没有注意的细节:

  • 有11个状态为ESTABLISHED的连接
  • 这个11个状态为ESTABLISHED的连接的另一边都是来自阿里云健康检查的网段ip
  • 此时,如果调用该服务会返回错误,而且会增加一条状态为CLOSE_WAIT的socket连接
  • 对于目前可用的机器上的服务,没有状态为CLOSE_WAIT的连接,但有几个状态为ESTABLISHED的连接,而且尽管没有人调用它,状态为ESTABLISHED的连接数在慢慢增加。

由此,可以基本断定,罪魁祸首就是阿里云的健康检查了。健康检查把当前服务的可用连接数(10个线程只能同时服务10个连接)用完了,并且没有释放,再进来的连接只能wait了。那么现在唯一的问题 就是:Why?阿里云的健康检查为什么会对thrift服务造成这样的结果?我还没有找到原因。从阿里云的官方文档中看到,所谓的TCP健康检查,是对指定ip的指定端口进行了三次握手然后发送了RST断开了 连接,没有看到他们说会造成连接一直不释放的情况。

google到一篇阿里云上部署thrift server出问题的文章,里面也提到了健康检查:

反思

  • 不要急于下结论。先把日志完整分析下,服务的使用场景也要了解下,再下结论,而不要看到一点问题就瞎猜。
  • 需要了解下网络方面的基础知识了。