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 Sun, 01 Jul 2012 12:48:33 GMT
https://issues.apache.org/bugzilla/show_bug.cgi?id=41214

msm <marc_sm2003@yahoo.com.br> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|Appender                    |Other
            Version|unspecified                 |1.2.17
                 OS|Linux                       |All

--- Comment #41 from msm <marc_sm2003@yahoo.com.br> ---
(In reply to comment #35)
> ####<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.

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.


2)In the org.apache.log4j.spi.ThrowableInformation class:
  2.1)Create the following instance field:

  private final String[] stackTraceArray;

  And, inside all the constructors, put the following piece of code:

    this.stackTraceArray = getThrowableStrRep();

  The intention here is using "stackTraceArray" instance field instead of
calling getThrowableStrRep() later.


  2.2)Make getThrowableStrRep() private. Doing so, there is no need to maintain
the synchronization of this method. Actually, I think there would be no need of
synchronizing this method even if it were public, because I didn't see any
place in Log4j source codes where an instance of ThrowableInformation is being
shared by more than one thread. I do not understand what was the intention of
the developer that created that method, maybe he/she predicted a future
necessity of synchronization, as ThrowableInformation is public and has public
constructors. We never know the sort of things the other programmers will do
with our public classes and methods (the "bug in Log4j" we are discussing here
shows exactly such a situation, doesn't it?)


  2.3)Create a public method called "getStackTraceArray()" that returns
"stackTraceArray" instance field (or we can also return a clone of this array).


3)In all the places where getThrowableStrRep() is being called, replace by
getStackTraceArray() invocation. This replacement should be done in the
following classes:
  org.apache.log4j.pattern.ThrowableInformationPatternConverter
  org.apache.log4j.spi.LoggingEvent
  org.apache.log4j.lf5.Log4JLogRecord


I do not think it is related just to RollingFileAppender, as the title of this
page suggests. That's just a synchronization among threads problem, not diretly
related to any appender.

Trying to understand who is the "guilty" of the problem (whether is Log4j or
the application/framework that uses Log4j) is not so important. What is
revelant is the fact that we have a big serious problem that has to be solved.
Otherwise, we can never rely on an multithreaded application subject to a Log4j
deadlock. If the solution I proposed doesn't solve the problem, I will really
consider the alternative of removing Log4j from my application. I will sadly do
that, although I like Log4j so much. But I tested my solution, and I think it
works and covers all the critical cases. Of course, as I said, this solution
might be considered just a mitigation, not a real solution. In my opinion, a
real and elegant solution would be done through a more deep refactoring.

-- 
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