获取异常信息里再出异常就找不到日志了，我TM人傻了

最近组里用第三方给的 SDK 搞了点开发，最近线上忽然开始报错，并且 发现一个特别奇怪的问题 ，组员和我说， 代码运行到一半不走了，跳过了<typo id=”typo-72″ data-origin=”一段” ignoretag=”true”>一段</typo> （这代码是刚参与<typo id=”typo-83″ data-origin=”东奥会” ignoretag=”true”>东奥会</typo>参与跳远么？？？）。

代码如下，逻辑非常简单：

try {    log.info("initiate client with conf: {}", conf);    SDKClient client = new SDKClient(conf);    client.init();    log.info("client initiated");} catch (Exception e) {    log.error("initiate client failed", e);}log.info("start to manipulate...");

我们发现 client 实际上没有初始化成功，后面的业务解决一直在报错。查看日志，发现：

initiate client with conf: xxxxxstart to manipulate...

这就是组员说的代码发生了跳跃。由于既没有打印 client initiated ，也没有打印 initiate client failed …就直接 start to manipulate… 了。

[图片上传失败…(image-5e5fb7-1628659037883)]

老读者知道，我们的线上是 k8s + Docker，并且每个 镜像中内置了 Arthas ，并且 Java 版本是 Java 16，并且启用了 JFR。日志中具备链路信息，通过 ELK Agent 拉取到统一日志服务器。

这个 SDK 里面要访问的远程地址都有 IP 白名单，我们为了安全本地并不能直接使用 SDK 访问对方的线上环境。在本地测试连接的是对方的测试环境，是没有问题的。所以这里，我们还是得 通过 Arthas 进行定位 。

首先得看看线上运行的源码能否和本地我们看到的一致呢？这个可以通过 jad 命令：

jad 要看的类全限定名称

查看后发现，反编译后的代码，和我们的源码一致诶。

而后我们看看代码的实际执行：

trace 要看的类全限定名称 方法

之后重新执行这个方法，查看 trace 发现，初始化的时候的确抛出异常了：

# 省略我们这里不关心的    +---[min=0.010174ms,max=0.01184ms,total=0.022014ms,count=2] org.apache.logging.log4j.Logger:info() #130    +---[min=599.388978ms,max=630.23967ms,total=1229.628648ms,count=2] com.dasha13.sdk.SDKClient:<init>() #131    +---[min=203.617545ms,max=221.785512ms,total=425.403057ms,count=2] com.dasha13.sdk.SDKClient:init() #132 [throws Exception,2]    +---[min=0.034798ms,max=0.084505ms,total=0.119303ms,count=2] org.apache.logging.log4j.Logger:error() #136    +---[min=0.010174ms,max=0.01184ms,total=0.022014ms,count=2] org.apache.logging.log4j.Logger:info() #138

但是， 这个异常日志，为何没有打印出来呢 ？我们继续查看下这个异常，使用 watch 方法，并且指定查看深度为 2，这样 期望能打印出堆栈以及 Message ：

watch com.dasha13.sdk.SDKClient init {throwExp} -x 2

但是，这里 只打印了一个看似是 Message 的信息 ：

method=com.dasha13.sdk.SDKClient init location=AtExceptionExitts=2021-08-10 02:58:15; [cost=131.20209ms] result=ERROR DATA!!! object class: class java.util.ArrayList, exception class: class com.google.common.util.concurrent.UncheckedExecutionException, exception message: java.lang.IllegalArgumentException

这很奇怪，正常来说，指定深度为 2，假如有异常抛出， 那么这个输出信息，会包含异常的 Message 以及堆栈信息的 。这是怎样回事呢？我们来分别获取堆栈以及信息试试：

首先获取堆栈：

watch com.dasha13.sdk.SDKClient init {throwExp.getStackTrace()} -x 2

