Dieser Code reproduziert, was ich für einen Fehler von Log4j2 halte. Es ist eine einfache Schleife, die 2000 Nachrichten mit zwei Appendern protokolliert: eine Konsole Appender und eine rollende Datei Appender, der die Datei alle 5Kb rollt. Dieses Limit ist absichtlich niedrig, um zu reproduzieren, was ich für einen Bug halte.Warum verhindert RollingFile Appender von Log4j2, dass eine eigenständige Anwendung 60 Sekunden lang beendet wird?
Hier ist der Code.
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);
}
}
}
Hier ist die log4j2.xml Konfigurationsdatei.
Was ist seltsam ist, dass wenn die Anwendung gestartet wird Sie sehen, dass diese Protokolle in der Konsole.
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]]...
Was seltsam ist, dass das letzte Protokoll zu einem bestimmten Zeitpunkt ausgegeben wird ...
2016-12-22 22:12:36 INFO This is log message #1999.
aber die Abschaltung von log4j2 beginnt genau eine Minute nach dem letzten „Geschäft“ Protokollmeldung .
2016-12-22 22:13:36,380 pool-1-thread-1 DEBUG Stopping LoggerContext[name=60199c81, [email protected]]
Dies ist das Problem! Die Geschäftslogik wird beendet, log4j2 wartet jedoch eine Minute, bevor die App gestoppt werden kann! Warum das? Ich würde es vorziehen, wenn die Anwendung sofort aufhört, wie man es wahrscheinlich erwartet.
Ich untersuchte ein wenig ... diese 60 Sekunden Verzögerung scheint mehr oder weniger unabhängig von der Anzahl der Nachrichten protokolliert werden.
Wenn Sie jedoch die log4j2.xml die Größe von 5Kb Erhöhen ändern ...
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy size="5 KB"/>
</Policies>
zu 5 MB ...
<Policies>
<OnStartupTriggeringPolicy/>
<SizeBasedTriggeringPolicy size="5 MB"/>
</Policies>
... das macht die Anwendung sofort zu stoppen direkt nach die letzte Protokollnachricht 5Mb ist ein Limit, das groß genug ist, um das Rollen nicht wirklich zu erfordern. Also ich denke, das ist das Rollen selbst, dass in gewisser Weise diese Verzögerung auftreten zu machen. Ich denke, es ist ein Fehler, aber ... Was denkst du?
Ich habe ein kleines Maven-Projekt auf GitHub eingerichtet, das demonstriert, was ich hier zu erklären versuchte.
Hallo @sazzad, ich akzeptiere die Antwort, weil es das Problem löst, aber ich frage mich, ob Sie freundlicherweise ein wenig zu dem Thema erweitern können. Weißt du, ich habe immer Log4j und Logback benutzt und ich musste das Logging-System nicht explizit "ausschalten", also bin ich etwas überrascht von dieser Funktion. Danke im Voraus. – danidemi
Sie können diese Antwort und log4j2 jira Probleme dort adressiert betrachten. http://StackOverflow.com/a/28835409/4021802 – sazzad