性能文章>获取异常信息里再出异常就找不到日志了,我人傻了>

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

10月前
231107

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

使用Arthas定位

老读者知道,我们的线上是 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 版本不兼容导致,其根本原因是三方接口超时,导致初始化异常,有异常抛出被封装成 ProvisionExceptionProvisionException 异常的 getMessage 依赖 Guava Cache 缓存一些异常信息,但是我们项目中 Guava 版本与 guice 版本不兼容,导致某些方法不存在,所以 ProvisionException 异常的 getMessage 也会有异常。之前运行没问题是因为三方没有还没有过初始化的时候接口超时抛异常。。。

为何log4j没有打印日志

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

微信搜索“我的编程喵”关注公众号,每日一刷,轻松提升技术,斩获各种offer

请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意
Java多线程——并发测试
编写并发程序时候,可以采取和串行程序相同的编程方式。唯一的难点在于,并发程序存在不确定性,这种不确定性会令程序出错的地方远比串行程序多,出现的方式也没有固定规则。那么如何在测试中,尽可能的暴露出这些问
Java多线程知识小抄集(一)
本文主要整理笔者遇到的Java多线程的相关知识点,适合速记,故命名为“小抄集”。本文没有特别重点,每一项针对一个多线程知识做一个概要性总结,也有一些会带一点例子,习题方便理解和记忆。 1.interr