Это мой 11-й день августовского испытания обновлений.
Эта серияя тупойТретий выпуск серии [закрой лицо], замечательный обзор предыдущих выпусков:
Недавно группа провела некоторые разработки с помощью 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...");
Мы обнаружили, что клиент не был успешно инициализирован, и последующая бизнес-обработка продолжала сообщать об ошибках. Просматривая логи, я обнаружил:
initiate client with conf: xxxxx
start to manipulate...
Это код, который, по словам членов команды, перескочил. потому что ни печататьclient initiated, тоже не печаталinitiate client failed... просто прямоstart to manipulate....
Постоянные читатели знают, что наша линейка — это k8s + Docker, и каждыйАртас встроен в образ, а версия Java — Java 16, и JFR включен. Журнал содержит информацию о ссылках, которые передаются на единый сервер журналов через агент ELK.
У удаленных адресов, к которым должен быть доступ в этом SDK, есть белые списки IP-адресов, Мы не можем напрямую использовать SDK для доступа к онлайн-среде другой стороны для локальной безопасности. Локальное тестовое соединение — это тестовая среда другой стороны, и здесь нет проблем. Так что здесь нам еще предстоитПрицеливание с Артасом.
Прежде всего, мы должны увидеть, соответствует ли исходный код, работающий онлайн, тому, что мы видим локально? Это можно сделать с помощью команды jad:
jad 要看的类全限定名称
После проверки я обнаружил, что декомпилированный код согласуется с нашим исходным кодом.
Затем мы смотрим на фактическое выполнение кода:
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, чтобыОжидайте распечатать стек и сообщение:
watch com.dasha13.sdk.SDKClient init {throwExp} -x 2
Однако здесьПечатается только сообщение, похожее на сообщение.:
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, если выбрасывается исключение,Затем эта выходная информация будет содержать сообщение об исключении и информацию о стеке.. Что тут происходит? Попробуем получить стек и информацию отдельно:
Сначала получите стек:
watch com.dasha13.sdk.SDKClient init {throwExp.getStackTrace()} -x 2
Повторно выполните проблемный метод, вывод стека в норме, проблем нет, но проблема должна быть в стеке, а структура управления перевернутыми компонентами зависимостей Google (аналогичная Spring) Guice загружает компонент и возникает исключение:
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 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
Мы обнаружили, что на самом деле это ProvisionExceptiongetMessage()Произошло исключение, т.аномальныйgetMessage()Произошло исключение.ПроверитьМы также обнаружили ненормальную причину, вызванную несовместимостью между версией Guava и версией guice., основной причиной является истечение времени ожидания стороннего интерфейса, что приводит к исключению инициализации, а созданное исключение инкапсулируется какProvisionException,ProvisionExceptionаномальныйgetMessageИспользование Guava Cache для кэширования некоторой информации об исключениях, но версия Guava в нашем проекте несовместима с версией guice, поэтому некоторые методы не существуют, поэтомуProvisionExceptionаномальныйgetMessageБудут и исключения.С предыдущей операцией проблем не было, потому что время ожидания интерфейса истекло, и возникло исключение, когда три стороны не были инициализированы.. . .
Конфигурация асинхронного журнала log4j2, которую мы используем, и исключение передается в качестве последнего параметра в метод журнала. При нормальных обстоятельствах это будет выводитьсяСообщение об исключении и стек исключений.Но из приведенного выше анализа мы знаем, что при получении сообщения было выдано исключение. Log4j предназначен для использованияСоздание и потребление событий журналаэта архитектура. Вот сообщение и стек исключений о том, что потребитель получает исключение, и при получении сообщения обнаруживается исключение. Для асинхронного журнала 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
И, после этого, согласно конфигурации ignoreExceptions аппендера (по умолчанию true), определяется, будет ли выброшено исключение там, где вызывается метод журнала, но этодля журналов синхронизации, асинхронный журнал выдаст исключение обработчику исключений Disruptor, а обработка исключений Log4j2 Disruptor также выведет исключение вSystem.errТо есть стандартный вывод исключения.По умолчанию не выбрасывается.Ведь никто не надеется, что дело не может вестись нормально из-за исключений в синхронном логе.Поскольку предыдущая обработка была выведена в стандартный вывод исключений, больше ничего делать не надо ..
Ищите «My Programming Meow» в WeChat, подписывайтесь на официальный аккаунт, чистите каждый день, легко улучшайте свои технологии и получайте различные предложения.