logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 41214] Deadlock with RollingFileAppender
Date Thu, 18 Oct 2012 22:31:07 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=41214

--- Comment #45 from Jason Marshall <jdmarshall@gmail.com> ---
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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message