在诊断Java应用的过程中, 经常发现有些 Socket 连接还没读, 然后就被放弃了, 然后应用程序对这些连接就置之不理, 导致连接泄漏.

当发生连接泄漏之后, 要去诊断是那个地方导致的连接泄漏, 于是就是一个逆向的过程. 从开始知道连接泄漏的URL找到泄漏的代码. 如果这些泄漏的连接还在 Java 内存, 可以从 heap 当中找到这些 Socket, 然后读取其中未读的 Request/Response, 这样就能很容易的找到当时访问的什么请求, 对方发回的什么响应, 然后去审察代码.

如何找到这些 Socket

假如你知道要访问的 URL, 一般一个 OQL 就能查询到对应的socket, 比如:

SELECT * FROM org.apache.http.impl.conn.DefaultClientConnection c WHERE (toString(c.targetHost.hostname) like ".*.online-metrix.net")![request.png][1]

从Socket 读取请求数据

从 Socket 读取响应数据

最近有个应用上线, 在本地环境和测试环境运行的好好的, 可是发布到生产环境竟然跑不通. 每次就报下面的这个错误:

java.lang.NoSuchMethodError: 'io.grpc.netty.NettyChannelBuilder io.grpc.netty.NettyChannelBuilder.maxInboundMessageSize(int)'
at org.nugraph.client.gremlin.driver.remote.GrpcConnectionPool.createNewConnection(GrpcConnectionPool.java:775)
at org.nugraph.client.gremlin.driver.remote.GrpcConnectionPool.fillConnectionPool(GrpcConnectionPool.java:596)
at org.nugraph.client.gremlin.driver.remote.GrpcConnectionPool.createNewConnections(GrpcConnectionPool.java:649)
at org.nugraph.client.gremlin.driver.remote.GrpcConnectionPool.connect(GrpcConnectionPool.java:684)

出错信息分析

从上面的信息看, 还是说很明确的. 就是找不到 NettyChannelBuilder 的 maxInboundMessageSize 方法. 这个方法传入一个 int 类型的参数, 返回一个 NettyChannelBuilder 实例对象.

然后我们在开发工具里面很快就找到了这个类 NettyChannelBuilder, 虽然它没有声明这样一个方法, 但是它实现的抽象父类 AbstractManagedChannelImplBuilder 确实有这个方法. 也就是它有这么一个期望的方法.

public final class NettyChannelBuilder
    extends AbstractManagedChannelImplBuilder<NettyChannelBuilder>

初步分析

先是问了谷歌, 确实有人遇到过类似的问题, 答案是当时版本不一致造成的. 于是看看本地的jar包版本, 分别是:
grpc-core-1.31.1.jar是1.31.1, 它包含 AbstractManagedChannelImplBuilder.
grpc-netty-1.31.1.jar是1.31.1, 它包含 NettyChannelBuilder.

于是远程登录到生产环境, 解压开总的jar包, 核对一下上面的2个 jar 包, 发现一模一样. 奇怪.

还有其它不同版本的jar包?

为了确认一定加载的是上面提及的两个版本的jar包, 于是我去审查了这个进程的启动参数. 原因是在生产环境使用的启动命令和本地不一样, 生产环境配置了更多的参数. 对比下来, 发现生产环境并没有多加额外的jar包进去.

于是在生产环境的启动参数里面添加了 -verbose:class 的启动参数, 这样就能打印出加载的所有类来自于那个jar包.

INFO   | jvm 1    | 2023/09/22 08:04:22 | [86.958s][info][class,load] io.grpc.netty.NettyChannelBuilder source: jar:file:/tmp/myapp-0.0.1-SNAPSHOT.jar!/BOOT-INF/lib/grpc-netty-1.31.1.jar!/
INFO   | jvm 1    | 2023/09/22 08:04:22 | [86.958s][info][class,load] io.grpc.internal.AbstractManagedChannelImplBuilder source: jar:file:/tmp/myapp-0.0.1-SNAPSHOT.jar!/BOOT-INF/lib/grpc-core-1.31.1.jar!/

