[logback-dev] [JIRA] Updated: (LBCLASSIC-133) Deadlock because of logging

[Olivier Cailloux (JIRA)]

     [ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Olivier Cailloux updated LBCLASSIC-133:
---------------------------------------

    Attachment: Accessor.java
                DeadlockTest.java
                Worker.java

Example source code test to reproduce the deadlock problem.

> Deadlock because of logging
> ---------------------------
>
>                 Key: LBCLASSIC-133
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-133
>             Project: logback-classic
>          Issue Type: Improvement
>    Affects Versions: unspecified
>            Reporter: Olivier Cailloux
>            Assignee: Logback dev list
>         Attachments: Accessor.java, DeadlockTest.java, logback-test.xml, Worker.java
>
>
> The short story is that in some circumstances, calling "s_logger.debug("Current worker status is: {}.", worker);" creates a deadlock while calling "s_logger.debug("Current worker status is: {}.", worker.toString());" does not. This is because the logger tries to acquire a lock on the worker object *while holding the lock on the logger itself*. It would be a good improvement, IMHO, to logback if the logger did not do that.
> In more details, 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.
> My reasoning:
> 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 the example code and the logging framework do not respect this rule, AFAIU.) If the logging implementation respected this rule, the user of the logging framework would not have to bother about thinking of locking issues *created by the use of the logging framework*, but only to his own locking problems inside his code.
> Currently, the two solutions I see for the logback user to overcome the deadlock issues are both not completely satisfactory:
> - don't use parametrized logging to spare the time of "stringification" of an object when logging and rather always call ".toString()" explicitely, as in the above example ; or
> - quit every lock you hold on your own objects before calling any logging statement. (Very unpractical!)
> A very nice improvement to logback classic (solving this class of problems, AFAIU) would be that logback releases its internal lock before calling the .toString method of the worker object, then locks itself again.
> You will find hereby an example reliably reproducing the deadlock problem (classes Accessor, Worker, and DeadlockTest which has a JUnit4 test case, with the appropriate logback configuration file).
> I don't know if this behavior is a bug or a "feature". If the improvement I suggest is too difficult to implement (or impractical for reasons I didn't think of), then a good improvement would be to document this fact. The possibility of introducing deadlock problems in a program when adding logging statements is something users should be warned against! (And once you have a deadlock problem in your code you don't start looking at the logging statements, so it can take much time to find the cause.)

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira