色www永久免费视频首页在线,黄色在线观看免费,亚洲视频在线播放

最近組里用第三方給的 SDK 搞了點開發，最近線上突然開始報錯，并且發現一個特別奇怪的問題，組員和我說，代碼運行到一半不走了，跳過了一段（這代碼是剛參加東奧會參加跳遠么？？？）。

loggerinfo日志沒出來

代碼如下，邏輯非常簡單：

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 也就是標準異常輸出。默認情況下是不拋出的，畢竟對于同步日志沒人希望因為日志有異常就讓業務不能正常進行，異步日志由于前面的處理已經輸出到標準異常輸出這里就沒必要多此一舉了。

版權聲明溫馨提示本站文章有人工和AI兩種，AI文章均有【創業號AI智能】通過 AI 工具匹配關鍵字智能整合而成，僅供參考，專在家創業網不對內容的真實、準確、完整作任何形式的承諾。

1本文內容以及圖片均由互聯網用戶自發貢獻，該文觀點僅代表作者本人行為。作者內容不構成任何投資建議，網友創業投資需謹慎！
2專在家創業網僅提供信息存儲空間服務，不擁有所有權，不承擔相關法律責任。如發現本站有涉嫌抄襲侵權/違法違規的內容，請發送郵件至1461314457@qq.com 舉報，一經查實，本站將立刻刪除。

THE END