统一版本不同的jar包内容?

于是从生产环境把这些 jar包复制到本地, 然后使用反编译软件查看内容, 是一样的.

该类没加载成功?

上面的类加载日志可以看到, 类其实是加载了的. 并且做了 heap dump 能够看到这两个类.

反射查看类的方法

为了确认该方法确实存在, 于是使用反射机制去查看它声明的方法:

      try {
            Class<?> c = NettyChannelBuilder.class;
            Method[] declaredMethods = c.getDeclaredMethods();
            for (Method method : declaredMethods) {
                System.out.println(method.getName() + " is declared in NettyChannelBuilder.");
                System.out.println("params: " + Arrays.asList(method.getParameterTypes()));
                System.out.println("return type: " + method.getReturnType());
            }

            System.out.println("NettyChannelBuilder super class is: " + c.getSuperclass());

            //c = AbstractManagedChannelImplBuilder.class;
            c = c.getSuperclass();
            declaredMethods = c.getDeclaredMethods();
            for (Method method : declaredMethods) {
                System.out.println(method.getName() + " is declared in AbstractManagedChannelImplBuilder.");
                System.out.println("params: " + Arrays.asList(method.getParameterTypes()));
                System.out.println("return type: " + method.getReturnType());
            }
        } catch (Exception e) {
            e.printStackTrace();
        }

确实是存在的:

2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT maxInboundMessageSize is declared in AbstractManagedChannelImplBuilder.
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT params: [int]
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT return type: class io.grpc.internal.AbstractManagedChannelImplBuilder
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT maxInboundMessageSize is declared in AbstractManagedChannelImplBuilder.
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT params: []
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT return type: int
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT maxInboundMessageSize is declared in AbstractManagedChannelImplBuilder.
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT params: [int]
2023-09-22 19:42:54,692 INFO [DefaultThreadPool-7] STDOUT return type: class io.grpc.ManagedChannelBuilder

手动修改调用类

根据出错栈, 出错的方法是: GrpcConnectionPool.createNewConnection(GrpcConnectionPool.java:775). 根据source code 代码可以看出, 其 775 行确实是调用了 maxInboundMessageSize 方法.

因为本地环境无法重现, 所以把这个代码复制到本地, 写一个同样包名类名的类, 然后放到 classes 目录, 这样 classes 目录里的优先级高先会被加载, 本来在 jar 包里面的就无法被加载. 如此就能在复制的这个类里面加一些日志代码, 方便打印一些信息.

加入一些打印日志信息后, 上传到服务器 classes 目录, 然后在测试, 竟然没在报错. 神奇!

在复制覆盖的这个类的过程中, 只有2处疑点:

1. 原来包含 GrpcConnectionPool 类的jar包是使用 JDK 8 编译的, 而我本地和生产环境都是 JDK 11.
2. source jar 中包含的 GrpcConnectionPool 使用了 lombok.extern.slf4j.Slf4j 的注解 @Slf4j, 但是我本地开发环境没设置 lombok, 所以报错. 只能去除 @Slf4j, 手工加入该类的 private static final Logger log = LoggerFactory.getLogger(GrpcConnectionPool.class)

也就是说重新编译上传的是可以运行的.

重新编译的差别在哪?

猜测之一是: 重新编译使用的是 JDK 11编译, 所以没报错. 于是单独对复制过来的类使用 JDK 8 编译, 然后重新调用, 发现还是好的.

于是对出错的版本和刚编译的新版本进行反编译, 然后对比, 竟然发现了差别:

