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

干货满满张哈希
• 阅读 1299

本系列是 我TM人傻了 系列第三期[捂脸],往期精彩回顾:

获取异常信息里再出异常就找不到日志了,我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... 了。

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

老读者知道,我们的线上是 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 也会有异常。之前运行没问题是因为三方没有还没有过初始化的时候接口超时抛异常。。。

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

我们使用的 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

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

点赞
收藏
评论区
推荐文章
技术小男生 技术小男生
4个月前
linux环境jdk环境变量配置
1:编辑系统配置文件vi/etc/profile2:按字母键i进入编辑模式,在最底部添加内容:JAVAHOME/opt/jdk1.8.0152CLASSPATH.:$JAVAHOME/lib/dt.jar:$JAVAHOME/lib/tools.jarPATH$JAVAHOME/bin:$PATH3:生效配置
光头强的博客 光头强的博客
4个月前
Java面向对象试题
1、请创建一个Animal动物类,要求有方法eat()方法,方法输出一条语句“吃东西”。创建一个接口A,接口里有一个抽象方法fly()。创建一个Bird类继承Animal类并实现接口A里的方法输出一条有语句“鸟儿飞翔”,重写eat()方法输出一条语句“鸟儿吃虫”。在Test类中向上转型创建b对象,调用eat方法。然后向下转型调用eat()方
刚刚好 刚刚好
4个月前
css问题
1、在IOS中图片不显示(给图片加了圆角或者img没有父级)<div<imgsrc""/</divdiv{width:20px;height:20px;borderradius:20px;overflow:h
blmius blmius
1年前
MySQL:[Err] 1292 - Incorrect datetime value: ‘0000-00-00 00:00:00‘ for column ‘CREATE_TIME‘ at row 1
文章目录问题用navicat导入数据时,报错:原因这是因为当前的MySQL不支持datetime为0的情况。解决修改sql\mode:sql\mode:SQLMode定义了MySQL应支持的SQL语法、数据校验等,这样可以更容易地在不同的环境中使用MySQL。全局s
小森森 小森森
4个月前
校园表白墙微信小程序V1.0 SayLove -基于微信云开发-一键快速搭建,开箱即用
后续会继续更新,敬请期待2.0全新版本欢迎添加左边的微信一起探讨!项目地址:(https://www.aliyun.com/activity/daily/bestoffer?userCodesskuuw5n)\2.Bug修复更新日历2.情侣脸功能大家不要使用了,现在阿里云的接口已经要收费了(土豪请随意),\\和注意
晴空闲云 晴空闲云
4个月前
css中box-sizing解放盒子实际宽高计算
我们知道传统的盒子模型,如果增加内边距padding和边框border,那么会撑大整个盒子,造成盒子的宽度不好计算,在实务中特别不方便。boxsizing可以设置盒模型的方式,可以很好的设置固定宽高的盒模型。盒子宽高计算假如我们设置如下盒子:宽度和高度均为200px,那么这会这个盒子实际的宽高就都是200px。但是当我们设置这个盒子的边框和内间距的时候,那
艾木酱 艾木酱
3个月前
快速入门|使用MemFire Cloud构建React Native应用程序
MemFireCloud是一款提供云数据库,用户可以创建云数据库,并对数据库进行管理,还可以对数据库进行备份操作。它还提供后端即服务,用户可以在1分钟内新建一个应用,使用自动生成的API和SDK,访问云数据库、对象存储、用户认证与授权等功能,可专
NVIDIA安培架构下MIG技术分析
关键词:NVIDIA、MIG、安培一什么是MIG2020年5月,NVIDIA发布了最新的GPU架构:安培,以及基于安培架构的最新的GPU:A100。安培提供了许多新的特性,MIG是其中一项非常重要的新特性。MIG的全名是MultiInstanceGPU。NVIDIA安培架构中的MIG模式可以在A100GPU上并行运行七个作业。多实
helloworld_28799839 helloworld_28799839
4个月前
常用知识整理
Javascript判断对象是否为空jsObject.keys(myObject).length0经常使用的三元运算我们经常遇到处理表格列状态字段如status的时候可以用到vue
密钥管理系统-为你的天翼云资产上把“锁
本文关键词:数据安全,密码机,密钥管理一、你的云上资产真的安全么?1.2021年1月,巴西的一个数据库30TB数据被破坏,泄露的数据包含有1.04亿辆汽车和约4000万家公司的详细信息,受影响的人员数量可能有2.2亿;2.2021年2月,广受欢迎的音频聊天室应用Clubhouse的用户数据被恶意黑客或间谍窃取。据悉,一位身份不明的用户能够将Clubho