Major Description
From the log4j-dev mailing list:
I just tried to do a full build and got this test to hang. Gary reported the same thing last week on Windows. The stack trace indicates that it isn’t properly shutting down. Somehow it seems the BlockingAppender must not be having its shutdown flag set. This test was only added a month ago. I’m not really sure what this test is trying to do but it appears to have some flawed logic somewhere.
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.80-b11 mixed mode): "Attach Listener" daemon prio=5 tid=0x00007fc93b81b000 nid=0x3d0b waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "AsyncAppender-Async" daemon prio=5 tid=0x00007fc93c16c000 nid=0x5603 sleeping[0x00007000015d5000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.logging.log4j.test.appender.BlockingAppender.append(BlockingAppender.java:44) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.callAppenders(AsyncAppender.java:338) at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.run(AsyncAppender.java:291) "surefire-forkedjvm-command-thread" daemon prio=5 tid=0x00007fc93c845800 nid=0x5403 runnable [0x00007000014d2000] java.lang.Thread.State: RUNNABLE at java.io.FileInputStream.readBytes(Native Method) at java.io.FileInputStream.read(FileInputStream.java:272) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read(BufferedInputStream.java:254) - locked <0x00000007aaa9ab70> (a java.io.BufferedInputStream) at java.io.DataInputStream.readInt(DataInputStream.java:387) at org.apache.maven.surefire.booter.MasterProcessCommand.decode(MasterProcessCommand.java:117) at org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:360) at java.lang.Thread.run(Thread.java:745) "last-ditch-daemon-shutdown-thread-30sec" daemon prio=5 tid=0x00007fc93c873800 nid=0x5203 waiting on condition [0x00007000013cf000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000007aad7d750> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:745) "Service Thread" daemon prio=5 tid=0x00007fc93c014800 nid=0x4e03 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread1" daemon prio=5 tid=0x00007fc93c82d800 nid=0x4c03 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" daemon prio=5 tid=0x00007fc93b051800 nid=0x4a03 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=5 tid=0x00007fc93b04c000 nid=0x3e0f runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=5 tid=0x00007fc93c800000 nid=0x3803 in Object.wait() [0x0000700000d3a000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000007aaa84858> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135) - locked <0x00000007aaa84858> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209) "Reference Handler" daemon prio=5 tid=0x00007fc93c00e000 nid=0x3603 in Object.wait() [0x0000700000c37000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000007aaa84470> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:503) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133) - locked <0x00000007aaa84470> (a java.lang.ref.Reference$Lock) "main" prio=5 tid=0x00007fc93c002800 nid=0x1703 in Object.wait() [0x0000700000218000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000007aca98af0> (a org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread) at java.lang.Thread.join(Thread.java:1281) - locked <0x00000007aca98af0> (a org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread) at org.apache.logging.log4j.core.appender.AsyncAppender.stop(AsyncAppender.java:126) at org.apache.logging.log4j.core.config.AbstractConfiguration.stop(AbstractConfiguration.java:321) at org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:306) at org.apache.logging.log4j.core.config.Configurator.shutdown(Configurator.java:337) at org.apache.logging.log4j.junit.LoggerContextRule$1.evaluate(LoggerContextRule.java:97) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.junit.runners.Suite.runChild(Suite.java:128) at org.junit.runners.Suite.runChild(Suite.java:27) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83) at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75) at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121) "VM Thread" prio=5 tid=0x00007fc93c00b800 nid=0x3403 runnable "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007fc93b809800 nid=0x2403 runnable "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007fc93b80a000 nid=0x2603 runnable "GC task thread#2 (ParallelGC)" prio=5 tid=0x00007fc93b80a800 nid=0x2803 runnable "GC task thread#3 (ParallelGC)" prio=5 tid=0x00007fc93b80b000 nid=0x2a03 runnable "GC task thread#4 (ParallelGC)" prio=5 tid=0x00007fc93b80c000 nid=0x2c03 runnable "GC task thread#5 (ParallelGC)" prio=5 tid=0x00007fc93b80c800 nid=0x2e03 runnable "GC task thread#6 (ParallelGC)" prio=5 tid=0x00007fc93b80d000 nid=0x3003 runnable "GC task thread#7 (ParallelGC)" prio=5 tid=0x00007fc93b00b800 nid=0x3203 runnable "VM Periodic Task Thread" prio=5 tid=0x00007fc93c01d000 nid=0x5003 waiting on condition JNI global references: 170