thrift server timed out超时

写于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. 注意和人沟通问题的方式，太直不利于推进问题。