本系列是 我TM人傻了 系列第三期[捂脸]，往期精彩回顾： 升级到Spring 5.3.x之后，GC次数急剧增加，我TM人傻了 这个大表走索引字段查询的 SQL 怎么就成全扫描了，我TM人傻了
最近组里用第三方给的 SDK 搞了点开发，最近线上突然开始报错，并且发现一个特别奇怪的问题，组员和我说，代码运行到一半不走了，跳过了一段（这代码是刚参加东奥会参加跳远么？？？）。
代码如下，逻辑非常简单：
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: xxxxx start to manipulate...
这就是组员说的代码发生了跳跃。因为既没有打印 client initiated，也没有打印 initiate client failed...就直接 start to manipulate... 了。
老读者知道，我们的线上是 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=AtExceptionExit ts=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 也会有异常。之前运行没问题是因为三方没有还没有过初始化的时候接口超时抛异常。。。
我们使用的 log4j2 异步日志配置，并且将异常作为最后一个参数传入日志方法中，正常情况下，会输出这个异常的 Message 以及异常堆栈.但从上面的分析我们知道，获取 Message 的时候，抛出了异常。Log4j 的设计是使用了日志事件的生产消费这种架构。这里是消费者获取异常的 Message 以及异常堆栈，并且在获取 Message 的时候，发现有异常。对于 Log4j2 异步日志，发现有异常的时候，原有日志事件会被直接抛弃，并将异常输出到 StatusLogger 中（底层其实就是标准异常输出）中，这里对应 log4j 的源码：
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：
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:
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 也就是标准异常输出。默认情况下是不抛出的，毕竟对于同步日志没人希望因为日志有异常就让业务不能正常进行，异步日志由于前面的处理已经输出到标准异常输出这里就没必要多此一举了。
