[logback-user] Best practices to avoid deadlocks while logging

Mon Jun 1 12:06:17 CEST 2009

Hi,

Thank you for your reply.

I agree with your comments on synchronization best practices. I simply 
produced a toy example to illustrate the problem I am encountering in my 
application, but the code is not the one I use in my application. I now 
changed the example to lock on a private lock object (hereby attached). 
I also added a logback-test.xml file because the problem only happen if 
logback indeed logs debug statements, so the configuration file is 
needed to reproduce the problem. Also the "final" on StringBuilder has 
indeed nothing to do with synchronization, it is simply my habit of 
always declaring my variables final when I don't need to change them 
after creation, for code self-documentation and auto-verification purposes.

I also agree on the fact that the deadlock happens because of two 
different orders in locking. One thread ("WorkerThread") locks the 
worker, then wants to acquire a lock on the logger, while the other one 
("AccessorThread") first locks the logger, and while holding the lock, 
tries to acquire a lock on the worker object.

But the problem is not solved by replacing the lock on the worker object 
itself by a lock on an internal lock: the same mechanisms still take 
place. The logger calls, in its internal routine, worker.getStatus(), 
which tries to lock the worker internal lock. Impossible as an other 
thread already holds the lock on the worker internal lock (because it is 
being executing the very same method!).

Please also note that logback does not really decide to lock the worker 
object. It just calls worker.toString(), as is expected from the logging 
statement ("s_logger.debug("Current worker status is: {}.", worker);"). 
And this method transparently locks the worker lock.

The more I think about it, the more I feel that the problem comes from 
the fact that, AFAIU, logback does not release the lock on its internal 
(shared) logger before calling a method on a not controlled, 
externally-provided, potentially shared, object (i.e., worker). Would 
logback 1) call worker.toString(), producing a String, and 2) acquire 
the lock and print the string, then the deadlock would not happen. As is 
illustrated by the fact that replacing the above logging statement by 
the apparently very similar "s_logger.debug("Current worker status (not 
deadlocking) is: {}.", worker.toString());" does not trigger the 
deadlock any more.

I would still be very interested by any proposal to change the attached 
demonstration code to avoid triggering the deadlock (other than 
systematically releasing any internal lock before issuing any logging 
statement, which I hope is not the only solution because not very 
convenient).

Once again thank you for your comments.
Olivier

