[slf4j-user] deadlock in slf4j-log4j12 ?

Paul French paul.french at kirona.com
Tue Feb 10 19:03:36 CET 2009 

Is this something to be concerned about? We have legacy code that uses log4j
directly and we also have code that uses the slf4j api + slf4jlog4j
implementation.
 
I haven't seen any problems to date but we are only in a testing phase. I'm
wondering if we have just been lucky so far to miss the problem below?
 
Cheers
Paul

  _____  

From: user-bounces at slf4j.org [mailto:user-bounces at slf4j.org] On Behalf Of
Patrick Hancke
Sent: 10 February 2009 15:58
To: User list for the slf4j project
Subject: Re: [slf4j-user] deadlock in slf4j-log4j12 ?


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(ThrowableInform
ation.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(Append
erAttachableImpl.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.RetryConnectingToSoc
ketTask.call(RetryConnectingToSocketTask.java:187)
       at
com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSoc
ketTask.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.ja
va:886)
       at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
       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(Log4JMessageHand
ler.java:61)
       at
org.aspectj.weaver.tools.WeavingAdaptor$WeavingAdaptorMessageHolder.handleMe
ssage(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(ClassPre
ProcessorAgentAdapter.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.genera
teEventMessage(Xml2EventMessageGenerator.java:75)
       at
com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationSta
teSendingListener.sendCommError(GridCommunicationStateSendingListener.java:1
12)
       at
com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationSta
teSendingListener.connectionFailed(GridCommunicationStateSendingListener.jav
a:74)
       at
com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSoc
ketTask.call(RetryConnectingToSocketTask.java:153)
       at
com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSoc
ketTask.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.ja
va:886)
       at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
       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/2aea4d62/attachment.htm>

More information about the slf4j-user mailing list