Bug 43568 - Deadlock in Log4j when logging inside exception stack trace
Summary: Deadlock in Log4j when logging inside exception stack trace
Status: RESOLVED LATER
Alias: None
Product: Log4j - Now in Jira
Classification: Unclassified
Component: Other (show other bugs)
Version: 1.2
Hardware: Sun Solaris
: P1 critical
Target Milestone: ---
Assignee: log4j-dev
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-10-07 23:20 UTC by Kenny Moens
Modified: 2007-10-31 09:44 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Kenny Moens 2007-10-07 23:20:44 UTC
- Log4j is configured with a RootLogger and a specific Logger for the package
com.siemens, both configured to use the same RollingFileAppender. 
- Thread 1: a class in the package X logs an exception outside the package X
- Thread 2: a class outside the package X tries to log another message 

ull description of deadlock: 
[T1]: Thread 1 acquires a lock on the specific Logger of package X
[T1]: As a consequence Thread 1 acquires a lock on the RollingFileAppender 
[T2]: Thread 2 wants to log something and as such acquires a lock on RootLogger.
[T2]: To perform the logging, Thread 2 waits to get a lock on the
RollingFileAppender 
[T1]: The logging of the exception in Thread 1 also wants to write stuff to the
log and as it is outside the X package wants a lock on the RootLogger which is
owned by Thread 2 already.

The problem occured with Apache Axis 1.4 which appearantly shows this behaviour
of logging during the generation of exception stack traces.
Comment 1 Curt Arnold 2007-10-31 09:44:58 UTC
log4j 1.2's architecture is such that any attempt to log from within the scope of a log4j method will 
potentially deadlock.  Eliminating the coarse-grained locking is a design goal for log4j 2.0, but it can't 
be done in log4j 1.2 without breaking appenders and layouts that depend on the current 
synchronization model.

This is typically encountered when the toString() member of the message parameter makes log4j calls.  
However, if an exception parameters printStackTrace(Writer) method makes log4j calls the same type of 
deadlock situation could arise.

The only potential remedy would be to prevent this situation from arising.  One way to prevent it would 
be to create a custom layout that suppresses the stack trace for the problematic exceptions (assuming 
that you are using a FileAppender or other derived from WriterAppender).  Something like:

public class MyPatternLayout extends PatternLayout {
    //
    //  returning false suppresses the default handling of 
    //    exceptions in WriterAppender
    public boolean ignoresThrowable() {
        return false;
    }
    private static boolean safeException(ThrowableInformation ti) {
         if (ti != null) {
             Throwable t = ti.getThrowable();
             if (t != null) {
                  if (t instanceof MyBadException1 ||
                      t instanceof MyBadException2) {
                      return false;
                  }
            }
            return true;
        }
        return false;
    }

    public String format(final LoggingEvent event) {
        String retval = super.format(event);
        if (safeException(event.getThrowableInfo()) {
             StringBuffer buf = new StringBuffer(retval);
             String[] trace = event.getThrowableStrRep();
             if (trace != null) {
                  for(int i = 0; i < trace.length; i++) {
                       buf.append(trace[i]);
                       buf.append(Layout.LINE_SEP);
                  }
             }
            retval = buf.toString();
       } else {
            //  as much info on the bad exception that you can get
            //     without triggering a log4j call
       }
}