重新执行出问题的方法，堆栈正常输出，没啥问题，不过看堆栈应该问题和 Google 的依赖翻转 Bean 管理框架（相似于 Spring） Guice 载入某个 Bean 出异常有关：

ts=2021-08-10 03:03:37; [cost=146.644563ms] result=@ArrayList[    @StackTraceElement[][        @StackTraceElement[com.google.inject.internal.InjectorImpl$2.get(InjectorImpl.java:1025)],        @StackTraceElement[com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1051)],        @StackTraceElement[com.dasha13.sdk.SDKClient.init(SDKClient.java:482)],        # 省略之后的

再来看异常信息：

watch com.dasha13.sdk.SDKClient init {throwExp.getMessage()} -x 2

重新执行出问题的方法，这时候发现 watch 失败：

watch failed, condition is: null, express is: {throwExp.getMessage()}, com.google.common.util.concurrent.UncheckedExecutionException: java.lang.IllegalArgumentException, visit /app/arthas/arthas.log for more details.

我们按照提醒，查看 arthas 日志，发现的异常堆栈：

2021-08-10 03:07:11 [XNIO-2 task-3] ERROR c.t.a.c.command.express.OgnlExpress -Error during evaluating the expression:com.google.common.util.concurrent.UncheckedExecutionException: java.lang.IllegalArgumentException                                        at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)                                        at com.google.common.cache.LocalCache.get(LocalCache.java:3937)                                               at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)                                   at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)                                         at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)            at com.google.inject.internal.util.StackTraceElements.forMember(StackTraceElements.java:66)                             at com.google.inject.internal.Errors.formatSource(Errors.java:806)                                                  at com.google.inject.internal.Errors.formatSource(Errors.java:785)                                                       at com.google.inject.internal.Errors.formatInjectionPoint(Errors.java:839)                                                         at com.google.inject.internal.Errors.formatSource(Errors.java:800)                                   at com.google.inject.internal.Errors.formatSource(Errors.java:785)                                            at com.google.inject.internal.Errors.format(Errors.java:584)                                                    at com.google.inject.ProvisionException.getMessage(ProvisionException.java:60)       cause by: MethodNotFoundException: Method not found: class com.google.common.xxxxxxxxx

我们发现，居然是 ProvisionException 的 getMessage() 发生了异常，也就是 异常的 getMessage() 发生了异常 .查看 异常的 Cause 我们也定位出来，是 Guava 版本与 guice 版本不兼容导致 ，其根本起因是三方接口超时，导致初始化异常，有异常抛出被封装成 ProvisionException ， ProvisionException 异常的 getMessage 依赖 Guava Cache 缓存少量异常信息，但是我们项目中 Guava 版本与 guice 版本不兼容，导致某些方法不存在，所以 ProvisionException 异常的 getMessage 也会有异常。 之前运行没问题是由于三方没有还没有过初始化的时候接口超时抛异常 。。。

[图片上传失败…(image-b1e869-1628659037882)]

我们使用的 log4j2 异步日志配置，并且将异常作为最后一个参数传入日志方法中，正常情况下，会输出这个 异常的 Message 以及异常堆栈 .但从上面的分析我们知道，获取 Message 的时候，抛出了异常。Log4j 的设计是使用了 日志事件的生产消费 这种架构。这里是消费者获取异常的 Message 以及异常堆栈，并且在获取 Message 的时候，发现有异常。对于 Log4j2 异步日志，发现有异常的时候，原有日志事件会被直接抛弃，并将异常输出到 StatusLogger 中（ 底层其实就是标准异常输出 ）中，这里对应 log4j 的源码：

AppenderControl

private void tryCallAppender(final LogEvent event) {    try {        //调用 appender 输出日志        appender.append(event);    } catch (final RuntimeException error) {        //解决 RuntimeException        handleAppenderError(event, error);    } catch (final Exception error) {        //解决其余 Exception        handleAppenderError(event, new AppenderLoggingException(error));    }}private void handleAppenderError(final LogEvent event, final RuntimeException ex) {    appender.getHandler().error(createErrorMsg("An exception occurred processing Appender "), event, ex);    if (!appender.ignoreExceptions()) {        throw ex;    }}

ErrorHandler 一般都是默认实现，即 DefaultErrorHandler；DefaultErrorHandler 是输出到一个 StatusLogger：

DefaultErrorHandler

private static final Logger LOGGER = StatusLogger.getLogger();public void error(final String msg, final LogEvent event, final Throwable t) {    final long current = System.nanoTime();    if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) {        LOGGER.error(msg, t);    }    lastException = current;    if (!appender.ignoreExceptions() && t != null && !(t instanceof AppenderLoggingException)) {        throw new AppenderLoggingException(msg, t);    }}

StatusLogger 其实就是标准异常输出 System.err :

StatusLogger

this.logger = new SimpleLogger("StatusLogger", Level.ERROR, false, true, showDateTime, false,                dateFormat, messageFactory, PROPS,                 //标准异常输出                System.err);

我们部署架构中，将标准异常输出放到了一个很偏远的位置，基本没有人看，所以没注意到。。。查看标准异常输出，会发现确实有异常：

2021-08-10 03:30:29,810 Log4j2-TF-10-AsyncLoggerConfig-3 ERROR An exception occurred processing Appender file com.google.common.util.concurrent.UncheckedExecutionException: java.lang.IllegalArgumentException    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)    at com.google.common.cache.LocalCache.get(LocalCache.java:3937)    at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)    at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)    at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)    at com.google.inject.internal.util.StackTraceElements.forMember(StackTraceElements.java:66)    at com.google.inject.internal.Errors.formatSource(Errors.java:806)    at com.google.inject.internal.Errors.formatSource(Errors.java:785)    at com.google.inject.internal.Errors.formatInjectionPoint(Errors.java:839)    at com.google.inject.internal.Errors.formatSource(Errors.java:800)    at com.google.inject.internal.Errors.formatSource(Errors.java:785)    at com.google.inject.internal.Errors.format(Errors.java:584)    at com.google.inject.ProvisionException.getMessage(ProvisionException.java:60)    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:105)    at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:93)    at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629)    at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:63)    at org.springframework.boot.logging.log4j2.ExtendedWhitespaceThrowablePatternConverter.format(ExtendedWhitespaceThrowablePatternConverter.java:50)    at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)    at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:345)    at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:244)    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:229)    at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:59)    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197)    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)    at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:312)    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)    at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:127)    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)    at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121)    at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncLoggerConfigsOnCurrentThread(AsyncLoggerConfig.java:169)    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:111)    at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:97)    at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)    at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)    at java.base/java.lang.Thread.run(Thread.java:834)Caused by: java.lang.IllegalArgumentException    at com.google.inject.internal.asm.$ClassReader.<init>(Unknown Source)    at com.google.inject.internal.asm.$ClassReader.<init>(Unknown Source)    at com.google.inject.internal.asm.$ClassReader.<init>(Unknown Source)    at com.google.inject.internal.util.LineNumbers.<init>(LineNumbers.java:65)    at com.google.inject.internal.util.StackTraceElements$1.load(StackTraceElements.java:46)    at com.google.inject.internal.util.StackTraceElements$1.load(StackTraceElements.java:43)    at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3527)    at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2319)    at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2282)    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2197)    ... 41 more

并且，在这之后，会根据 Appender 的 ignoreExceptions 配置（默认都是 true），决定调用日志方法的地方能否会抛出异常，但这个是 针对同步日志的 ，异步日志即将异常抛到 Disruptor 的异常解决器，Log4j2 Disruptor 的异常解决也是将异常输出到 System.err 也就是标准异常输出。 默认情况下是不抛出的，毕竟对于同步日志没人希望由于日志有异常就让业务不能正常进行，异步日志因为前面的解决已经输出到标准异常输出这里就没必要多此一举了 。