https://issues.apache.org/bugzilla/show_bug.cgi?id=41214
--- Comment #35 from [email protected] 2011-02-25 08:38:57 EST --- ####<Feb 16, 2011 7:05:25 PM GST> <Critical> <WebLogicServer> <camp1s> <CAMAProd> <[ACTIVE] ExecuteThread: '6' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1297868725143> <BEA-000394> < DEADLOCK DETECTED: ================== [deadlocked thread] [ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)': -------------------------------------------------------------------------------------------------- Thread '[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'' is waiting to acquire lock 'org.apache.log4j.RollingFileAppender@18cceaf' that is held by thread '[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'' Stack trace: ------------ org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:210) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.debug(Category.java:257) com.company.product.jdbc.MyJDBC.selectAllObjects(MyJDBC.java:294) com.company.product.business.MyBusinessMgrImpl.selectAllObjects(MyBusinessMgrImpl.java:155) ... [deadlocked thread] [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)': -------------------------------------------------------------------------------------------------- Thread '[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'' is waiting to acquire lock 'org.apache.log4j.Logger@155742b' that is held by thread '[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'' Stack trace: ------------ org.apache.log4j.Category.callAppenders(Category.java:201) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.warn(Category.java:1008) com.company.product.datatypes.BusinessException.toString(BusinessException.java:757) org.apache.log4j.spi.VectorWriter.println(ThrowableInformation.java:97) java.lang.Throwable.printStackTrace(Throwable.java:510) org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:59) org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:342) org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:304) org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:234) org.apache.log4j.WriterAppender.append(WriterAppender.java:159) org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) org.apache.log4j.Category.callAppenders(Category.java:203) org.apache.log4j.Category.forcedLog(Category.java:388) org.apache.log4j.Category.error(Category.java:319) com.company.framework.ejb.connectivity.BaseMessageDrivenBean.doRollback(BaseMessageDrivenBean.java:111) ... Before diving into the explanation, you need a few code samples to fully understand: The BusinessException extends Exception and implements the toString() method with some logging inside. public class BusinessException extends Exception { private static final Logger log = Logger.getLogger(BusinessException.class); @Override public String toString() { ... log.debug("some logging in the toString()"); ... } } The Category.callAppenders() method makes its way up the Logger hierarchy (log4j Logger hierarchy knowledge needed). On each iteration the Logger is locked with a synchronized block. Once in the synchronized block, if an AppenderAttachableImpl exists on the current Logger, it calls AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent). public class Category implements AppenderAttachable { public void callAppenders(LoggingEvent event) { int writes = 0; for(Category c = this; c != null; c=c.parent) { // Protected against simultaneous call to addAppender, removeAppender,... synchronized(c) { if(c.aai != null) { writes += c.aai.appendLoopOnAppenders(event); } if(!c.additive) { break; } } } if(writes == 0) { repository.emitNoAppenderWarning(this); } } } In AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent), the method Appender.doAppend(LoggingEvent) is called. public class AppenderAttachableImpl implements AppenderAttachable { public int appendLoopOnAppenders(LoggingEvent event) { int size = 0; Appender appender; if(appenderList != null) { size = appenderList.size(); for(int i = 0; i < size; i++) { appender = (Appender) appenderList.elementAt(i); appender.doAppend(event); } } return size; } } Finally, the RollingFileAppender indirectly implementes Appender via the indirectly extended AppenderSkeleton class. AppenderSkeleton.doAppend(LoggingEvent) is a synchonized method, so calling RollingFileAppender.doAppend(LoggingEvent) will lock the current RollingFileAppender object. public abstract class AppenderSkeleton implements Appender, OptionHandler { public synchronized void doAppend(LoggingEvent event) { ... } } What follows is what I found was happening. We have the following Logger hierarchy: RootLogger +- com.company - RollingFileAppender attached +- com.company.product.jdbc.MyJDBC (ExecuteThread: '4') +- com.company.product.datatypes.BusinessException (ExecuteThread: '0') +- framework.core.ejb.connectivity.BaseMessageDrivenBean (ExecuteThread: '0') - RollingFileAppender attached I think the sequence of event is something like this: 1. ExecuteThread: '0' – is logging on the BaseMessageDrivenBean logger with a BusinessException (which implements toString()) 2. ExecuteThread: '0' - in Category.callAppenders(), it starts to make its way up in the Logger hierarchy (locking the current Logger on each iteration). 3. ExecuteThread: '0' - it reaches and locks the "framework.core.ejb.connectivity.BaseMessageDrivenBean" Logger, where it finds a RollingFileAppender attached. It calls AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent), which ends up calling synchronized method doAppend(LoggingEvent) on a RollingFileAppender object, locking it at the same time. 4. ExecuteThread: '4' – is logging something on the MyJDBC logger 5. ExecuteThread: '4' - in Category.callAppenders(), it starts to make its way up in the Logger hierarchy (locking the current Logger on each iteration). 6. ExecuteThread: '4' - it reaches and locks the "com.company" Logger, where it finds a RollingFileAppender attached. It calls AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent), which ends up calling the synchronized method doAppend(LoggingEvent) on the _already locked_ RollingFileAppender object. *ExecuteThread: '4' is blocked waiting on ExecuteThread: '0'* 7. ExecuteThread: '0' – goes on with its execution inside the RollingFileAppender. This ends up logging the BusinessException, which indirectly calls BusinessException.toString(). Inside the toString() method come logging is called on the BusinessException Logger. 8. ExecuteThread: '0' - in Category.callAppenders(), it starts to make its way up in the Logger hierarchy (locking the current Logger on each iteration). 9. ExecuteThread: '0' - it reaches "com.company" and tries to lock it, but it is already locked by ExecuteThread: '4'. *ExecuteThread: '0' is blocked waiting on ExecuteThread: '4'* THIS IS A DEADLOCK SITUATION. This is not really a problem with log4j's itself. The problem lies more in how log4j is configured, and a complex sequence of method calls exhibiting a deadlock situation with java locks on synchronized blocks. Using the RollingFileAppender probably makes things worse: if a file rolling (very slow compared to running java code) is happening in this sequence of events, then it greatly increases the chances of reaching such problem. -- Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug. --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
