Re: X-IMail-SPAM-SPF-Fail Re: Log4j 1.2.x deadlock, bug or faulty usage?

[Frank Karlstrom <ka...@corporater.com>]

Curt Arnold wrote:
>
> On Oct 20, 2008, at 8:27 AM, Frank Karlstrom wrote:
>
>> We are experiencing deadlocks on our server.
>>
>> We have tested with log4j version 1.2.8 up to and including 1.2.15
>>
>> We have identified that cause to be a log statement inside a 
>> synchronized block,
>> which is called from different threads.
>>
>> We have attached to very simplified classes, to reproduce the 
>> deadlock. Our framework is a lot more complex, where log4j can be 
>> called indirectly with reflection, not neccessarily by us, but from 
>> third party libraries etc.
>>
>> The deadlock can be reproduced always.
>>
>> Is our usage (or library usage) of log4j faulty, or is it a bug?
>>
>
> The example provided results in a logging request being made during 
> the toString() method of a message parameter.  If you pass an 
> arbitrary object as a message, you have to insure that it does not 
> make any log4j logging requests in the evaluation of toString().  This 
> is a known weakness of log4j 1.x, but can not be addressed outside of 
> a major version change.  It is an issue in the log4j 2.0 JIRA which 
> lists requirements and wishes for log4j 2.0 development 
> (https://issues.apache.org/jira/browse/LOG4J2-8).
>

Ok, for our purposes we have somewhat "resolved" the issue, others 
experiencing the same issue can probably use the same techinque.
since we are using commons-logging as a facade to log4j, we have 
extended commons-logging to always prerender the message and calling 
toString() on the message before sending it further down to log4j.

The deadlock occured on us when we sent an infomessage to log4j with an 
object containing the current state of the application. further down 
after going throught spring, jackrabbit, a custom proxy layer and 
ehcache, the application deadlocked. Reason? We were logging the info of 
an object, and ehcache of course uses logging and synchronization, thus 
deadlocking with the rootlogger locked. As one can see, this is not a 
happy situation, as the rest of the application also uses logging, and 
the whole application silently dies, with no logs indicating what have 
happended. Only a forentic evidence of the stackdump was available to 
indicate that the logging system had deadlocked.


We have read the issue 
https://issues.apache.org/bugzilla/show_bug.cgi?id=24159, and all other 
duplicated bugs, which appear to be the same issue we are experiencing. 
It clearly states in the comments: "The way log4j is designed, the 
object rendering is done as late as possible".

Can someone enlighten us why it is designed this way?

I bet lots of developers using log4j would be happy if this issue is 
resolved somehow before 2.0 is released. There is no guarantee that some 
popular framework doesn't use log4j in this way, and 
end-users/developers suddenly get deadlocks when going from development 
to production in heavy load, which definentily isn't a happy situation.

Best regards Frank Karlstrøm
Senior developer.