Written by 🍺
on September 29, 2024

dubbo 升级引发的StackOverflowError

最近主导了项目组的 dubbo 版本升级，从 dubbo 2.6.0 升级到 2.7.23，这周五上班的路上看到群里说线上有个功能出现了异常，提示远程调用失败，当时我就知道出事了，还好影响范围很小，这里简单记录分享下处理和排查的过程。

线上处理恢复

当时来到公司，一查日志都是长长的堆栈，伴随着java.lang.StackOverflowError。因为日志被截断了，一下子无法定位到具体位置，了解到异常的触发点是一个查询接口，IN 查询了大概 1800 个 key。让项目组尝试使用少量的 key 进行调用，发现能正常调用（当时松了一口气），最后测试下来在 1600 key 左右出现异常。项目组走紧急版本，改成 500 一次的分批查询，发版后线上异常恢复。

故障定位

既然是StackOverflowError，又和 sql 有关系，既然是要采集下基础信息。

基础信息

栈空间大小使用java -XX:+PrintFlagsFinal -version | grep ThreadStackSize,

1
2
3
4
5
6


     intx CompilerThreadStackSize                   = 0                                   {pd product}
     intx ThreadStackSize                           = 1024                                {pd product}
     intx VMThreadStackSize                         = 1024                                {pd product}
openjdk version "1.8.0_352"
OpenJDK Runtime Environment (Temurin)(build 1.8.0_352-b08)
OpenJDK 64-Bit Server VM (Temurin)(build 25.352-b08, mixed mode)

ORM框架使用hibernate
项目组通过 JVM 参数使用了-Xss256k，配置了栈空间为 256k。

堆栈中打印的异常信息

stack antlr.BaseAST toStringList

进一步定位

因为线上日志中，堆栈信息太深了，没有全部打印。使用 arthas 进行排查。 stack antlr.BaseAST toStringList -n 1

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14


    @antlr.BaseAST.toStringList()
        at antlr.BaseAST.toStringList(BaseAST.java:347)
        at antlr.BaseAST.toStringList(BaseAST.java:343)
        at antlr.BaseAST.toStringList(BaseAST.java:343)
        at antlr.BaseAST.toStringTree(BaseAST.java:358)
        at org.hibernate.hql.internal.ast.HqlSqlWalker.processQuery(HqlSqlWalker.java:654)
        at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.query(HqlSqlBaseWalker.java:673)
        at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.selectStatement(HqlSqlBaseWalker.java:309)
        at org.hibernate.hql.internal.antlr.HqlSqlBaseWalker.statement(HqlSqlBaseWalker.java:257)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.analyze(QueryTranslatorImpl.java:262)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.doCompile(QueryTranslatorImpl.java:190)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.compile(QueryTranslatorImpl.java:142)
        ...
        //省略了下面一大堆的代码

排查源码

org.hibernate.hql.internal.ast.HqlSqlWalker.processQuery

源码判定为 debug 等级导致的hibernate对 sql 调用了toStringTree 打印执行的 sql，导致堆栈溢出。但为什么日志等级会突然间发生变化，此次升级没有改动到hibernate以及日志框架。

JBoss Logging

回到调用类HqlSqlWalker，注意到使用的 LOG 其实是经过 hibernate 封装的

1

private static final CoreMessageLogger LOG = CoreLogging.messageLogger(HqlSqlWalker.class);

具体实现则是使用的jboss.logging，jboss.logging会自动适配当前使用的日志框架进行日志输出，根据官方文档它存在一个发现顺序

JBoss Log Manager JBoss
Log4j 2
SLF4J and Logback SLF4J 和 Logback
log4j (note this log manager is EOL’d)
Java Util Logging

而我们项目本身使用的是slf4j，会不会是升级 dubbo 的过程中无意间引入了一个log4j2，导致 JBoss 优先使用了 log4j2 而不是 slf4j。对线上运行的 jar 包进行解压，lib 包中果然发现了log4j-1.2.17.jar，确定就是因为无意中引入了log4j，导致 jboss 的日志发现使用了非预期的 log4j，而 log4j 没有配置日志等级，导致默认输出了 debug 日志，最终出现栈溢出。

修复

确定是依赖问题，下面就是怎么修复的问题了。使用依赖分析确定log4j 是从封装的 sdk 包中引入进来的，对 log4j 手动进行exclusion，重新打包 sdk 发版新的版本，要求项目组重新升级版本进行发版，bugfix。

总结

其实后过头来看这次排查比上文展示出来的时间要久一些，当时线上的日志因为太长了并没有完整打印堆栈信息，不能直接定位到触发递归的地方。最后是在非生产环境通过比较邪道的方式stack antlr.BaseAST toStringList -n 1 才定位到具体位置。判定是日志等级导致的异常后反而一下子不知道怎么排查了，最终问了下公司之前封装过日志框架的开发才真正定位到 JBoss。

为什么没有大规模异常

这次这个异常其实是比较难触发的，公司其实对 SQL 查询这一块是有进行封装的，正常查询并不会走到hibernate的这一块逻辑，所以触发此次 bug 需要满足以下前提：

没有使用公司封装的查询方式
使用 IN 查询了大量的 key
手动配置了较小的栈空间大小

只能说维护老项目，还要给老项目升级依赖包真是头疼。。。

← Top