code学习

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

获取异常信息里再出异常就找不到日志了,我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: xxxxx
start 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=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 也会有异常。 之前运行没问题是因为三方没有还没有过初始化的时候接口超时抛异常 。。。

[图片上传失败...(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 :

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