獲取異常資訊裡再出異常就找不到日誌了，我TM人傻了

乾貨滿滿張雜湊發表於2021-08-11

本系列是 我TM人傻了 系列第三期[捂臉]，往期精彩回顧：

升級到Spring 5.3.x之後，GC次數急劇增加，我TM人傻了

這個大表走索引欄位查詢的 SQL 怎麼就成全掃描了，我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... 了。

老讀者知道，我們的線上是 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 也會有異常。之前執行沒問題是因為三方沒有還沒有過初始化的時候介面超時拋異常。。。

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

JAVA異常和日誌
2020-12-11
Java
iOS 日誌重定向和異常捕獲
2017-04-25
iOS
儲存過程——異常捕獲&列印異常資訊
2020-05-13
儲存過程
JVM 輸出 GC 日誌導致 JVM 卡住，我 TM 人傻了
2022-06-17
JVMGC
Android-獲取app包資訊異常
2015-03-06
AndroidAPP
Flutter異常捕獲和Crash崩潰日誌收集
2019-09-11
Flutter
Java-異常、斷言和日誌
2018-08-14
Java
日誌異常，IO,CPU的檢查
2011-07-29
獲取input框輸入值異常
2021-03-24
捕獲 React 異常
2020-01-14
React
iOS異常捕獲
2016-09-11
iOS
前端異常日誌監控 – 使用Sentry
2018-09-12
前端
Spring Cloud Gateway 沒有鏈路資訊，我 TM 人傻了（上）
2021-09-24
SpringCloudGateway
在日誌中記錄Java異常資訊的正確姿勢
2019-06-20
Java
CircuitBreaker斷路器Fallback如何獲取異常
2021-08-16
UI
PLSQL獲取異常堆疊資訊-dbms_utility.format_error_backtrace
2014-02-25
SQLORMError
我已經受夠了“系統異常”！
2023-02-14
python異常捕獲
2023-03-06
Python
Linux 日誌異常tpvmlpd[4966]: device type not supported
2012-11-25
Linuxdev
異常篇——異常處理
2022-02-27
商城系統日誌與異常資訊追蹤機制設計_OctShop
2023-05-10
資料庫日誌中一條"異常"資訊所包含的細節
2015-08-04
資料庫
Java 異常（二）自定義異常
2020-06-04
Java
Java checked異常和unchecked異常。
2016-06-14
Java
異常處理機制(二)之異常處理與捕獲
2023-11-14
Auto.js Pro 資料獲取與異常捕獲
2020-12-01
JS
win10 異常關機檢視方法 win10 異常關機日誌怎麼看
2020-10-24
Win10
Java核心技術筆記異常、斷言和日誌
2019-01-19
Java筆記
異常-編譯期異常和執行期異常的區別
2018-09-02
編譯
異常錯誤資訊處理
2019-12-16
android 異常捕獲-UncaughtExceptionHandler
2019-02-20
AndroidException
記錄Javascript 異常捕獲
2019-04-18
JavaScript
PHP使用trycatch,捕獲異常
2017-08-09
PHP
【筆記】forall 異常捕獲
2009-03-31
筆記
前端異常捕獲與上報
2016-03-22
前端
PLSQL宣告部分異常捕獲
2012-09-18
SQL
異常-throws的方式處理異常
2018-09-02
異常處理與異常函式
2016-11-12
函式

獲取異常資訊裡再出異常就找不到日誌了，我TM人傻了

相關文章