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
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
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
