Bug 24159 - Log4J can create deadlock conditions (concurrent package donation)
Log4J can create deadlock conditions (concurrent package donation)
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.3alpha
Sun Solaris
: P3 normal
: ---
Assigned To: log4j-dev
:
: 33855 41274 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2003-10-27 18:26 UTC by Elias Ross
Modified: 2007-08-22 19:44 UTC (History)
4 users (show)



Attachments
Diffs for AppenderSkeleton and WriterAppender (3.03 KB, patch)
2003-12-18 21:13 UTC, Elias Ross
Details | Diff
Changed appender attachable to return a copy-on-write array (1.31 KB, patch)
2003-12-18 22:15 UTC, Elias Ross
Details | Diff
Changed category to not lock on the appender attachable (839 bytes, patch)
2003-12-18 22:16 UTC, Elias Ross
Details | Diff
Changes against Log4J 1.3 CVS (3.62 KB, patch)
2004-09-22 22:11 UTC, Elias Ross
Details | Diff
Concurrent library enhancements (52.12 KB, patch)
2005-12-04 03:12 UTC, Elias Ross
Details | Diff
Concurrent library enhancements, some other doc fixes (61.17 KB, patch)
2006-02-07 02:20 UTC, Elias Ross
Details | Diff
Concurrent library enhancements, some other doc fixes (61.26 KB, patch)
2006-02-07 02:33 UTC, Elias Ross
Details | Diff
Unit tests for concurrent library, couple bug fixes (14.76 KB, patch)
2006-10-12 17:26 UTC, Elias Ross
Details | Diff
Unit tests for concurrent library, couple bug fixes (14.76 KB, patch)
2006-10-12 17:55 UTC, Elias Ross
Details | Diff
RollingFileAppender and ReentrantReadWriteLock etc. (76.57 KB, patch)
2006-10-13 12:09 UTC, Elias Ross
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Elias Ross 2003-10-27 18:26:28 UTC
I posted this to the user list:


I just came across a deadlock condition in my code brought out by
Log4J.  Here is a simplified view of the objects in play:

class State {
   Logger log1;
  
   synchronized void setState() {
     // Something takes a long time here
     log.debug("hello world");
   }

   synchronized Object getState() {
   }

   public String toString() {
      return "state=" + getState();
   }
}

So, imagine that I call in thread (1)

Logger log2;
State s = new State();
log.debug(s);

And then, in another thread (2), I called setState().  It is in the
middle of setState when this debug statement is fired.

In thread (1), the logger holds a lock on
'org.apache.log4j.spi.RootCategory'.  The renderer attempts construct
the message by calling s.toString(), and toString calls getState().

Thread (1) has to wait for setState in thread (2) to exit.  But setState
can't exit until it has finished logging.



On Fri, 2003-10-24 at 15:26, Elias Ross wrote:
> 
> Here is the stack trace:

org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        - locked <d6655dd0> (a
org.jboss.logging.appender.DailyRollingFileAppender)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        org.apache.log4j.Category.callAppenders(Category.java:187)
        - locked <d52e5db0> (a org.apache.log4j.spi.RootCategory)

I suggest what needs to happen is that the rendering stage has to take
place without holding any locks.  But that would mean that
AppenderSkeleton would have to be re-written (but only slightly):

1.  Holding locks, all major pre-conditions are checked.  (Is the event
filterable?  Is the threshold set too low?)
2.  The message is rendered.
3.  Holding any final locks necessary to actually write/output the
message, the rendered message is then sent to disk/the network/wherever.

I've run into this problem two times:  One time while using JBoss,
another time using a third-party library that uses log4j.  Since more
and more libraries and platforms use log4j (or commons-logging), this
sort of "rendering-interference"--especially on multiple-CPU
machines--is very worrisome.
Comment 1 Elias Ross 2003-12-12 19:49:23 UTC
I'm wondering if this issue has been resolved in Log4j 1.3?  I can lend my
assistance, as I have dealt with multi-processor issues many times on our
Solaris machines.

It is also a performance problem, as you have to hold category locks while the
appender is doing its thing.  If you're appending to two disks, or to JMS and a
Socket, then the IO throughput could be increased dramatically for
multi-processor machines.
Comment 2 Ceki Gulcu 2003-12-18 20:20:10 UTC
Elias, 

