[slf4j-user] deadlock in slf4j-log4j12 ?
Patrick Hancke
patrick.hancke at gmail.com
Tue Feb 10 16:57:32 CET 2009
It seems I've found the deadlock issue. Our code base consistently uses
slf4j except in a MessageHandler which is registered with AspectJ and takes
care of logging AspectJ related messages. That MessageHandler was still
using the log4j API directly which most probably caused a deadlock. The
solution is quite simple: I've written an slf4j MessageHandler and the
deadlock seems gone.
Thanks for your help,
Patrick Hancke
2009/2/10 Ceki Gulcu <ceki at qos.ch>
> 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
> _______________________________________________
> user mailing list
> user at slf4j.org
> http://www.slf4j.org/mailman/listinfo/user
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/slf4j-user/attachments/20090210/15df22b3/attachment.htm>
More information about the slf4j-user
mailing list