// 之前出错版本的反编译:
((NettyChannelBuilder)(
    (NettyChannelBuilder)(
        (NettyChannelBuilder)
            NettyChannelBuilder.forAddress(entry.getHost(), entry.getRpcPort())
                .sslContext(GrpcSslContexts.configure(SslContextBuilder.forClient()).trustManager(trustManagerFactory).build())
                .maxInboundMessageSize(messageSizelimit)
                .intercept(new ClientInterceptor[] { clientInterceptor })
        ).overrideAuthority(strAuthorityOverride)
    ).idleTimeout(entry.getTtl(), TimeUnit.MILLISECONDS)
).build()
// 现在运行正确的版本反编译:
((NettyChannelBuilder)
    ((NettyChannelBuilder)
        ((NettyChannelBuilder)
            ((NettyChannelBuilder)
                NettyChannelBuilder.forAddress(entry.getHost(), entry.getRpcPort())
                .sslContext(GrpcSslContexts.configure(SslContextBuilder.forClient()).trustManager(trustManagerFactory).build())
                .maxInboundMessageSize(messageSizelimit)
            ).intercept(new ClientInterceptor[]{clientInterceptor})
        ).overrideAuthority(strAuthorityOverride)
    ).idleTimeout(entry.getTtl(), TimeUnit.MILLISECONDS)
).build();

仔细对比2个版本, 就会发现差别. 之前的代码少一次强制转换, 新的代码在字节码中多一次转换. 但是2次的原代码都是一样的, 原代码如下:

NettyChannelBuilder.forAddress(entry.getHost(), entry.getRpcPort())                    .sslContext(GrpcSslContexts.configure(SslContextBuilder.forClient()).trustManager(trustManagerFactory).build())
    .maxInboundMessageSize(messageSizelimit)
    .intercept(clientInterceptor)
    .overrideAuthority(strAuthorityOverride)
    .idleTimeout(entry.getTtl(), TimeUnit.MILLISECONDS)
    .build();

对比2次编译结果, 可以发现在出错的版本里面, 编译器认为执行完 maxInboundMessageSize(messageSizelimit) 方法后返回的是 NettyChannelBuilder, 不需要强转, 而后面的执行正常的版本任务执行完maxInboundMessageSize(messageSizelimit) 方法后返回的是 AbstractManagedChannelImplBuilder, 需要一次强转. 这都是编译起自动做的工作, 源代码体现不出来.

为什么那次编译不需要强转

最新的编译版本需要强转, 是因为那个方法声明在 AbstractManagedChannelImplBuilder 类, 返回的值是它的之类, 但是它不知道子类的具体类型, 所以加一个强转(这也是我之前由于对这块不熟悉, 不能做为推理依据的原因).

但是为什么之前那个版本不需要强转呢? 尝试使用了不同版本的 JDK 去编译, 然后在反编译, 也不能找出答案.

于是把那jar所在的项目 clone 下来, 然后本地建立工程, 再去查看源代码, 竟然发现它依赖的 grpc-core 和 grpc-netty 竟然和我依赖的不一样. 在那个版本里面 maxInboundMessageSize(messageSizelimit) 这个方法竟然是声明在 NettyChannelBuilder 里面的, 当然不需要强转. 然而我现在使用的版本, 这个方法是声明在 AbstractManagedChannelImplBuilder 里面的, 当然需要强转.

所以问题就出在依赖的 grpc-core 和 grpc-netty 的版本不一致造成的, 出错的那个 jar 依赖的grpc版本较新, 而我的项目里面依赖的grpc 版本较旧.

为什么依赖的版本不一致?

按照依赖传递的原则, 我的项目依赖那个出错的jar, 它把它所依赖的版本传递进来, 应该是一致, 可是现在我这边看到的却是老版本. 我这个项目没有直接依赖 grpc, 间接依赖的共2处. 就是出错的这个 graph-xxx.jar 和 jetch-xxx.jar. 仔细察看这两个 jar, 他们依赖的 grpc 相关的jar 都是新版本, 为什么我的项目却依赖的一个旧版本呢?

为了排除干扰, 分别去除 graph-xxx.jar 或 jetch-xxx.jar, 每个依赖的仍然是旧版本. 使用 mvn dependency:tree 去单独查看这两个jar 包的 pom 文件, 看到的每个依赖的都是新版本. 怪异.

修改自己项目的 pom.xml, 单独排除

为了彻底查找到底是哪里引入的旧版本, 于是二分法去除其它依赖的jar, 最后发现即便仅仅依赖 graph-xxx.jar 或 jetch-xxx.jar, 仍旧是老版本, 但是单独查看这两个jar的pom.xml, 却都是新版本.

最后发现自己的项目还有 parent 项目

<parent>
  <groupId>com.tianxiaohui.platform</groupId>
  <artifactId>raptor-io-parent</artifactId>
  <version>0.18.1-RELEASE</version>
  <relativePath></relativePath>
</parent>

若是去掉做个parent project, 那么依赖都变成了新版本, 也就说由于有个 parent project, 它管制了 grpc 版本的依赖, 导致依赖到了老版本.

查看 parent project 依赖

当有parent project 的时候, 如果父子project 对某个jar 都有依赖, 就会使用 parent project 使用的. 所以要找出是哪个 parent project 使用了旧版本.

使用下面命令能查看当前项目的依赖:

# 自己体会下面3个不同
apache-maven-3.9.1/bin/mvn  dependency:tree 
apache-maven-3.9.1/bin/mvn  dependency:tree -Dincludes=io.grpc:grpc-netty 
apache-maven-3.9.1/bin/mvn  dependency:tree -Dincludes=io.grpc:grpc-netty -Dverbose

但是它不能显示 parent project 依赖.

方法的签名

在最早的 Error message java.lang.NoSuchMethodError 后面, 给出了缺少的方法名字. 但是我们看到当时那个版本的类的父类是包含做个方法签名的.

在Java 里面, 一个方法的签名是指由 方法名, 参数类型, 参数顺序, 参数个数 这几个因素决定的. 方法的返回值并不能决定方法签名.

但是在字节码中, 方法的签名是包含包含返回值的. 因为字节码支持的其它动态语言是需要返回值做签名的.

如果 类A extends 非抽象类 B, 那么类A 的方法(A.getClass().getMethods())会包含 类B 的所有实例方法(非static).
如果 类A extends 抽象类 B, 那么类A 的方法(A.getClass().getMethods())会包含 类B 的所有实例方法, 若A override 了某个方法, 并且返回了不一样的值类型, 那么会出现2个不同的方法, 一个属于A, 一个属于B.

在诊断Java应用的时候, 我们经常看到很多异步的调用, 当前线程等待其它线程返回结果. 有时候会发现这些线程迟迟没有往下走, 于是查看线程状态, 会看到如下的线程栈:

sun.misc.Unsafe.park(Native Method) 
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) 
java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429) 
java.util.concurrent.FutureTask.get(FutureTask.java:191) 
com.tianxiaohui.RboCache.compute(RboCache.java:46)

我们会很自然的发问, 为什么它停在这, 到底发生了什么?

初步分析

对于这种情况, 有2种情况:

1. 这个任务还没有被执行, 所以没有结果;
2. 这个任务在执行中, 所以还没有结果;

对于第一种情况, 要去查看线程为什么没启动, 或者线程池为啥没执行它. 通常这时候要查看线程池的core size, max size, 和workQueue 和 workers 的情况.
对于第二种情况, 则要查看执行的线程在干什么事情, 为什么还没出结果.

java.util.concurrent.Future

对于java.util.concurrent.Future 我们很容易的能从它的字段: runner 看出谁在执行, 还是没有在执行, 如下图:

java.util.concurrent.CompletableFuture

对于 java.util.concurrent.CompletableFuture 则稍微麻烦一些, 要看谁指向它:

1. 如果指向它的对象除了当前线程还有另外一个线程, 那么另外一个线程就是执行线程;
2. 如果指向它的对象除了当前线程还有一个等待队列中的某个对象, 则它还没开始执行;
   
   

上面用到的代码:

import java.util.concurrent.Callable;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.function.Supplier;

public class WhyFutureStuck {
    
