I have a very basic (almost textbook) Log4J2 sample, using latest (2.14.1):
log4j2.xml (taken from the official appender doc):
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
<Appenders>
<File name="MyFile" fileName="logs/app.log">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
</File>
<Async name="Async">
<AppenderRef ref="MyFile"/>
</Async>
</Appenders>
<Loggers>
<Root level="error">
<AppenderRef ref="Async"/>
</Root>
</Loggers>
</Configuration>
Program, TestLog.java:
public class TestLog {
private static final org.apache.logging.log4j.Logger l = org.apache.logging.log4j.LogManager.getLogger(TestLog.class);
public static void main(String[] args) {
l.error("Boo");
}
}
pom.xml:
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns="http://maven.apache.org/POM/4.0.0"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>com.tuna</groupId>
<artifactId>log4j2-not-shutting-down</artifactId>
<version>0</version>
<dependencies>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.14.1</version>
</dependency>
</dependencies>
<properties>
<maven.compiler.source>1.8</maven.compiler.source>
<maven.compiler.target>1.8</maven.compiler.target>
</properties>
</project>
When I run this, I do get the expected ERROR log line in logs/app.log; however the Java process hangs (does not shut down after main() completes). A thread dump shows (in addition to Java's native threads) a non-daemon async-appender thread that remains WAITING (most probably the cause for the hang).
"Log4j2-AsyncAppenderEventDispatcher-1-Async" #15 prio=5 os_prio=0 cpu=0.00ms elapsed=17.04s tid=0x000001bd5bc98000 nid=0x7324 waiting on condition [0x0000006962bff000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@12/Native Method)
- parking to wait for <0x00000007110c2618> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@12/LockSupport.java:194)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12/AbstractQueuedSynchronizer.java:2081)
at java.util.concurrent.ArrayBlockingQueue.take(java.base@12/ArrayBlockingQueue.java:417)
at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.dispatchAll(AsyncAppenderEventDispatcher.java:70)
at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.run(AsyncAppenderEventDispatcher.java:62)
- Removing the
Asyncappender (and directly appending toMyFile) causes the program to shut down properly. - Adding a
shutdownTimeoutto theAsyncappender definition has no effect. (Anyways the only log line already gets written to the file properly, so it could not possibly be a queueing issue.) - Switching
log4j-coreto a lower version (e.g.2.9.1) also resolves the hang.
Is this the expected behavior, or a bug? Am I missing anything?
Appears to be already reported and fixed.
Anyways 2.14.1 is no longer viable (due to the infamous CVE-2021-44228 RCE vulnerability), and given the several vulnerabilities discovered afterwards it is now recommended to upgrade to 2.17.0 or above - where the originally stated LOG4J2-3102 is also fixed.