Skip to content

出了错,日志里却没有可用的信息 ​

线上报警:下单失败。打开日志,对应的时间点只有一行 java.lang.NullPointerException,没有消息,没有调用栈。往前翻一个小时,同样的异常是带着完整调用栈的。代码没有发版,日志配置也没有改。

排查线上问题时,手里通常只有日志。一个异常从抛出到被记录,中间经过 finally、catch、线程池、异步回调,每一处都可能丢掉一部分信息,或者把整个异常丢掉。正常路径会被测试反复执行,这些出错路径上的代码很少被执行,问题只有在真的出错时才暴露,而那正是最需要信息的时候。

本文把几种常见的丢失方式各跑了一遍。实验见文末。

写法类型消息调用栈实际看到的try-with-resources;重新抛出时带上原因保留保留保留关闭的异常在 suppressed 里new RuntimeException(e.getMessage())丢失保留丢失getCause() 是 nullstatic final 的异常对象反复抛出保留保留指向别处第一帧是 <clinit>热点代码里反复出现的空指针异常保留丢失丢失只有一行类名手写 finally 关闭,关闭也失败丢失丢失丢失只看到关闭的异常finally 里写了 return丢失丢失丢失方法正常返回submit 提交的任务,没有人 get丢失丢失丢失没有任何输出scheduleAtFixedRate 的任务抛异常丢失丢失丢失之后不再执行排查线上问题时手里只有日志:出错路径上每丢一样,定位就多一轮「加日志、发版、等复现」前六行靠写法就能保住;最后两行要靠约定:任务体自己捕获并记录,或者一定有人取结果
图 1 · 实测:一个异常带着三样东西:类型、消息、调用栈(以及原因链)。从抛出的地方到日志或调用方,中间每一种写法各丢掉其中一部分。最后三行是整个异常都没有到达任何人:调用方把它当成了成功,或者根本没有人去取。

一、finally 里的 return ​

java
static int finallyOverridesReturn() { try { return 1; } finally { return 2; } }
static int finallySwallows() { try { throw new IllegalStateException("扣款失败"); } finally { return -1; } }
text
try { return 1; } finally { return 2; } 返回 2
try { throw …; } finally { return -1; }:方法正常返回 -1,调用方看不到异常

finally 块以 return 结束时,try 里正在传播的东西被丢弃,不论那是一个返回值还是一个异常。第二个方法里「扣款失败」的异常彻底消失了,调用方拿到 -1,按成功处理。finally 里的 break、continue 有同样的效果。

text
javac 默认参数:没有任何提示
javac -Xlint:finally:WARNING finally clause cannot complete normally

编译器能发现这种写法,但默认不提示。构建脚本里打开 -Xlint:finally(或 -Xlint:all),并让警告导致构建失败。

二、关闭失败盖住了原来的异常 ​

一段写入数据的代码,写入失败了,随后关闭连接也失败了。手写 finally:

java
Res r = new Res("连接");
try { throw new IllegalStateException("写入失败"); } finally { r.close(); }
text
手写 finally 关闭:调用方收到 IOException(关闭连接失败),被压住的异常 0 个,原来的「写入失败」不见了

finally 里抛出的异常取代了 try 里的。日志里记录的是「关闭连接失败」,真正的原因是写入失败,而关闭失败往往只是它的后果(连接已经断了,关闭当然也失败)。排查的人顺着关闭失败去查,方向就错了。

try-with-resources 的处理不同:

text
try-with-resources:调用方收到 IllegalStateException(写入失败),getSuppressed() = [IOException(关闭连接失败)]

主体的异常是主异常,关闭时的异常挂在它的 getSuppressed() 里,两个都没有丢。日志框架打印调用栈时会把 suppressed 的部分一起打出来。

资源不止一个时,手写的版本还容易漏关:

text
三个资源、第三个打开失败:打开A → 打开B → 关闭B → 关闭A;收到 IOException(打开C失败)
手写:两个资源先都打开再进 try,第二个打开失败:打开A(A 没有被关闭)

try-with-resources 按相反的顺序关闭已经打开的资源,中途打开失败也一样。凡是实现了 AutoCloseable 的资源都用它。

三、换一个异常抛出去 ​

java
catch (Exception e) { throw new RuntimeException("下单失败:" + e.getMessage()); }
text
throw new RuntimeException("…" + e.getMessage()):getCause() = null,调用栈第一帧在 main,找不到 originate
throw new RuntimeException("…", e):getCause() = IllegalStateException(库存服务返回 503),原因的第一帧在 originate

