[
http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11167#action_11167
]
Ceki Gulcu commented on LBCLASSIC-133:
--------------------------------------
For the record, there is what happens when the DeadLock test is run.
Found one Java-level deadlock:
=============================
"AccessorThread":
waiting to lock monitor 0x02a5155c (object 0x22a1cc00, a java.lang.Object),
which is held by "WorkerThread"
"WorkerThread":
waiting to lock monitor 0x02a508c4 (object 0x22a51730, a
ch.qos.logback.core.ConsoleAppender),
which is held by "AccessorThread"
Java stack information for the threads listed above:
===================================================
"AccessorThread":
at
ch.qos.logback.classic.issue.lbclassic133.Worker.getStatus(Worker.java:30)
- waiting to lock <0x22a1cc00> (a java.lang.Object)
at
ch.qos.logback.classic.issue.lbclassic133.Worker.toString(Worker.java:38)
at
org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:270)
at
org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:242)
at
org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:200)
at
ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:284)
at
ch.qos.logback.classic.pattern.MessageConverter.convert(MessageConverter.java:22)
at
ch.qos.logback.classic.pattern.MessageConverter.convert(MessageConverter.java:1)
at
ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:32)
at
ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:110)
at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:132)
at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:1)
at ch.qos.logback.core.WriterAppender.subAppend(WriterAppender.java:261)
at ch.qos.logback.core.WriterAppender.append(WriterAppender.java:114)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:87)
- locked <0x22a51730> (a ch.qos.logback.core.ConsoleAppender)
at
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258)
at
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:412)
at ch.qos.logback.classic.Logger.debug(Logger.java:505)
at
ch.qos.logback.classic.issue.lbclassic133.Accessor.access(Accessor.java:14)
at
ch.qos.logback.classic.issue.lbclassic133.DeadlockTest$2.run(DeadlockTest.java:29)
at java.lang.Thread.run(Thread.java:619)
"WorkerThread":
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
- waiting to lock <0x22a51730> (a ch.qos.logback.core.ConsoleAppender)
at
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258)
at
ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:394)
at ch.qos.logback.classic.Logger.debug(Logger.java:501)
at ch.qos.logback.classic.issue.lbclassic133.Worker.work(Worker.java:21)
- locked <0x22a1cc00> (a java.lang.Object)
at
ch.qos.logback.classic.issue.lbclassic133.DeadlockTest$1.run(DeadlockTest.java:19)
at java.lang.Thread.run(Thread.java:619)
Found 1 deadlock.
> 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