This bug is impossible to fix as long as log4j holds any exclusive lock while 
rendering the message object. The way log4j is designed, the rendering of the 
message object is done at the latest possible moment, that is when formatting 
the log message. 

If log4j holds to any lock at that moment (when rendering the object) a 
deadlock will occur. In log4j 1.2.8, the lock is on a logger object. In log4j 
version 1.3, the lock is on the appender itself even if locks on loggers are 
non-exclusive read-write locks.

In short, either we modify our code making log4j thread *unsafe* or you change 
your code. The former is not an option. As such, I am marking this report as 
WONTFIX. 
Comment 3 Elias Ross 2003-12-18 21:13:21 UTC
Created attachment 9633 [details]
Diffs for AppenderSkeleton and WriterAppender
Comment 4 Elias Ross 2003-12-18 22:15:45 UTC
Created attachment 9634 [details]
Changed appender attachable to return a copy-on-write array
Comment 5 Elias Ross 2003-12-18 22:16:24 UTC
Created attachment 9635 [details]
Changed category to not lock on the appender attachable
Comment 6 Elias Ross 2003-12-18 22:27:10 UTC
Okay, you can have your cake and eat it too.  ("Have your synchronization and
avoid deadlocks too"?)

There are a few problems with the AppenderAttachable changes I suggest.  One is
that it's not efficient to maintain a vector and array.  Two, iteration is
effectively doubled, but this can be optimized.  And I also think the cached
array needs to be cleared after every add and remove, just in case an
add+remove+get is done in another thread.  Anyway, I'll leave that up to you to
optimize and remove that boundry (somewhat) easily solved condition.

I'm re-opening in the hope that you will reconsider your conclusion.  I believe
there are more than the two alternatives you suggest.
Comment 7 Elias Ross 2004-09-07 17:42:20 UTC
Ceki,

Have you looked at my proposed changes?  Perhaps you won't change
AppenderSkeleton to be deadlock free, however I would appreciate it if you gave
it some consideration.

My proposed changes work (and aren't impossible) but I can understand wanting to
preserve compatibility so changing AppenderSkeleton might be inappropriate.  How
about creating a AppenderSupport or AppenderBase?
Comment 8 Elias Ross 2004-09-22 22:11:21 UTC
Created attachment 12840 [details]
Changes against Log4J 1.3 CVS
Comment 9 Elias Ross 2004-09-22 22:12:49 UTC
I tried using read-write locks and other techniques, which do indeed
work but are not really backwards compatible, but I think the best
solution I came up with is this: (you can refer to the diffs against CVS)

1.  While synchronized, check on the threshold
2.  Call getRenderedMessage(), ignore the result
3.  While synchronized, check if guard is set or closed
                     ...then call append()

The trick with calling LoggingEvent.getRenderedMessage() early is that
it caches the rendered form of the message.  This is something not
available in 1.2, but will work in 1.3.

Here is the result for those who can't view the attachment:

public abstract class AppenderSkeleton implements Appender, OptionHandler {

...

  public void doAppend(LoggingEvent event) {
    if (!canAppend(event))
      return;
    // Pre-render the message to prevent deadlock
    event.getRenderedMessage();
    doAppend0(event);
  }

  private synchronized void doAppend0(LoggingEvent event) {
    if (closed) {
      LogLog.error(
        "Attempted to append to closed appender named [" + name + "].");
      return;
    }
    try {
      if (guard)
        return;
      guard = true;
      append(event);
    } finally {
      guard = false;
    }
  }

  private synchronized boolean canAppend(LoggingEvent event) {
    if (!isAsSevereAsThreshold(event.getLevel())) {
      return false;
    }
    Filter f = this.headFilter;

FILTER_LOOP:
    while (f != null) {
      switch (f.decide(event)) {
      case Filter.DENY:
        return false;
      case Filter.ACCEPT:
        break FILTER_LOOP;
      case Filter.NEUTRAL:
        f = f.getNext();
      }
    }
    return true;
  }


Comment 10 Yoav Shapira 2004-12-10 19:05:15 UTC
I don't think this is worth doing: if log4j had a serious deadlock situation, 
we'd have heard more about it by now, after years of wide-spread usage.  Of 
course you could come up with contrived code to fit any point you're trying to 
make, but it's just that: contrived.
Comment 11 Elias Ross 2004-12-10 19:39:23 UTC
I feel a bit frustrated because I've been bitten in the ass a few times
encountering this "contrived" problem and I haven't been taken very
seriously pointing this out.  As I have tried to explain, this is
something that has happened before on servers at this company, and it's
something we'd like to have fixed.

If you one day turned on DEBUG and soon watched your server lock up,
you'd be shaking your fist at whoever designed log4j.  It is not just
some annoying bug, it's also something that can result in your server
hanging.  And I'd rather have the server reboot than do that...  I admit
my test case was "contrived", but in the real world people employ
multiple levels of indirection and the actual triggering mechanism can
be quite convoluted.  And it can lurk until one unlucky day somebody
unknowingly turns on DEBUG.

I thought in the quest for helping fix this bug we could improve
concurrency and multi-threading.  Even if you think this bug is dumb,
wouldn't you like to improve in this area?

I sent out some changes that will maintain compatibility and fix this
issue, have you seen them?

I've also talked to several people who use JBoss who have run into this before.  
Comment 12 Hein Meling 2004-12-20 11:22:49 UTC
I support any attempt to fix this bug, as I also have experienced this problem 
on several occasions.  SO PLEASE FIX IT.

Hein Meling


(In reply to comment #11)
> I feel a bit frustrated because I've been bitten in the ass a few times
> encountering this "contrived" problem and I haven't been taken very
> seriously pointing this out.  As I have tried to explain, this is
> something that has happened before on servers at this company, and it's
> something we'd like to have fixed.
> 
> If you one day turned on DEBUG and soon watched your server lock up,
> you'd be shaking your fist at whoever designed log4j.  It is not just
> some annoying bug, it's also something that can result in your server
> hanging.  And I'd rather have the server reboot than do that...  I admit
> my test case was "contrived", but in the real world people employ
> multiple levels of indirection and the actual triggering mechanism can
> be quite convoluted.  And it can lurk until one unlucky day somebody
> unknowingly turns on DEBUG.
> 
> I thought in the quest for helping fix this bug we could improve
> concurrency and multi-threading.  Even if you think this bug is dumb,
> wouldn't you like to improve in this area?
> 
> I sent out some changes that will maintain compatibility and fix this
> issue, have you seen them?
> 
> I've also talked to several people who use JBoss who have run into this 
before.  

Comment 13 Elias Ross 2004-12-31 05:38:11 UTC
From a thread on the JBoss forum:
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=56740

AlanY
Location: Perth, Western Australia
-----------------------------------

Not sure if this is related to your problem ... but we too have had JBoss
hanging during web requests and also other servlet related activities.

Had to use JProfiler to help us work out what was going on. It revealed that
log4j (yes amazing as it seems) is causing blocked threads.

You can refer to http://issues.apache.org/bugzilla/show_bug.cgi?id=24159 in
bugzilla for a rundown on the problem.

Whilst we are not 100% positive that this is our problem I am in the process of
turning off the logging to see if the problem still occurs. Unfortunately this
can take anywhere from 10 minutes to 8 hours of testing as the deadlock is
difficult to isolate in such a big system as ours.

Anyhow - hope this helps and let us know how you get on. 
Comment 14 Mark Womack 2005-07-01 19:56:19 UTC
1.2.12 candidate
Comment 15 Arthur Tsang 2005-07-13 01:02:43 UTC
is there any reason to acquire the RootCategory lock before the renderer 
constructing the message?
Comment 16 Elias Ross 2005-07-15 03:19:21 UTC
I'm the person who filed the bug 1 1/2 years ago...

Despite having to wait, I think that 1.2 is probably too early and
likely too disruptive.  You would have to change the synchronization
behavior of AppenderSkeleton, which would subtly break classes that
extend AppenderSkeleton or its subclasses.

In 1.3, you have already cleaned up the coarse locking in the Category
(Logger) class with respect to adding and removing appenders by using a
read-write lock.  This is a step in the right direction.  My concurrent
appender uses the same read-write class and my AppenderSkeleton (called
ConcurrentAppender) is nearly identical in implementation to the
original, except for a few additional finer-locked objects.

For 1.3, it would be reasonable to include a concurrent appender tree.
In addition to having better performance and less coarse locking (and no
dead-locks), it would be a reasonable parent class for network- and
JDBC-based loggers.  Eventually, they could form the basis of appenders
in a future release.

From working with application services (namely JBoss) for over two
years, it is imperative to have a logging subsystem that is dead-lock
free and high-performance on two and four-processor machines.  Although,
we do not log a huge volume typically, it is necessary for debugging a
live a system.  My original complaint came from debugging a third-party
library on a application system.

If you want a more current version of the concurrent.zip for review, please let
me know.  "Changes against Log4J 1.3 CVS" is out of date.
Comment 17 Mark Womack 2005-07-15 18:49:15 UTC
1.2.12 declined

Leaving open for review in 1.3 work.  Thanks for the comments, Elias.
Comment 18 Rick Genter 2005-11-23 21:52:55 UTC
I also support any attempt to fix this bug. We were bitten by this as well; it
was unexpected that our appender would get called while a "global" lock was held
and ended up causing a deadlock in our highly multithreaded application.

(In reply to comment #12)
> I support any attempt to fix this bug, as I also have experienced this problem 
> on several occasions.  SO PLEASE FIX IT.
> 
> Hein Meling
> 
> 
> (In reply to comment #11)
> > I feel a bit frustrated because I've been bitten in the ass a few times
> > encountering this "contrived" problem and I haven't been taken very
> > seriously pointing this out.  As I have tried to explain, this is
> > something that has happened before on servers at this company, and it's
> > something we'd like to have fixed.
> > 
> > If you one day turned on DEBUG and soon watched your server lock up,
> > you'd be shaking your fist at whoever designed log4j.  It is not just
> > some annoying bug, it's also something that can result in your server
> > hanging.  And I'd rather have the server reboot than do that...  I admit
> > my test case was "contrived", but in the real world people employ
> > multiple levels of indirection and the actual triggering mechanism can
> > be quite convoluted.  And it can lurk until one unlucky day somebody
> > unknowingly turns on DEBUG.
> > 
> > I thought in the quest for helping fix this bug we could improve
> > concurrency and multi-threading.  Even if you think this bug is dumb,
> > wouldn't you like to improve in this area?
> > 
> > I sent out some changes that will maintain compatibility and fix this
> > issue, have you seen them?
> > 
> > I've also talked to several people who use JBoss who have run into this 
> before.  
> 
> 

Comment 19 Curt Arnold 2005-12-03 23:03:39 UTC
My unsubstantiated opinion is that the proposed solution would break the locking
contract so it can't be addressed in a 1.x branch.

From what I can tell, the observed problem is not a regression.  The
coarse-grain locking approach has been in log4j likely forever.  The problem
only manifests itself when you pass an Object (not a String) as the message and
the toString() method itself logs or otherwise acquires a lock on a log4j
object.  If the developer does not pass objects or only pass objects where he
knows that toString() does not acquire locks, the problem does not occur.

If a lock is released to allow a locking toString() to be called, all the
potential code paths that might be executed (possibly including custom appenders
and layouts) must be audited to see if their will be any interaction between the
in-process logging request and logging requests that may be called in the
toString() call or if the release of the lock might allow any other logging
request to enter the pipeline while the original request is suspended.  Much of
the log4j internals aren't thread safe by themselves and depend on the outer
synchronization to keep things safe.

Another approach would be to use a thread with a timeout to call toString().  If
the call blocked, then some message like "Message unavailable timeout while
calling CLASSNAME.toString() " could be created.  It would add overhead to any
call where msg is not a String and all the preconditions are satisified, however
that may not be high relative to the processing cost of most appenders.
Comment 20 Elias Ross 2005-12-04 02:22:13 UTC
Although the *first* comments were suggesting changing AppenderSkeleton, I
have been suggesting in the later comments an alternative solution that does
not break compatibility.

I offer the following suggestion:

Maintain the existing appender class tree as-is.  Introduce a new package
called org.apache.log4j.concurrent which contains deadlock-free and concurrent
appenders.  (These are within an attachment to this bug, I also have newer
versions to offer which have several tweaks.)

Make any new 1.3 appenders (e.g. "log4j.rolling.RollingFileAppender") derive
from log4j.concurrent.FileAppender.

Make the new org.apache.log4j.pattern.PatternConverter thread-safe.  (All
of them for 1.3 are, except the DatePatternConverter.)

Although "Layout" does not indicate thread usage pattern, by convention it
appears thread-unsafe.  I suggest that you fix it by stating that
implementations must be thread-safe and fix the log4j implementations to match.
(Alternatively, assume that this class must be externally locked.  This increases
the locking scope for all usages, although locking may not be necessary.)  (Note
that string buffer reuse does not help performance for mature JVM versions.)

Advantages:  Synchronization convention guaranteed for users who derive from
existing appender classes.  Provides a standard implementation base for
application servers, such as JBoss and Tomcat.

Disadvantages:  Existing appender classes are "mirrored" and increase
maintenence cost.  Additional code bloat.  (Note:  If the classes in this
package are not used, there is no memory impact.)

* Note:  There may be some possible way to create an AppenderSkeleton that uses
two different locking strategies, which are configured by system property, a
configuration key, or by class name.  You would want to have any subclass
implementation by default use the original locking strategy.  I considered this
approach, but I thought it better to clean up the existing AppenderSkeleton
ugliness instead.

* Note:  If somebody would allow it, I would like to have repository access so
that I may check-in and maintain the classes properly myself.  I'm not sure what
the secret handshake is, but I have repository access for some other open
projects, so I believe I'm generally trustworthy.
Comment 21 Elias Ross 2005-12-04 02:24:19 UTC
Comment on attachment 9634 [details]
Changed appender attachable to return a copy-on-write array

Log4j 1.3 now uses a read-write lock so the copy-on-write strategy for the
appender list is probably not necessary.  (It probably does perform better,
however.)
Comment 22 Elias Ross 2005-12-04 03:12:10 UTC
Created attachment 17133 [details]
Concurrent library enhancements

This patch implements the proposal above.
Comment 23 Elias Ross 2005-12-04 03:36:51 UTC
> My unsubstantiated opinion is that the proposed solution would 
> break the locking contract so it can't be addressed in a 1.x branch.

Again, the locking contract only exists for AppenderSkeleton.


Note:  Although 99.99% of the users use strings or generally Object.toString()
as their output message, there is nothing to prevent users from using any other
custom object as well.  For example, I wrote an Appender a while back that would
accept a data structure which contained (essentially) multiple database columns'
worth of data.

Note 2:  Log4j would cause deadlocks for JBoss when a user logged an Object
which triggered a class loading operation.  This is because JBoss itself uses Log4J.

Note 3:  There is a way with 1.3 to have Log4j render "printf"-style messages. 
Currently, Log4J converts it to a string before calling "append", though the
string may or may not be actually logged if a filter is present.  (My particular
application uses filtering based on MDC values, I would greatly benefit from
*not* rendering complicated data structures or calculated values from
Object.toString().)

An optimization of this behavior would be to create temporary object like this:

class FormattedMessage {
  String msg;
  Object param[];
  public String toString() { /* format here */ }
}

If the call to FormattedMessage.toString() was called when holding a lock on
AppenderSkeleton, it would greatly increase deadlock potential for statements
such as:

Logger.debug("Object stuff: {}", obj);

Where "obj" itself called Logger.
Comment 24 Elias Ross 2005-12-04 03:56:40 UTC
> Another approach would be to use a thread with a timeout to call toString().  If
> the call blocked, then some message like "Message unavailable timeout while
> calling CLASSNAME.toString() " could be created.

I don't know if there would be any way to "undo" a deadlock condition.  Perhaps
you could call "Thread.stop" on one of the deadlocked threads.  This has
potential to create additional deadlocks.

> Much of
> the log4j internals aren't thread safe by themselves and depend on the outer
> synchronization to keep things safe.

Many of the "internals" are public classes which are not really internal at all
and need proper documentation and/or locking.

It is irresponsible to not state or establish the contract or convention of how
a library's public classes can (or cannot) used within multiple threads.  Even
though, for example, a "Layout" implementation may not be typically used outside
of a locking context or appender, it is not guaranteed or even implied this is
how it will be used.

The JDK used to be somewhat haphazard about this, but it's important to state at
least if a class is thread-safe or not thread-safe.  It's also important to
state how locking is performed in the thread-safe case (or not necessary due to
design.)

Of course, users generally expect things to work for their multi-threaded
applications.  It's usually good to design with this in mind.  If
multi-threaded, unlocked use is dangerous, it needs to be spelled out.  (Did you
know that if multiple threads modify and access a java.util.HashMap you can
lock-up one thread?  If the user reads the JavaDoc they anticipate bad things
might happen without locking.)
Comment 25 Elias Ross 2006-02-07 02:20:03 UTC
Created attachment 17612 [details]
Concurrent library enhancements, some other doc fixes


Synchronized with revision 375439.
Comment 26 Elias Ross 2006-02-07 02:33:37 UTC
Created attachment 17613 [details]
Concurrent library enhancements, some other doc fixes

Fix small hole in concurrent.WriterAppender.setWriter()
Comment 27 Curt Arnold 2006-02-11 02:16:45 UTC
Eliminated unused variables and documentation fixes committed to log4j trunk committed in rev 
376836 and 376836.

Concurrent appender project added to Sandbox in rev 376902.  Project can be checked out using

svn co http://svn.apache.org/repos/asf/logging/sandbox/log4j/concurrent log4j-concurrent

Can be built with either Maven or Ant but each require log4j 1.3 to be provided.  Ant build:

ant -Dlog4j.jar=/foo/log4j-1.3alpha-8.jar

Maven build requires manually adding a log4j-1.3alpha8 entry to the local repository.  Maven doesn't 
like the hyphen in "1.3alpha-8".
Comment 28 Elias Ross 2006-02-17 18:23:48 UTC
I'll leave it up to the Log4j people to decide if they want these fixes.
Comment 29 Humberto Hernandez 2006-03-31 16:02:14 UTC
It also happended to us when printing a POJO that had to be initialized by
Hibernate. It hanged all the threads in the hole application. The fix was to
convert the object to string before logging it (e.g. log.debug("" + obj); ) We
had to go thru the hole system and modify all the occurrences.

I think the chances of this happening will increase as more libraries use lo
Comment 30 Jerome Lacoste 2006-06-07 14:05:29 UTC
We are hitting the same issue given the following:

- one thread logs a specially internationalized exception class with an
overriden getLocalizedMessage(Locale ) method that formats a message according
to the locale. We reuse the code doing the formatting from another class and
that reused code contains some log4j calls
- another thread triggers a logging simulateneously


We cannot use the "" + object trick as the logging of the object is initiated by
the printStackTrace which delegates to the VectorWriter.println(Object) call (in
our case the Object is the exception).




Our current solution is to disable the logging in our third party library that
does the formatting but this is not satisfying. We can try to remove the logging
from the third party library but that removes some functionality.

We believe the concurrent version of the Appender is the correct way to solve
the issue as given the log below, lock 04dbb288 in Thread 1 below wouldn't be
acquired. I don't see another solution right now.


Details:

Found one Java-level deadlock:
=============================
"Thread 1":
  waiting to lock monitor 0x00a89914 (object 0x04dbb830, a
org.apache.log4j.spi.RootCategory),
  which is held by "Thread 2"
"Thread 2":
  waiting to lock monitor 0x00a89934 (object 0x04dbb288, a
org.apache.log4j.ConsoleAppender),
  which is held by "Thread 1"

Java stack information for the threads listed above:
===================================================
"Thread 1":
        at org.apache.log4j.Category.callAppenders(Category.java:185)
        - waiting to lock <0x04dbb830> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.debug(Category.java:241)
        at com.yyy.MyFormater.format(MyFormater.java:328)
        at com.xxx.MyException.getLocalizedMessage(MyException.java:273)
        at com.xxx.MyException.getLocalizedMessage(MyException.java:259)
        at java.lang.Throwable.toString(Throwable.java:344)
        at com.xxx.MyException.toString(MyException.java:334)
        at org.apache.log4j.spi.VectorWriter.println(ThrowableInformation.java:88)
        at java.lang.Throwable.printStackTrace(Throwable.java:510)
        - locked <0x06028c48> (a org.apache.log4j.spi.VectorWriter)
        at
org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:50)
        at
org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:333)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:295)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        - locked <0x04dbb288> (a org.apache.log4j.ConsoleAppender)
        at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        - locked <0x04dc4c08> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.error(Category.java:303)
        at com.xxx.Controller.handleError(Controller.java:92)
        [...]
"Thread 2":
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:201)
        - waiting to lock <0x04dbb288> (a org.apache.log4j.ConsoleAppender)
        at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        - locked <0x04dbb830> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.error(Category.java:286)
        at com.xxx.OtherController.handleError(OtherController.java:214)
        [...]
Comment 31 Elias Ross 2006-06-30 20:43:05 UTC
*** Bug 33855 has been marked as a duplicate of this bug. ***
Comment 32 Curt Arnold 2006-07-01 03:48:18 UTC
Additional elements of 2006-02-07 2:33 attachment committed in rev 418432.
Comment 33 Curt Arnold 2006-07-27 13:36:54 UTC
Per vote on log4j-dev concluded on 2006-07-25, the concurrent package from the sandbox has been 
moved over to the trunk for further feedback and development.  The concurrent package classes have 
been added to the base log4j.jar and not spun off into a log4j-concurrent.jar as previous suggested.

The tests from the sandbox were not migrated from the sandbox.  DeadlockTest is a test of TTCCLayout 
and not a test of the concurrent package and so should be in the corresponding test case.  In addition, it 
would run out of heap space since it attempts to fire off debug requests as fast as possible for a fixed 
duration.  PerformanceTest is not a unit test.  It would be good to have unit tests that cover the new code, 
but I'm not undertaking that.

Committed in rev 426073. 
Comment 34 srikanth ganapavarapu 2006-09-12 19:14:25 UTC
I support any attempt to fix this bug, as I also have experienced this problem.

We're a large cable company using Tomcat for our app server needs in the back 
office for serving our content and binary streams. During our recent efforts 
to scale some of our apps to multiple markets... we are doing benchmarking of 
our servers and we're running into dead locks.

Upon investigation, we found that the root is log4j as already explained in 
this bug/thread descriptions.

We strongly support fixing this bug.
Comment 35 srikanth ganapavarapu 2006-09-12 19:15:50 UTC
In continuation my earlier remarks... our markets deployment results in close 
to Half a Million investment in hardware for new markets' scaling. With this 
bug blocking us... we're not able to move forward and thinking alternatives!
Comment 36 Elias Ross 2006-10-12 17:26:30 UTC
Created attachment 18997 [details]
Unit tests for concurrent library, couple bug fixes

Here are some unit tests which I created.  Should cover much of the
functionality.
Comment 37 Elias Ross 2006-10-12 17:55:42 UTC
Created attachment 18998 [details]
Unit tests for concurrent library, couple bug fixes

Added test for FileAppender (somehow missed those)
Comment 38 Elias Ross 2006-10-13 12:09:58 UTC
Created attachment 19004 [details]
RollingFileAppender and ReentrantReadWriteLock  etc.

RollingFileAppender addition, also incorporates fixes in attachment 18998 [details]. I
also (for usability) changed the locking strategy to use reentrant locking. My
changes contain code from Doug Lea, which is public domain code:

http://g.oswego.edu/dl/classes/EDU/oswego/cs/dl/util/concurrent/intro.html
Comment 39 Elias Ross 2007-01-28 00:24:03 UTC
Code and tests checked in and integrated with the ANT build.

I'm reasonably happy with the enhancement.

Probably I need more documentation, but there is package.html and JavaDoc for
all classes.  Further enhancements can be added as separate issues.
Comment 40 Curt Arnold 2007-01-30 08:45:05 UTC
Changes committed in rev 500148 appear to be related to this bug, but attributed to bug 19004 which 
isn't a log4j bug.
Comment 41 Curt Arnold 2007-02-01 14:31:20 UTC
Rev 502386 avoided use of Boolean.valueOf(boolean) (added JDK 1.4).  Again misattributed to bug 19004.
Comment 42 Curt Arnold 2007-08-22 19:44:50 UTC
*** Bug 41274 has been marked as a duplicate of this bug. ***