Этот код воспроизводит то, что я думаю, является ошибкой Log4j2. Это простой цикл, который регистрирует 2000 сообщений с двумя добавками: консольный appender и загружаемый файл appender, который перекатывает файл каждые 5Kb. Этот предел намеренно невелик, чтобы воспроизвести то, что я считаю ошибкой.Почему приложение Log4j2 RollingFile не позволяет автономному приложению заканчиваться на 60 секунд?
Вот код.
package bug;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class Example {
private static final Logger logger = LogManager.getLogger(Example.class);
public static void main(String[] args) throws InterruptedException {
for(int i = 0; i<2000; i++){
logger.info("This is log message #{}.", i);
Thread.sleep(0);
}
}
}
Это log4j2.xml файл конфигурации.
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE">
<Appenders>
<Console name="stdout" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} %p %m%n"/>
</Console>
<RollingFile name="roll-by-size"
fileName="target/log4j2/roll-by-size/app.log"
filePattern="target/log4j2/roll-by-size/app.%i.log.gz"
ignoreExceptions="false"
append="false">
<PatternLayout>
<Pattern>%d{yyyy-MM-dd HH:mm:ss} %p %m%n</Pattern>
</PatternLayout>
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy
size="5 KB"/>
</Policies>
</RollingFile>
</Appenders>
<Loggers>
<Logger name="bug" level="TRACE">
<AppenderRef ref="roll-by-size"/>
</Logger>
<Root level="DEBUG">
<AppenderRef ref="stdout"/>
</Root>
</Loggers>
</Configuration>
Странно, что при запуске приложения вы увидите эти журналы в консоли.
2016-12-22 22:12:36 INFO This is log message #1993.
2016-12-22 22:12:36 INFO This is log message #1994.
2016-12-22 22:12:36 INFO This is log message #1995.
2016-12-22 22:12:36 INFO This is log message #1996.
2016-12-22 22:12:36 INFO This is log message #1997.
2016-12-22 22:12:36 INFO This is log message #1998.
2016-12-22 22:12:36 INFO This is log message #1999.
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, [email protected]]
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, [email protected]]...
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81,component=StatusLogger]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=60199c81,component=ContextSelector]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=60199c81,component=Loggers,name=bug, org.apache.logging.log4j2:type=60199c81,component=Lo
ggers,name=]
2016-12-22 22:13:36,381 pool-1-thread-1 TRACE Unregistering 2 MBeans: [org.apache.logging.log4j2:type=60199c81,component=Appenders,name=roll-by-size, org.apache.logging.log4j2:type=60199c81,c
omponent=Appenders,name=stdout]
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=AsyncAppenders,name=*'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=AsyncLoggerRingBuffer'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=60199c81,component=Loggers,name=*,subtype=RingBuffer'
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=C:\Users\danidemi\workspace\bug-log4j2-hanging-up-before-shutdown\target\classes\log4j2.xml]...
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration notified 3 ReliabilityStrategies that config will be stopped.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping 2 LoggerConfigs.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping root LoggerConfig.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration notifying ReliabilityStrategies that appenders will be stopped.
2016-12-22 22:13:36,382 pool-1-thread-1 TRACE XmlConfiguration stopping remaining Appenders.
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shutting down RollingFileManager target/log4j2/roll-by-size/app.log
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shut down RollingFileManager target/log4j2/roll-by-size/app.log, all resources released: true
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
2016-12-22 22:13:36,383 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
2016-12-22 22:13:36,384 pool-1-thread-1 TRACE XmlConfiguration stopped 2 remaining Appenders.
2016-12-22 22:13:36,384 pool-1-thread-1 TRACE XmlConfiguration cleaning Appenders from 3 LoggerConfigs.
2016-12-22 22:13:36,384 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=C:\Users\danidemi\workspace\bug-log4j2-hanging-up-before-shutdown\target\classes\log4j2.xml] OK
2016-12-22 22:13:36,385 pool-1-thread-1 DEBUG Stopped LoggerContext[name=60199c81, [email protected]]...
Что странно, что последний журнал выпускается в определенное время ...
2016-12-22 22:12:36 INFO This is log message #1999.
но закрытие log4j2 начинается точно одну минуту после последнего «бизнеса» сообщение войти ,
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, [email protected]]
В этом проблема! Бизнес-логика завершается, но log4j2 ждет одну минуту, прежде чем разрешить приложение останавливаться! Зачем? Я бы предпочел, чтобы приложение немедленно остановилось, как можно было бы ожидать.
Я исследовал немного ... эта 60-секундная задержка кажется более или менее независимой из числа регистрируемых сообщений.
Однако, если вы измените log4j2.xml приращение размера от 5KB ...
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy size="5 KB"/>
</Policies>
в 5Mb ...
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy size="5 MB"/>
</Policies>
... что делает приложение, чтобы немедленно прекратить сразу же после последнее сообщение журнала. 5Mb - это предел, достаточно большой, чтобы не требовать, чтобы каток действительно имел место. Так что я думаю, что это сама прокатка, которая каким-то образом заставляет эту задержку произойти. Я думаю, что это ошибка, но ... как вы думаете?
Я установил небольшой проект Maven на GitHub, который демонстрирует то, что я пытался объяснить здесь.
Привет @sazzad, я принимаю ответ, потому что он решает проблему, но мне было интересно, можете ли вы немного рассказать о теме. Знаете, я всегда использовал log4j и logback, и мне никогда не приходилось явно «отключать» систему ведения журнала, поэтому я немного удивлен этой особенностью. Thx заранее. – danidemi
Вы можете изучить этот ответ и проблемы с log4j2 jira. http://stackoverflow.com/a/28835409/4021802 – sazzad