HeapDump性能社区

性能工具
登录注册
性能文章>获取异常信息里再出异常就找不到日志了，我人傻了>

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

张哈希
3年前
414629

最近组里用第三方给的 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 版本不兼容导致，其根本原因是三方接口超时，导致初始化异常，有异常抛出被封装成 ProvisionException， ProvisionException 异常的 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

点赞收藏
张哈希
请先登录，查看2条精彩评论吧
快去登录吧，你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流，共同进步

为你推荐

随机一门技术分享之Netty

随机一门技术分享之Netty

java
netty
源码
MappedByteBuffer VS FileChannel：从内核层面对比两者的性能差异

MappedByteBuffer VS FileChannel：从内核层面对比两者的性能差异

jvm
java
jdk
9
2
Lv4
张哈希

徽章

推荐阅读

随机一门技术分享之NettyMappedByteBuffer VS FileChannel：从内核层面对比两者的性能差异JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析浅析AbstractQueuedSynchronizer日常Bug排查-集群逐步失去响应为什么要做代码Review？
站内搜索
Linux
SpringBoot
锁
字节码
火焰图
故障排查
java
jvm
gc
linux
内存泄漏
内核

专题推荐

对于刚刚接触 JVM 的同学来说，JVM 就像一个黑盒一样，完全不知道这是一个什么东西。所以对于小白来说，最重要是搞清楚 JVM 到底是干嘛的，以及其常用的知识框架。针对这样的需求，才有了这个专题，从零开始循序渐进地介绍了 JVM，相信是很不错的 JVM 入门教程。
15篇文章36486阅读量
通过阅读 Redis 源码，可以学习和掌握到的计算机系统设计思想，redis 涉及的知识点有很多，本期专题我们由浅入深，简洁的给大家剖析Redis源码。
15篇文章26159阅读量

本月精选性能专题

本月精选线上案例

本月精选原创好文

HeapDump

有性能问题，上HeapDump性能社区

Copyright © 2019-2024 heapdump.cn 版权所有 浙ICP备17054444号

联系我们

HeapDump性能社区

网媒渠道

堆堆酱

扫码加堆堆酱好友

友情链接

PerfMa官网SegmentFault思否TesterHomeXPocket开源社区DCloud 问答社区稀土掘金博客园W3CTech