本系列是 我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 的原始碼：
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：
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:
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：
