记录一次线上 connection reset 排查

有开发人员发现他们的应用程序经常报一个空指针的错误, 他们自己查不出来是啥原因, 就报给了网络团队, 因为在这个空指针前面, 打了一行日志, 说接收回应数据为空(Response is empty), 他们认为网络时不时有问题.

  1. 找到对应的代码, 发现有人写了一段这样的代码:

    try {
//access another service
Response rsps = callAnotherService();
} catch (Exception e) {
logErr("Response is empty", e.getMessage);
}
return rsps;
  2. 上面这段代码中, 捕获异常, 只是打印了日志, 没有做错误处理, 这时候返回的 rsps 肯定为 null, 就可能导致上层调用者空指针异常. 通常我们需要封装之前的 Exception, 如果没有封装, 那么最好打印之前异常的错误栈到日志中, 这样方便排查问题出在哪一行. 另外这里有个特殊的地方, logErr() 方法的第二个参数并没有打印到日志中, 而是做了其它用途, 导致开发人员最后只看到 "Response is empty", 没看到具体出错原因.
  3. 对这行代码改造之后, 我们看到了出错栈和具体原因: connection reset by peer. 就是连接被断掉了.
  4. 于是做 tcpdump, 发现对于这种情况基本是客户端发出请求后, 服务端就 reset 了连接;
  5. 由于中间使用了 LB, 复制 LB 的同事在 LB 上双向抓包, 说是服务端主动 reset 连接;
  6. 于是在服务端抓包, 确实发现有时候服务端在收到请求后主动 reset 连接;

  7. 观察服务端的情况, 发现有些发来的请求服务端已经在处理了, 等处理完发现连接已经被 reset, 有些根本没进入服务端进行处理. 其它观察到的一些情况

    1. 服务端是异步 IO, 所以有些线程负责建立连接, 负责数据的读取写入, 有些负责业务处理;
    2. 服务端并没有发现特殊的线程 interrupt 的情况(这种情况很容易造成 IO 连接中断);
    3. 服务端在处理的时候, 又使用了 @suspended AsyncResponse. 基本是 Tomcat server 线程处理了 token 验证, 之后就留给线程池处理了.
  8. 通过 perf 过滤操作系统层面的 tcp:reset, 确实发现一些从tomcat 端口 reset 的连接, 可是由于是没有java 代码的栈, 所以看不出为什么要 reset;
  9. 于是对 java 进程添加 -XX:+PreserveFramePointer, 生成符号表文件, 成功看到部分 java 栈. 可是由于另外一些还是热度不够, 看到的代码仍然是翻译过来的, 所以看到的都是 Interpreter:
    interpreter.png
  10. 不过通过async-profiler 持续抓包, 终于捕获类似一个 java 栈:
    close_reset.png
  11. 通过 2 个栈相结合, 能看到导致 reset 的原因是: 代码中出了某种问题, 要 close 连接, close 的时候, 发现正常 close 的条件没达到, 比如还有没读的数据, 只能直接 reset;
  12. 导致 close 的代码段是:
    close.png

到底是什么情况导致 cancelledKey() close, 未完待续

标签: none

添加新评论