只把消息拼进新异常,原异常的类型和调用栈都丢了。新异常的调用栈指向 catch 块所在的位置,那不是出错的地方。把原异常作为第二个参数传进去,原因链才是完整的。

e.getMessage() 本身也不可靠:

text
"失败:" + e.getMessage() 遇到没有消息的异常 = 失败:null;"失败:" + e = 失败:java.lang.IllegalStateException

很多异常没有消息。日志里一行 失败:null,连异常的类型都不知道。记录日志时把异常对象整个交给日志框架(log.error("下单失败, orderId={}", id, e)),不要自己取消息拼字符串。

空指针异常的消息是另一种情况。JDK 15 起它默认会指出是哪个变量、哪次调用为空:

text
空指针异常的消息:Cannot invoke "Object.toString()" because "<local3>" is null

这里显示 <local3> 而不是变量名,是因为实验以源码方式运行,编译时没有带调试信息。Maven 和 Gradle 默认带 -g 编译,会显示变量名;自定义的构建如果关掉了调试信息,这条消息的价值就少了一半。

四、调用栈不对,或者没有 ​

复用的异常对象 ​

为了省掉创建异常的开销,有的代码把异常做成常量:

java
static final RuntimeException SHARED = new RuntimeException("余额不足");
static void pay() { throw SHARED; }
static void refund() { throw SHARED; }
text
static final 的异常对象从 pay() 抛出时第一帧是 <clinit>,从 refund() 抛出时第一帧是 <clinit>

调用栈是在异常创建时记录的,不是抛出时。这个常量在类初始化时创建,之后不管从哪里抛出,调用栈都指向类初始化。日志里看到的位置与出错的位置毫无关系。

确实不需要调用栈的场景(用异常做控制流、高频的业务校验失败),应该明确地关掉它,让调用栈是空的而不是错的:

text
关掉调用栈的异常(writableStackTrace = false):getStackTrace().length = 0

热点代码里被省掉调用栈的异常 ​

开头的现象来自 JVM 的一项优化。同一处代码反复抛出隐式异常(空指针、数组越界、除零、类型转换失败、数组存储类型不符)时,JIT 编译后的代码不再每次创建新的异常对象,而是抛出一个预先分配好的、没有调用栈的实例:

text
默认参数:20 万次里出现了调用栈为空的异常,消息 = null,后面的异常与它是同一个对象 = true
-XX:-OmitStackTraceInFastThrow:20 万次里每一次都带调用栈

所以刚开始出错时日志里有完整的调用栈,同一个位置错得多了,就只剩一行类名。这通常发生在最糟糕的时候:某个错误正在大量出现。

默认参数:日志随时间的变化NullPointerExceptionCannot invoke … · 完整调用栈NullPointerExceptionCannot invoke … · 完整调用栈热点代码被 JIT 编译java.lang.NullPointerException消息 null · 无调用栈java.lang.NullPointerException同一个对象排查方法往前翻最早的几次日志保留要覆盖到-XX:-OmitStackTraceInFastThrowNullPointerException完整调用栈NullPointerException完整调用栈…20 万次每次都有代价:高频异常路径多一些 CPU
图 2 · 实测:同一处代码循环 20 万次抛出空指针。刚开始每个异常都带消息和调用栈;这段代码被 JIT 编译之后,抛出的是预先分配好的同一个对象,消息为 null、调用栈为空。加上 -XX:-OmitStackTraceInFastThrow 后每一次都带调用栈。只影响 JVM 自己抛出的几种隐式异常,代码里 new 出来的不受影响

应对方式有两种:

  • 往前翻日志,找这个异常最早出现的那几次,那时还有调用栈。日志保留的时间和滚动策略要能覆盖。
  • 启动参数加 -XX:-OmitStackTraceInFastThrow,关闭这项优化。代价是高频异常路径上每次都要填充调用栈,对已经在大量抛异常的服务会增加一些 CPU 开销;多数服务可以接受。

这项优化只影响 JVM 自己抛出的那几种异常,代码里 new 出来的不受影响。

五、异常没有到达任何人 ​

线程池 ​

java
Future<?> f = pool.submit(() -> { throw new IllegalStateException("对账失败"); });
pool.execute(() -> { throw new IllegalStateException("推送失败"); });
text
submit 与 execute 各提交一个抛异常的任务,未捕获异常处理器收到:[IllegalStateException(推送失败)]
submit 的异常只在 Future.get() 时出现:IllegalStateException(对账失败);没有人调用 get 就没有任何输出

