[
http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11171#action_11171
]
Joern Huxhorn commented on LBCLASSIC-133:
-----------------------------------------
As with LBCORE-99, this would vanish if LoggingEvent was a dumb data-type as
suggested in LBCLASSIC-45.
> 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
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