    public static void main(String[] args) {
        ExecutorService es = Executors.newFixedThreadPool(2);
        
        Future<String> f1 = es.submit((Callable<String>) new Callable<String>() {
            @Override
            public String call() throws Exception {
                Thread.sleep(3600 * 1000);
                return "result-f1";
            }
        });
        
        CompletableFuture<String> cf1 = CompletableFuture.supplyAsync((Supplier<String>) () -> {
            try {
                Thread.sleep(3600 * 1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            return "result-cf1";
        }, es);
        
        //threads are used up
        Future<String> f2 = es.submit((Callable<String>) new Callable<String>() {
            @Override
            public String call() throws Exception {
                Thread.sleep(3600 * 1000);
                return "result-f2";
            }
        });
        
        CompletableFuture<String> cf2 = CompletableFuture.supplyAsync((Supplier<String>) () -> {
            try {
                Thread.sleep(3600 * 1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            return "result-cf2";
        }, es);
        
        try {
            System.out.println(f1.get());
            System.out.println(f2.get());
            System.out.println(cf1.get());
            System.out.println(cf2.get());
        } catch (InterruptedException | ExecutionException e) {
            e.printStackTrace();
        }
    }
}

最近接手一个新的Java项目, 架构师明确要Java 11 版本, 于是在 eclipse 里面设置使用JDK 17, JDK 编译器兼容 level 设置成 11. 设置完成后, 然后重新编译, 竟然报错了, 还是几百个错误!

错误内容全部是: The package java.util is accessible from more than one module: <unnamed>, java.base.

如下图, 这些从java.util引用的类, 全部都报这个错:

这个错误代表什么意思

Java 9 开始有了模块化系统的概念(JPMS), 每个Java 文件都属于某个模块. 例如上面例子中出现的 java.util.HashMap, java.util.concurrent.TimeUnit 都属于JDK里面的 java.base 模块.

那么<unnamed> 模块是什么呢?

对于JDK本身, 它默认已经分了模块, 但是我们还有很多jar包, 并没有按照模块的方式去打包, 或者在JDK 9 之前就有了这些jar包, 我们照样可以依赖它们.

对各种模块的依赖, 会加到modulepath, 对于非模块的依赖, 继续使用classpath. classpath上的类会被统一的分配到一个叫<unnamed>的模块.

如下面的 eclipse 截图所示, 所有maven的依赖全部放到了classpath.

错误含义

所以, 这个错误的真正含义是: 在我们依赖中, java.util包即出现在了 JDK 的 java.base 这个模块, 也出现在了我们依赖的classpath上. 而Java模块化系统不允许同一个包出现在2个模块里面.

如何修复

有2种可能的方案:

1. 退回到Java 8, 不使用模块化的概念, 错误消失.
2. 找到提供java.util包的jar包, 质问开发者为啥给自己的jar包加入jdk的包名, 是想夹带私货吗?

我们这里只能选择第二个选项, 所以如何找到这个包含java.util的jar包成了重点.

如何找到第二个包含java.util的jar包

看到最初错误截图里面那些类, 我们很直观的可能认为: 只要使用eclipse的 open type 菜单是不是就很容易找到了, 我们试一下:

从上面截图可以看到, eclipse 只找到一个HashMap, 并且源自于JDK11, 同样, 对于java.uti.Map, java.util.concurrent.TimeUnit 我们也只能找到仅有的一个属于JDK的.

明明报了java.util包来自2个模块, 为啥我们只找到一个呢?

其实, 我们上面的方式去找HashMap这个类出现在哪个包, 但是这个错误的真正的重点是包的名字, 也就是说, 有另外一个jar包里包含了java.util.Xxxx, 它不管类名是什么, 只管包名和JDK里面的java.util包重复了.

我们可以同样的方式在 eclipse 的 open type 里面输入java.util.*, 只不过会出现非常长的列表, 然后人工一个个对比.

如何手工找到这个jar包

这里提供2个方法:

1. 方法一: 使用 eclipse open type, 然后输入 java.util.*,如下图, 按顺序找一定能找到:
   
2. 方法二: 在 maven 的pom.xml 里面去掉一部分依赖, 看是不是这个错误消失了(同时其它依赖缺失错误会出现), 如果这个消失了, 说明去掉的这个依赖里面(直接或间接)包含这个包名. 使用一次去掉多个依赖(二分查找)可以加快速度.

如何自动化找到这个jar

eclipse 能报出这个错误, 说明它在我们的依赖中, 除了JDK之外还有一个jar包含这个包. 那么, 我们可以用同样的方法, 找到这个jar.

步骤:

1. 通过 mvn 命令找到所有的依赖jar.
2. 查找 jar 里面的类全名是不是包含 java.util.

mvn 命令找到所有的依赖jar

首先, 我们进入的项目pom.xml 所在的目录, 然后执行mvn 的goal: dependency:build-classpath, 把输出结果全部放到/tmp/dep.txt文件.

$ cd <project_dir>
$ ~/work/tools/apache-maven-3.9.1/bin/mvn dependency:build-classpath -Dmdep.outputFile=/tmp/dep.txt

打开/tmp/dep.txt文件, 可以看到里面是以:(MAC上)分割开的jar文件名.

遍历查找每个jar的类

第二步, 读取上面的输出, 以:分隔成多个jar, 然后遍历每个jar, 找出包含java.util的类,

    jars=(${(s/:/)$(cat /tmp/dep.txt)})
    for i in "${jars[@]}" 
    do 
        jar -tf $i | grep '^java.util' && echo "\t\tfind in ${i}"
    done

执行上面的脚本(mac 上的zsh), 得到如下结果:

java/util/
java/util/concurrent/
java/util/Hashtable.class
java/util/concurrent/ConcurrentHashMap.class
        find in /Users/eric/.m2/repository/com/boundary/high-scale-lib/1.0.6/high-scale-lib-1.0.6.jar

最终, 通过几行shell命令, 我们也找到了包含这个包名的jar包.

总结

Java 9 之后, 开始分模块, 一个项目可能既有对模块的依赖, 还有对普通jar包的依赖, 这些以前的jar包会被放到一个<unnamed>的模块. 如果一个包名出现在多个模块中(包含<unnamed>的模块), 就会出现这个错.

本文中另外一个出现在<unnamed>的模块, 可以通过遍历查找依赖jar的方式去查找到这个jar包.

JDK 里面有哪些模块?

java --list-modules

有开发人员问我, 有没有见过这个 Java 应用报出的异常消息: IO Error: Remote host terminated the handshake. 从这个message看, 这个是说无法通过握手建立连接, 单纯从这个消息看, 看不出来什么原因.

背景

这个应用最近更改了不少文件, 然后重新发布新版本, 就出现了这个错误. 出这个错误的上下文是: 这是一个连接 Oracle 数据的连接, 使用的是TSLv1.2加密连接.

他们问了DBA, DBA 说数据库完好, 问了网络, 网络也没有其它问题.

诊断

最简单的方法是抓包, 查看具体的握手失败的原因. 抓包后看到如下的 SSL client hello 协议内容, 然后服务器就拒绝了:

从上面的截图我们可以看到, tcp 三次握手, 正常. 然后客户端发送 client hello, 服务器直接就发了 FIN, 要拒绝连接.

在看 client hello 的具体消息, 从消息可以看到, 这里上面写的是 SSLv2, 难道这是1995年使用的 SSL 2.0? 看上去很奇怪.

如果比较熟悉 TLS 协议, 我们可以知道, 在TLS 层, 又分为 TLS record 协议, 它内部又封装了具体的 TLS 子协议, 分别是: Application, Alert, Handshake, ChangeCipherSpec. 而 record 协议的第一个字节表示子协议的类型.

然而我们这个截图里面, 前两个字节是 80 b3, 表示内容长度, 关键是 Wireshark 认识这种格式. 太诡异了.

然后仔细查看 Wireshark 的解析, 我们看到 Wireshark 标注的是: SSLv2 Record Layer: Client Hello.

关于 SSLv2Hello

顺着这个关键字, 我们终于找到了另外一种协议: SSLv2Hello. 这是一种伪协议, 它是 Oracle 之前发明的, 并且现在已经不在使用的. 它的主要作用是在客户端发送一个SSLv2Hello消息, 试探一下服务端使用的到底是哪种协议, 是 TLS 1.1, 还是 TLS 1.2.

JDK 里面在 JDK 7 之前默认是有这种协议的, 之后 Oracle disable 了它.

-- 未完待续 --