https://issues.apache.org/bugzilla/show_bug.cgi?id=41214
--- Comment #45 from Jason Marshall <[email protected]> --- I too like the snapshotting aspects of this solution, unfortunately some people use toString to implement expensive pretty printing calls. You wouldn't want to call toString() eagerly on a debug() level call, only to have it be dropped on the floor. (In reply to comment #41) > (In reply to comment #35) > > 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. > > Actually, I think the solution (or a mitigation) might be simple. I suggest > the following "workaround" modifications, in the Log4J version 1.2.17 (the > last version): > > 1)In the org.apache.log4j.spi.LoggingEvent class, inside all the > constructor's: > > Replace: > this.message = message; > > By: > this.message = message != null ? message.toString() : null; > > Doing so, you can make the "message" instance field always of the type > String. > > -- 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]
