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.
Ralph
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