Chris Miller a écrit :
> What's happening here, as I guess you're aware, is that multiple locks 
> are not being aquired in the same fixed order globally - a situation 
> prone to deadlocking. But on top of that, Logback is unintentially 
> executing a denial-of-service attack on your app by locking the Worker 
> instance. The reason this can happen is because your Worker code is 
> synchronizing on the Worker object itself. That object is exposed to 
> the outside world and therefore you have no control over who else can 
> lock on it and therefore no way to prevent possible deadlocks or a 
> plain denial-of-service.
>
> Best practices is to never use "synchronized(this) { ... }" or 
> synchronize entire methods (which amounts to the same thing) in your 
> code. Instead your Worker class should have a private lock object of 
> its own that you synchronize on. This makes the lock object 
> inaccessible to the outside world and therefore impossible (without 
> malicious reflection at least!) to cause a denial-of-service situation 
> like you are experiencing.
>
> eg:
>
> public class Worker {
> private static final Logger logger = 
> LoggerFactory.getLogger(Worker.class);
> private final Object LOCK = new Object();
>
> public void work() {
> synchronized(LOCK) {
> ...
> logger.info("Did some work...");
> }
> ...
> }
>
> Note that the 'final' is essential for the LOCK object declaration 
> (and really for the logger variable too). Without final, you risk 
> different threads locking on different objects and visibility issues 
> between threads. In your implementation of getStatus() { ... } you 
> declare a final StringBuffer though - I guess you're aware that 
> doesn't have any impact on the threadsafety of your code?
>
>
>> Dear list,
>>
>> I recently had a deadlock problem related to logging and I am
>> wondering if it comes from a problem in the logging framework (I must
>> say I doubt it) or from the way I use logging, in which case I'd like
>> to hear advices about how others avoid this kind of problems.
>>
>> The pattern is the following. (Please see hereby the java classes
>> which
>> might be clearer.)
>> - In a class "Worker", a method "work()" locks the object instance of
>> the class Worker to do some work and calls the logging framework to
>> print the result (while still holding the lock).
>> - In the same class "Worker", an other method "getStatus()" obtains
>> the
>> current status of the object instance of the class Worker and returns
>> it
>> as a String (method used for logging). That method locks the object at
>> some point to make sure it reads consistent internal status
>> information.
>> - In an other class "Accessor", a method "access()" performs some work
>> (not locking anything), then logs the status of an object of the class
>> Worker by using its getStatus() method.
>> Now the deadlock scenario is the following.
>> - A thread "WorkerThread" is executing the method "work()". It has
>> acquired the lock for the Worker object and has not reached the
>> logging
>> statement yet.
>> - An other thread "AccessorThread" is executing the method "access()",
>> and is executing the logging statement.
>> AFAIU, logback console logger has some sort of "central" locking
>> point:
>> when a thread is logging, an other thread may not log in parallel
>> (that
>> seems good as the user does not want his different logging statements
>> to
>> be mixed together)... Thus, the following happens.
>> - AccessorThread has a lock to the Logger, and waits to acquire the
>> Worker lock to execute the synchronized block in getStatus().
>> - WorkerThread is holding that precise lock, and will never release
>> it,
>> because arriving at the logging statement in "work()", it starts
>> waiting
>> for the Logger lock acquired by AccessorThread. These two threads are
>> caught in a deadlock.
>> I feel the problem comes from not respecting the general rule that a
>> block of code holding a lock should not call a method on an externally
>> controlled object (possibly shared with other threads) whose locking
>> behavior is unknown. (Note that both my code and the logging framework
>> do not respect this rule, AFAIK.) So I should not have issued the log
>> statement in my synchronized block in "work()". In my case, I can
>> remove this logging statement from the synchronized block, but it is
>> not clear to me whether it is always possible (or easy) to do so,
>> especially if the thing you want to log depends on an internal state
>> which might change as soon as you release the lock.
>>
>> An other way to solve that problem is to not use the parametrized
>> message system in SLF4J. Indeed, it would disable the possibility of
>> the AccessorThread to try to acquire the lock on Worker while being in
>> the SLF4J method.
>>
>> I am wondering however if there is not a way that slf4j implementation
>> (logback) release the lock on its logger, then gets the Worker lock,
>> then re-acquire the lock on its logger only after having released the
>> Worker lock, so that it has only one lock at a time? I tend to think
>> that it would enable a user of the logging framework to pay no
>> attention of the deadlock possibilities incurred by the logging
>> framework, and to avoid him introducing subtle bugs with logging
>> statements... But I may be wrong and I am not an expert in multithread
>> programming.
>>
>> More generally speaking, what would be the advices from experienced
>> programmers to avoid this problem? How do you log in a multithreading
>> context?
>>
>> Also I am wondering if that (anti-)pattern could be documented on the
>> logback page, to avoid others to do the same mistake as me? Or even on
>> the SLF4J page, if it is not logback-specific?
>>
>> The attached classes provide a test case showing the deadlock
>> scenario. The test fails reliably on my box.
>>
>> Thank you for any help.
>> Olivier
>
>
>
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://qos.ch/mailman/listinfo/logback-user

-------------- next part --------------
A non-text attachment was scrubbed...
Name: Accessor.java
Type: text/x-java
Size: 644 bytes
Desc: not available
URL: <http://qos.ch/pipermail/logback-user/attachments/20090601/ef68bde1/attachment.java>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: DeadlockTest.java
Type: text/x-java
Size: 870 bytes
Desc: not available
URL: <http://qos.ch/pipermail/logback-user/attachments/20090601/ef68bde1/attachment-0001.java>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Worker.java
Type: text/x-java
Size: 956 bytes
Desc: not available
URL: <http://qos.ch/pipermail/logback-user/attachments/20090601/ef68bde1/attachment-0002.java>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logback-test.xml
Type: text/xml
Size: 412 bytes
Desc: not available
URL: <http://qos.ch/pipermail/logback-user/attachments/20090601/ef68bde1/attachment.bin>