[slf4j-user] deadlock in slf4j-log4j12 ?

[Ceki Gulcu]

Hello Patrick,

Looking at the stack trace, it seems that pool-2-thread-2 after obtaining a lock 
on the RootLogger tries to obtain a lock on an sun.misc.Launcher$AppClassLoader 
instance within the org.jmock.api.ExpectationError.toString()  method.
Another thread namely, pool-1-thread-3, after obtaining a lock on the 
aforementioned sun.misc.Launcher$AppClassLoader instance tries to obtain a lock 
on RootLogger, hence the deadlock.

Not knowing more about RetryConnectingToSocketTask, I can't suggest a solution, 
However, I am pretty confident that the problem is not SLF4J related. Log4j's 
threading model might be at cause although I doubt it. You should try to 
identify the place where sun.misc.Launcher$AppClassLoader is locked.

HTH,

Patrick Hancke wrote:
> 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?
> ---------------

[snip]

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

-- 
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch