写于2020-01-13
一、故障描述
时间是2017年的某天:
有个服务,Python+Thrift做的Server;
对应库及版本:Cython==0.23.5,thriftpy==0.3.7。
相关配置:服务超时时间3s
线上使用Supervisor管理进程。
一直跑着没问题,有天运维同学提问题,该服务日志出现大量time out(那时候Kibana还没搭起来,日志只能在服务器上看)。日志如下:
2020-01-13 03:33:29,204 - thriftpy.server - ERROR - timed out
Traceback (most recent call last):
File "/ENV/local/lib/python2.7/site-packages/thriftpy/server.py", line 95, in handle
self.processor.process(iprot, oprot)
File "/ENV/local/lib/python2.7/site-packages/thriftpy/thrift.py", line 257, in process
api, seqid, result, call = self.process_in(iprot)
File "/ENV/local/lib/python2.7/site-packages/thriftpy/thrift.py", line 287, in process_in
api, type, seqid = iprot.read_message_begin()
File "thriftpy/protocol/cybin/cybin.pyx", line 428, in cybin.TCyBinaryProtocol.read_message_begin (thriftpy/protocol/cybin/cybin.c:6471)
File "thriftpy/protocol/cybin/cybin.pyx", line 60, in cybin.read_i32 (thriftpy/protocol/cybin/cybin.c:1688)
File "thriftpy/transport/buffered/cybuffered.pyx", line 66, in thriftpy.transport.buffered.cybuffered.TCyBufferedTransport.c_read (thriftpy/transport/buffered/cybuffered.c:1821)
return sz
File "thriftpy/transport/buffered/cybuffered.pyx", line 70, in thriftpy.transport.buffered.cybuffered.TCyBufferedTransport.read_trans (thriftpy/transport/buffered/cybuffered.c:1891)
if i == -1:
File "thriftpy/transport/cybase.pyx", line 61, in thriftpy.transport.cybase.TCyBuffer.read_trans (thriftpy/transport/cybase.c:1609)
File "/ENV/local/lib/python2.7/site-packages/thriftpy/transport/socket.py", line 108, in read
buff = self.sock.recv(sz)
timeout: timed out
二、排查过程
猜测:
- 在开发环境,跑起服务,调用成功,client能拿到数据,但这边server仍然报该日志错误;排除掉中间件影响;
- 看日志,buff = self.sock.recv(sz),这一句从语义上看,是server期望收到什么消息,但是没收到,然后sock等待超时,报timed out错误;
- 既然client能拿到数据,那就不是获取请求阶段出错,否则server拿不到请求参数,自然给不了结果;
- 细细想一遍todo-thrift请求处理流程,那就应该是,四次挥手关闭连接的时候,收握手消息出错了;
- 我们的server不主动关闭连接,大多数Thrift服务应该都是如此,因为thrift是允许在请求方在同一连接上发送多个请求的,更详细的讨论参见讨论;
-
对照下图,server在右边,左边的client端没有发送FIN/ACK,鉴于开发中一般都是用封装好的.close()方法,故发了FIN,没有发送ACK的情况应该可以排除。
image
验证:
- 使用 tcpdump -X -i eth0 port 80(-X可以看到的数据的十六进制和字符表示) 抓包,可以清楚的看到握手->client发送消息->server推送数据,然后没了,等过了3s,server超时,才看到server发送了FIN主动结束连接;
- 再看日志,该日志错误是某天突然多起来的,一问,是有个新服务上线,clone代码,找到请求的方法,代码(NodeJS)大致如下,少了finally {this.close();}
try {
result = await this._invoke(funcName, args);
} catch (err) {
this.logError(funcName, args, err);
if (err.name === 'ReturnFalse') {
return [err.returnCode, null];
}
throw err;
}
三、沟通问题
- 于是跑去和该项目负责人说明问题,但可能是我表述方式不对,又或者他忙;只说这项目代码在线上跑着也没问题,另一个相同代码的项目在线上都跑了好几年了,也没问题,你再查查。
- 然后,又是另一个故事了。。。
四、收获
- 复习了抓包,细细地分析了请求内容;
- thriftpy代码过了一遍,请求流程大致清楚;
- 注意和人沟通问题的方式,太直不利于推进问题。
网友评论