美文网首页
thrift server timed out超时

thrift server timed out超时

作者: 风雨灿烂 | 来源:发表于2020-01-13 21:34 被阅读0次

写于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

二、排查过程

猜测:

  1. 在开发环境,跑起服务,调用成功,client能拿到数据,但这边server仍然报该日志错误;排除掉中间件影响;
  2. 看日志,buff = self.sock.recv(sz),这一句从语义上看,是server期望收到什么消息,但是没收到,然后sock等待超时,报timed out错误;
  3. 既然client能拿到数据,那就不是获取请求阶段出错,否则server拿不到请求参数,自然给不了结果;
  4. 细细想一遍todo-thrift请求处理流程,那就应该是,四次挥手关闭连接的时候,收握手消息出错了;
  5. 我们的server不主动关闭连接,大多数Thrift服务应该都是如此,因为thrift是允许在请求方在同一连接上发送多个请求的,更详细的讨论参见讨论
  6. 对照下图,server在右边,左边的client端没有发送FIN/ACK,鉴于开发中一般都是用封装好的.close()方法,故发了FIN,没有发送ACK的情况应该可以排除。


    image

验证:

  1. 使用 tcpdump -X -i eth0 port 80(-X可以看到的数据的十六进制和字符表示) 抓包,可以清楚的看到握手->client发送消息->server推送数据,然后没了,等过了3s,server超时,才看到server发送了FIN主动结束连接;
  2. 再看日志,该日志错误是某天突然多起来的,一问,是有个新服务上线,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;
}

三、沟通问题

  1. 于是跑去和该项目负责人说明问题,但可能是我表述方式不对,又或者他忙;只说这项目代码在线上跑着也没问题,另一个相同代码的项目在线上都跑了好几年了,也没问题,你再查查。
  2. 然后,又是另一个故事了。。。

四、收获

  1. 复习了抓包,细细地分析了请求内容;
  2. thriftpy代码过了一遍,请求流程大致清楚;
  3. 注意和人沟通问题的方式,太直不利于推进问题。

相关文章

网友评论

      本文标题:thrift server timed out超时

      本文链接:https://www.haomeiwen.com/subject/llpgactx.html