execute 提交的任务抛出异常,会走到线程的未捕获异常处理器,默认把调用栈打印到标准错误。submit 提交的任务,异常被存进了返回的 Future,只有调用 get() 时才会抛出来。提交之后把 Future 丢在一边的写法很常见,那个任务失败与否就没有人知道了。

周期任务更隐蔽:

text
scheduleAtFixedRate 每 20 ms 一次,第 3 次抛异常:又过了 400 ms 后一共执行了 3 次;isDone = true;未捕获异常处理器收到的仍是 1 条

周期任务的某一次执行抛了异常,后续的执行全部取消,没有任何输出。一个每分钟同步一次数据的定时任务,某次遇到空指针之后就再也不运行了,进程还活着,线程池还在,监控上只是「数据不更新了」。

交给线程池的任务体,最外层自己 try/catch 并记录:

java
ses.scheduleAtFixedRate(() -> {
    try { sync(); } catch (Exception e) { log.error("sync failed", e); }
}, 0, 1, TimeUnit.MINUTES);

CompletableFuture ​

text
没有任何后续处理的失败任务:isCompletedExceptionally = true,标准错误与未捕获异常处理器都没有输出

与 submit 一样,异常留在 future 里。异步链的末尾要有一个处理异常的阶段(whenComplete、exceptionally、handle),或者有人 join。

处理异常时还有一个容易写错的地方:拿到的异常类型取决于它是怎么来的。

text
completeExceptionally(ISE) 之后 exceptionally 收到 IllegalStateException
supplyAsync 里抛 ISE,exceptionally 收到 CompletionException,原因是 IllegalStateException
completeExceptionally(ISE) 之后再 thenApply,下一级的 exceptionally 收到 CompletionException
join() 抛 CompletionException,原因 IllegalStateException(超时)
get() 抛 ExecutionException,原因 IllegalStateException(超时)

任务体里抛出的异常、经过一级传递的异常,都被包了一层 CompletionException。exceptionally(e -> e instanceof TimeoutException ? … : …) 这样的判断,在单测里用 completeExceptionally 直接构造时是对的,换成真实的异步任务就走进了另一个分支。判断类型之前先解开:

java
Throwable cause = (e instanceof CompletionException && e.getCause() != null) ? e.getCause() : e;

中断被吞掉之后任务停不下来的问题,见超时了、取消了,任务其实还在跑。

六、出错路径上没释放的锁 ​

java
lock.lock();
process();          // 抛了异常
lock.unlock();      // 没有执行
text
lock(); 处理; unlock(); 处理中途抛异常,线程已经结束:isLocked = true,另一个线程 tryLock(200 ms) = false

持有锁的线程已经结束了,锁还显示被占着,之后所有要这把锁的线程都会一直等。synchronized 在异常退出时由 JVM 释放,显式锁必须写成:

java
lock.lock();
try { process(); } finally { lock.unlock(); }

信号量的许可、连接池里借出的连接、限流器的令牌、分布式锁,凡是「拿了要还」的东西都一样。这类问题在正常路径上测不出来,表现是服务运行一段时间后某个功能卡死,重启就好。归还的归属问题见信号量有 2 个许可,两个线程却拿到了同一个连接。

七、检查清单 ​

  • finally 里不写 return、break、continue;编译时打开 -Xlint:finally。
  • 资源用 try-with-resources 关闭。
  • 重新抛出时把原异常作为 cause 传入;记录日志时传异常对象,不传 getMessage()。
  • 不复用异常对象;不需要调用栈时显式关掉。
  • 评估是否加 -XX:-OmitStackTraceInFastThrow;至少知道「只有一行类名」是怎么来的。
  • 交给线程池、定时器的任务体自己捕获并记录异常;submit 返回的 Future 要么有人取,要么改用 execute。
  • 异步链的末尾有异常处理;判断异常类型前先解开 CompletionException。
  • 锁、许可、连接在 finally 里归还。
  • 出错路径有测试:让依赖抛异常,断言调用方看到的异常类型、原因链,以及资源被释放。

异常完整地交给日志框架之后,日志本身还可能在异步队列里丢掉,见出事的那几秒,日志恰好是空的。

Python 里对应的一组问题,见 python -O 之后,参数校验全没了。


配套实验

  • codesphere-labs/java/java-failure-paths:JDK 25.0.4.1 上的确定性实验:finally 里的 return、关闭失败与 suppressed、换异常重抛、复用的异常对象、默认参数与 -XX:-OmitStackTraceInFastThrow 下的隐式异常、线程池与周期任务、CompletableFuture 的异常包装、没释放的锁(验证记录)

参考资料

文章以 CC BY-NC-SA 4.0 授权 · 代码片段以 MIT 授权