[slf4j-user] deadlock in slf4j-log4j12 ?

Tue Feb 10 14:32:54 CET 2009

I'm using slf4j version 1.5.6 in combination with log4j version
1.2.15. Java version is 1.6.0.

In my unit tests, I'm experiencing a deadlock which seems related to
slf4j / log4j. Below is a thread dump. Anybody experienced similar
problems?
---------------

2009-02-10 12:58:52
Full thread dump Java HotSpot(TM) Server VM (11.0-b15 mixed mode):

"Attach Listener" daemon prio=10 tid=0x09df7000 nid=0x551e runnable
[0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"pool-2-thread-2" prio=10 tid=0x8f92e400 nid=0x54c0 waiting for
monitor entry [0x8fa56000..0x8fa56eb0]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.jmock.api.ExpectationError.toString(ExpectationError.java:32)
	at java.lang.String.valueOf(String.java:2827)
	at java.io.PrintWriter.println(PrintWriter.java:710)
	at java.lang.Throwable.printStackTrace(Throwable.java:509)
	- locked <0xb170f1b0> (a java.io.PrintWriter)
	at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:76)
	at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:407)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:305)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x94d92c40> (a org.apache.log4j.ConsoleAppender)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:571)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:187)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

"pool-2-thread-1" prio=10 tid=0x8f949800 nid=0x54bf waiting for
monitor entry [0x8faa7000..0x8faa7e30]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:281)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:150)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

"pool-1-thread-3" prio=10 tid=0x8f9fe400 nid=0x54be waiting for
monitor entry [0x8faf6000..0x8faf8db0]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.debug(Category.java:260)
	at com.traficon.util.logging.Log4JMessageHandler.handleMessage(Log4JMessageHandler.java:61)
	at org.aspectj.weaver.tools.WeavingAdaptor$WeavingAdaptorMessageHolder.handleMessage(WeavingAdaptor.java:615)
	at org.aspectj.bridge.MessageUtil.debug(MessageUtil.java:92)
	at org.aspectj.weaver.tools.WeavingAdaptor.debug(WeavingAdaptor.java:459)
	at org.aspectj.weaver.tools.WeavingAdaptor.weaveClass(WeavingAdaptor.java:280)
	at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:95)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:52)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:169)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:365)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:621)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:124)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:260)
	at java.net.URLClassLoader.access$000(URLClassLoader.java:56)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:195)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
	at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at com.traficon.domain.message.impl.xml2.event.Xml2EventMessageGenerator.generateEventMessage(Xml2EventMessageGenerator.java:75)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.sendCommError(GridCommunicationStateSendingListener.java:112)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.connectionFailed(GridCommunicationStateSendingListener.java:74)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:153)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x90308800 nid=0x54b7
runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x906fec00 nid=0x54b6 waiting on
condition [0x00000000..0x902fe328]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x906ff800 nid=0x54b5 waiting on
condition [0x00000000..0x904e5368]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x90611800 nid=0x54b4 runnable
[0x00000000..0x905bfb10]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x90600800 nid=0x54b3 in Object.wait()
[0x90762000..0x90762db0]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x94d7dd60> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
	- locked <0x94d7dd60> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x09bec000 nid=0x54b2 in
