Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-3102

Asynchronous Logger WAITS indefinitely after end of main method

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 2.14.1
    • 2.15.0
    • Appenders
    • None

    Description

      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:

       

      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
      

       

       Here is the log4j2.xml configuration file being used:

      <?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>
      

      Attachments

        Issue Links

          Activity

            People

              ckozak Carter Kozak
              krallus Philip Hachey
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: