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

[Ralph Goers]

Create a Jira issue.  If you really want it fixed create a patch and  
add it to the issue. That isn't a guarantee, but it is more likely to  
get attention if you have already done most of the work.

Ralph

On Jun 5, 2009, at 2:56 PM, Olivier Cailloux wrote:

> Chris Miller a écrit :
>> Ah I see, I hadn't looked at your code closely enough so failed to
>> realise it was your toString() implementation that was grabbing the
>> lock, rather than Logback itself. That makes a lot more sense of  
>> course!
>>
>> I don't think there's any solution from your side other than to  
>> rework
>> the locking or call worker.toString() yourself, as you have  
>> indicated.
>>
>> So yes I agree with your conclusion, Logback should be evaluating the
>> toString() call before it grabs any internal locks. This should solve
>> the problem plus potentially improve performance of Logback when
>> multiple threads are writing, without any obvious downside. After a
>> quick glance at the Logback code though this may not be a
>> straightforward change, since the worker object gets treated as an
>> Object/Object[] until right at the last minute.
>
> Do you think I should file a request for improvement about this? It  
> does
> not seem like Ceki is reading this thread... What's the preferred  
> way to
> go about suggestions for change in the code for the logback project?
> Olivier
>
>>
>>> 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
>>> _______________________________________________
>>> Logback-user mailing list
>>> Logback-user at qos.ch
>>> http://qos.ch/mailman/listinfo/logback-user
>>
>>
>>
>> _______________________________________________
>> Logback-user mailing list
>> Logback-user at qos.ch
>> http://qos.ch/mailman/listinfo/logback-user
>
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://qos.ch/mailman/listinfo/logback-user