Object.wait() [0x907b3000..0x907b4130]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x94d7dd18> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:485)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <0x94d7dd18> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x09b67400 nid=0x54ac waiting for monitor entry
[0xb7ed7000..0xb7ed91f8]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:319)
	at com.traficon.tmsng.server.inputgrid.detector.gridgain.GridGainDetectorCommunicator.setStateStopped(GridGainDetectorCommunicator.java:374)
	at com.traficon.tmsng.server.inputgrid.detector.state.DetectorCommunicatorStateActive.switchToStopped(DetectorCommunicatorStateActive.java:48)
	at com.traficon.tmsng.server.inputgrid.detector.gridgain.GridGainDetectorCommunicator.setState(GridGainDetectorCommunicator.java:190)
	at com.traficon.tmsng.server.inputgrid.detector.gridgain.GridGainDetectorCommunicatorManager.stopBoards(GridGainDetectorCommunicatorManager.java:313)
	at com.traficon.tmsng.server.inputgrid.detector.gridgain.GridGainDetectorCommunicatorManager.stop(GridGainDetectorCommunicatorManager.java:150)
	- locked <0xb47d4500> (a java.util.concurrent.ConcurrentHashMap)
	at com.traficon.tmsng.server.inputgrid.detector.gridgain.GridGainDetectorCommunicatorManagerTest.testUpdateDetectors(GridGainDetectorCommunicatorManagerTest.java:198)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.testng.internal.MethodHelper.invokeMethod(MethodHelper.java:580)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:478)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:617)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:885)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:126)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:110)
	at org.testng.TestRunner.runWorkers(TestRunner.java:712)
	at org.testng.TestRunner.privateRun(TestRunner.java:582)
	at org.testng.TestRunner.run(TestRunner.java:477)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:324)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:319)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:292)
	at org.testng.SuiteRunner.run(SuiteRunner.java:198)
	at org.testng.TestNG.createAndRunSuiteRunners(TestNG.java:821)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:788)
	at org.testng.TestNG.run(TestNG.java:708)
	at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:74)
	at org.apache.maven.surefire.testng.TestNGXmlTestSuite.execute(TestNGXmlTestSuite.java:92)
	at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:345)
	at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1009)

"VM Thread" prio=10 tid=0x09be8800 nid=0x54b1 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x09b6e400 nid=0x54ad runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x09b70000 nid=0x54ae runnable

"VM Periodic Task Thread" prio=10 tid=0x9030a400 nid=0x54b8 waiting on
condition

JNI global references: 973

Found one Java-level deadlock:
=============================
"pool-2-thread-2":
  waiting to lock monitor 0x09d17be0 (object 0x94d51000, a
sun.misc.Launcher$AppClassLoader),
  which is held by "pool-1-thread-3"
"pool-1-thread-3":
  waiting to lock monitor 0x09beebac (object 0x94dcf218, a
org.apache.log4j.spi.RootLogger),
  which is held by "pool-2-thread-2"

Java stack information for the threads listed above:
===================================================
"pool-2-thread-2":
	at org.jmock.api.ExpectationError.toString(ExpectationError.java:32)
	at java.lang.String.valueOf(String.java:2827)
	at java.io.PrintWriter.println(PrintWriter.java:710)
	at java.lang.Throwable.printStackTrace(Throwable.java:509)
	- locked <0xb170f1b0> (a java.io.PrintWriter)
	at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:76)
	at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:407)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:305)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	- locked <0x94d92c40> (a org.apache.log4j.ConsoleAppender)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	- locked <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.log(Category.java:856)
	at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:571)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:187)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
"pool-1-thread-3":
	at org.apache.log4j.Category.callAppenders(Category.java:205)
	- waiting to lock <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.debug(Category.java:260)
	at com.traficon.util.logging.Log4JMessageHandler.handleMessage(Log4JMessageHandler.java:61)
	at org.aspectj.weaver.tools.WeavingAdaptor$WeavingAdaptorMessageHolder.handleMessage(WeavingAdaptor.java:615)
	at org.aspectj.bridge.MessageUtil.debug(MessageUtil.java:92)
	at org.aspectj.weaver.tools.WeavingAdaptor.debug(WeavingAdaptor.java:459)
	at org.aspectj.weaver.tools.WeavingAdaptor.weaveClass(WeavingAdaptor.java:280)
	at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:95)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:52)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:169)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:365)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:621)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:124)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:260)
	at java.net.URLClassLoader.access$000(URLClassLoader.java:56)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:195)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
	at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
	- locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
	at com.traficon.domain.message.impl.xml2.event.Xml2EventMessageGenerator.generateEventMessage(Xml2EventMessageGenerator.java:75)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.sendCommError(GridCommunicationStateSendingListener.java:112)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.connectionFailed(GridCommunicationStateSendingListener.java:74)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:153)
	at com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

Found 1 deadlock.