You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Philip Hachey (Jira)" <ji...@apache.org> on 2021/06/07 19:06:00 UTC
[jira] [Closed] (LOG4J2-3102) Asynchronous Logger WAITS
indefinitely after end of main method
[ https://issues.apache.org/jira/browse/LOG4J2-3102?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Philip Hachey closed LOG4J2-3102.
---------------------------------
I tested the fix using Log4j 2.15.0-SNAPSHOT (from [https://repository.apache.org/snapshots)] and I have confirmed that the issue is resolved. Asynchronous loggers no longer block the termination of the JVM. Thank you for the resolution!
> Asynchronous Logger WAITS indefinitely after end of main method
> ---------------------------------------------------------------
>
> Key: LOG4J2-3102
> URL: https://issues.apache.org/jira/browse/LOG4J2-3102
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.14.1
> Reporter: Philip Hachey
> Assignee: Carter Kozak
> Priority: Major
> Fix For: 2.15.0
>
>
> When running a Java 8 console application on Linux while a Log4j2 asynchronous logger is configured, the "Log4j2-AsyncAppenderEventDispatcher-1-AsynAppenders" thread remains in a "WAITING (parking)" state even after the end of the application's "main" method is reached. This prevents the JVM from exiting and the console application from terminating.
> *This is a NEW issue as of 2.14.1. Log4j 2.14.0 does not have this problem.*
> Here is jstack output:
>
> {code:java}
> 2021-06-03 22:48:25
> Full thread dump OpenJDK 64-Bit Server VM (25.292-b10 mixed mode):
> "Attach Listener" #16 daemon prio=9 os_prio=0 tid=0x00007fa228001000 nid=0x2bf6b6 waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "DestroyJavaVM" #15 prio=5 os_prio=0 tid=0x00007fa29000b000 nid=0x2bf67f waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "Log4j2-AsyncAppenderEventDispatcher-1-AsynAppenders" #13 prio=5 os_prio=0 tid=0x00007fa29089e800 nid=0x2bf695 waiting on condition [0x00007fa2714e8000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x000000064981b2c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
> at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.dispatchAll(AsyncAppenderEventDispatcher.java:70)
> at org.apache.logging.log4j.core.appender.AsyncAppenderEventDispatcher.run(AsyncAppenderEventDispatcher.java:62)
> "Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00007fa290268800 nid=0x2bf692 runnable [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "C1 CompilerThread3" #8 daemon prio=9 os_prio=0 tid=0x00007fa290255800 nid=0x2bf691 waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007fa290253000 nid=0x2bf690 waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fa290251800 nid=0x2bf68f waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fa29024e800 nid=0x2bf68e waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fa290249000 nid=0x2bf68d runnable [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fa29021a800 nid=0x2bf68c in Object.wait() [0x00007fa2722e1000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on <0x000000064982b578> (a java.lang.ref.ReferenceQueue$Lock)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
> - locked <0x000000064982b578> (a java.lang.ref.ReferenceQueue$Lock)
> at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
> "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fa290216000 nid=0x2bf68b in Object.wait() [0x00007fa2723e2000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> - waiting on <0x0000000649815328> (a java.lang.ref.Reference$Lock)
> at java.lang.Object.wait(Object.java:502)
> at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
> - locked <0x0000000649815328> (a java.lang.ref.Reference$Lock)
> at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
> "VM Thread" os_prio=0 tid=0x00007fa29020c800 nid=0x2bf68a runnable
> "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fa29001f800 nid=0x2bf680 runnable
> "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fa290021800 nid=0x2bf681 runnable
> "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fa290023800 nid=0x2bf682 runnable
> "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fa290025000 nid=0x2bf683 runnable
> "GC task thread#4 (ParallelGC)" os_prio=0 tid=0x00007fa290027000 nid=0x2bf684 runnable
> "GC task thread#5 (ParallelGC)" os_prio=0 tid=0x00007fa290028800 nid=0x2bf685 runnable
> "GC task thread#6 (ParallelGC)" os_prio=0 tid=0x00007fa29002a800 nid=0x2bf686 runnable
> "GC task thread#7 (ParallelGC)" os_prio=0 tid=0x00007fa29002c000 nid=0x2bf687 runnable
> "GC task thread#8 (ParallelGC)" os_prio=0 tid=0x00007fa29002e000 nid=0x2bf688 runnable
> "GC task thread#9 (ParallelGC)" os_prio=0 tid=0x00007fa29002f800 nid=0x2bf689 runnable
> "VM Periodic Task Thread" os_prio=0 tid=0x00007fa29026b000 nid=0x2bf693 waiting on condition
> JNI global references: 1652
> {code}
>
> Here is the log4j2.xml configuration file being used:
> {code:java}
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE Configuration>
> <Configuration status="WARN">
> <Properties>
> <Property name="rootLogger.level">trace</Property>
> <Property name="rollingFile.fileName">${sys:mediafeed.logbase}.log</Property>
> <Property name="rollingFile.filePattern">${sys:mediafeed.logbase}.%date{yyyy-MM-dd}.log</Property>
> <Property name="logExcludedArticles.enabled">false</Property>
> <Property name="logExcludedArticles.directory">filtered</Property>
> </Properties>
> <Appenders>
> <ScriptAppenderSelector name="LogExcludedArticlesIfEnabled">
> <Script language="JavaScript"><![CDATA[${sys:logExcludedArticles.enabled} ? "LogExcludedArticles" : "DoNotLogExcludedArticles";]]></Script>
> <AppenderSet>
> <RollingFile name="LogExcludedArticles" fileName="${sys:logExcludedArticles.directory}/excludedarticles.csv" filePattern="${sys:logExcludedArticles.directory}/excludedarticles-%d{yyyy-MM-dd}.csv.gz">
> <TimeBasedTriggeringPolicy />
> <CsvParameterLayout />
> </RollingFile>
> <Null name="DoNotLogExcludedArticles" />
> </AppenderSet>
> </ScriptAppenderSelector>
> <RollingFile name="RollingLogFile" fileName="${rollingFile.fileName}" filePattern="${rollingFile.filePattern}">
> <PatternLayout pattern="%date [%9replace{%threadName}{ForkJoinPool.commonPool-worker}{FJP.cw}] %-5level %30.30logger{-6} %message%n%throwable" />
> <SizeBasedTriggeringPolicy size="20 MB" />
> <DefaultRolloverStrategy max="6" />
> </RollingFile>
> <Async name="AsynAppenders">
> <AppenderRef ref="RollingLogFile" />
> </Async>
> </Appenders>
> <Loggers>
> <Logger name="ExcludedArticlesLogger" level="trace" additivity="false">
> <AppenderRef ref="LogExcludedArticlesIfEnabled" level="trace" />
> <AppenderRef ref="AsynAppenders" level="${sys:rootLogger.level}" />
> </Logger>
> <Root level="${sys:rootLogger.level}">
> <AppenderRef ref="AsynAppenders" />
> </Root>
> </Loggers>
> </Configuration>
> {code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)