有人上报说他们的 app 连接另外一个微服务的时候, 连接经常断掉, 不知道什么原因.

查看网络方面的监控, 网络一切安好.

查看日志, 看到一些异常信息: java.nio.channels.ClosedByInterruptException. 顺着这个信息, 我们找到了根本原因.

1. 既然是 java.nio.channels.ClosedByInterruptException, 那么我们可以用 btrace 查看为什么这个异常被创建, 得到结果如下:

   java.nio.channels.ClosedByInterruptException.<init>(ClosedByInterruptException.java:51)
   java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
   sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:477)
   com.tianxiaohui.java.BufferedWriteChannel.flush(BufferedWriteChannel.java:281)
   com.tianxiaohui.java.BufferedWriteChannel.write(BufferedWriteChannel.java:223)
   com.tianxiaohui.java.BaseClient.sendBytesActual(BaseClient.java:339)
   com.tianxiaohui.java.BaseClient.sendBytesOverChannel(BaseClient.java:203)
   ...
   rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
   rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
   rx.Observable.unsafeSubscribe(Observable.java:10327) 
   rx.internal.operators.OperatorSubscribeOn$SubscribeOnSubscriber.call(OperatorSubscribeOn.java:100)
   rx.xinternal.schedulers.CachedThreadScheduler$EventLoopWorker$1.call(CachedThreadScheduler.java:230)
   rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
   ...
    java.lang.Thread.run(Thread.java:748)

2. 既然是 interrupt 异常, 那么就一定有其它线程给这个线程发 interrupt, 于是通过下面的 btrace 代码, 我们就能找到发 interrupt 的线程

   import org.openjdk.btrace.core.annotations.*;
   import static org.openjdk.btrace.core.BTraceUtils.*;
   
   import org.openjdk.btrace.core.BTraceUtils.Strings;
   
   @BTrace
   public class ThreadInterruptTrace {
   
    @OnMethod( clazz="/java\\.nio\\.channels\\.ClosedByInterruptException/", method="<init>" )
    public static void createException() {
      println(Strings.strcat(name(currentThread()), " --- get ClosedByInterruptException "));
      println(jstackStr());
    }
   
    @OnMethod( clazz="/java\\.lang\\.Thread1/", method="/interrupt/" )
    public static void t1r(@ProbeClassName String probeClass, @Self Thread self) {
      if (Strings.startsWith(name(self), "RxIoScheduler")) {
          println(Strings.strcat(Strings.strcat(name(currentThread()), " try to interrupt ->  "), str(self)));
            println(jstackStr());
        }
    }
   }

3. 找到发 interrupt 的线程, 那么就去看代码, 找了发生 interrupt 的原因, 最终原因是下面的代码. 每次 create 一个 Observable 都要新起一个线程池做为 scheduler, 其实不需要. 到时每次新建一个 scheduler 线程池导致创建太多线程池, 消耗大量内存, 之后又自动销毁. 然后这些 scheduler 销毁的时候, 还要通知 I/O 线程(这里的 I/O 线程池用的默认的), 也就是给 I/O 线程发一个 interrupt. 最终导致了我们看到的问题.

   Observable.create(new Observable.OnSubscribe<List<T>>() {
    @Override
    public void call(Subscriber<? super List<T>> subscriber) {
           //some code here
      }
    }).}).observeOn(Schedulers.newThread())
       .subscribeOn(Schedulers.io())
       .timeout(threadTimeout, TimeUnit.MILLISECONDS);
   

下面内容是从 https://www.opsian.com/faq/ 页面抄的:

If you've downloaded a JVM from a normal distribution - for example Oracle, Azul or Adopt OpenJDK - then it will come with debug symbols built in. Many distributions do not ship debug symbols with their JDK packages, this will result in some features of the Opsian agent not being available. It is easy to install the debug packages.

Ubuntu - If you are using Java 11 then run apt install openjdk-11-dbg or if you're running Java 8 then run apt install openjdk-8-dbg
Red Hat / Centos - If you are running version 7 or later then you need to Enable the DebugInfo repository on Red Hat or Centos. Then you need to install the appropriate debug info package for your JDK version, for example yum -y install java-1.8.0-openjdk-debuginfo.x86_64 if you're using Java 8.

附带一张 18 年参加 SRE con 上面别人的总结:

1. L4 使用 OSI 模型的第 4 层的信息来决定下一个路由是哪里, 一般使用源 IP, 源端口, 目标 IP, 目标端口;
2. L4 一般使用专门的芯片快速解包, 修改包. 如今 CPU 和内存都足够快, 越来越多使用软件 LB;
3. 所谓修改包就是做 Network Address Translation (NAT), response 回来时候, 也要修改回去;
4. 因为只使用 L4 包头的一些信息, 所以只要提取包头的少量信息就可以了;
5. L7 是分析应用层协议的属性来判断下一个路由, 同样它也要拆包, 并且要拆到第 7 层, 然后修改包;

比如 java.lang.Thread.java 里面定义了定义了一些 native 代码, 那么如何找到这些 native 代码呢? 使用 google search 对应的 .c 文件:
thread.c site:openjdk.java.net

又比如: sun.nio.ch.FileDispatcherImpl.java 里面定义了一些 native 代码, 那么只要 search:
FileDispatcherImpl.c site:openjdk.java.net
就可以了.

有开发人员发现他们的应用程序经常报一个空指针的错误, 他们自己查不出来是啥原因, 就报给了网络团队, 因为在这个空指针前面, 打了一行日志, 说接收回应数据为空(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:
   
10. 不过通过async-profiler 持续抓包, 终于捕获类似一个 java 栈:
    
11. 通过 2 个栈相结合, 能看到导致 reset 的原因是: 代码中出了某种问题, 要 close 连接, close 的时候, 发现正常 close 的条件没达到, 比如还有没读的数据, 只能直接 reset;
12. 导致 close 的代码段是:
    

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