美文网首页程序员
获取异常信息里再出异常就找不到日志了，我TM人傻了

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

作者: Java架构奶思 | 来源:发表于2021-08-11 13:17 被阅读0次

最近组里用第三方给的 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 :

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 也就是标准异常输出。 默认情况下是不抛出的，毕竟对于同步日志没人希望因为日志有异常就让业务不能正常进行，异步日志由于前面的处理已经输出到标准异常输出这里就没必要多此一举了 。

相关文章

网友评论

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

    本文链接：https://www.haomeiwen.com/subject/cbixbltx.html

    延伸阅读

    深度阅读

    • 您也可以注册成为美文阅读网的作者，发表您的原创作品、分享您的心情！

    栏目导航

    热点阅读

    程序员

    关于我们|服务条款|联系我们|获取异常信息里再出异常就找不到日志了，我TM人傻了|投稿指南|网站地图|RSS订阅|排版工具|手机版

    提供经典美文摘抄,优美散文欣赏,现代诗歌精选,短篇小说,心情随笔,表白情书范文,故事会在线阅读欣赏

    Copyright © 2014-2023 Haomeiwen.com All Rights Reserved. 好美文阅读网 版权所有

    备案信息：桂公网安备 45052102000051号 · 桂ICP备13007215号-3

    本站所收录作品、热点评论等信息部分来源互联网，目的只是为了系统归纳学习和传递资讯

    所有作品版权归原创作者所有，与本站立场无关，如不慎侵犯了你的权益，请联系我们告知，我们将做删除处理！