[JIRA] Created: (LBCLASSIC-133) Deadlock because of logging
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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] 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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] Olivier Cailloux updated LBCLASSIC-133: --------------------------------------- Attachment: logback-test.xml Config file needed to reproduce the deadlock problem (if no logging, naturally, no 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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] 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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] 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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-133: --------------------------------------
As with LBCORE-99, this would vanish if LoggingEvent was a dumb data-type as suggested in LBCLASSIC-45.
For precision's sake, this bug would be fixed if *all* parts of the logging event were assigned before the appender entered its synchronized block. As a direct consequence, the present issue is *unrelated* to LBCLASSIC-45, that is whether LoggingEvent is smart or dumb. However, if by LoggingEvent being dumb, you actually mean that the assignment of all fields in LoggingEvent before invoking any appenders, then we agree.
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
[ http://jira.qos.ch/browse/LBCLASSIC-133?page=com.atlassian.jira.plugin.syste... ] Joern Huxhorn commented on LBCLASSIC-133: ----------------------------------------- By "dumb" I mean that all critical things like conversion of Object[] => String[] must already have happened. All data contained in LoggingEvent must be completely detached from the application that was originally emitting it. This would likely also include some kind of "deep-clone" concerning Markers since user-provided Markers are explicitly supported, right? All fields should have been initialized when they reach *any* part of the logging system != Logger, exactly. Things like creation of caller data or whether or not ThrowableInfo should contain version info should be configured once, globally, and all appenders should be able to live in the absence of either. I'd suggest to turn both on by default but this should be discussed separately.
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
[ http://jira.qos.ch/browse/LBCORE-102?page=com.atlassian.jira.plugin.system.i... ] Ceki Gulcu moved LBCLASSIC-133 to LBCORE-102: --------------------------------------------- Project: logback-core (was: logback-classic) Key: LBCORE-102 (was: LBCLASSIC-133) Issue Type: Bug (was: Improvement) Affects Version/s: 0.9.9 0.9.10 0.9.11 0.9.12 0.9.13 0.9.14 0.9.15 (was: unspecified)
Deadlock because of logging ---------------------------
Key: LBCORE-102 URL: http://jira.qos.ch/browse/LBCORE-102 Project: logback-core Issue Type: Bug Affects Versions: 0.9.9, 0.9.10, 0.9.11, 0.9.12, 0.9.13, 0.9.14, 0.9.15 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
[ http://jira.qos.ch/browse/LBCORE-102?page=com.atlassian.jira.plugin.system.i... ] Ceki Gulcu updated LBCORE-102: ------------------------------ Parent: LBCORE-62 Issue Type: Sub-task (was: Bug)
Deadlock because of logging ---------------------------
Key: LBCORE-102 URL: http://jira.qos.ch/browse/LBCORE-102 Project: logback-core Issue Type: Sub-task Affects Versions: 0.9.9, 0.9.10, 0.9.11, 0.9.12, 0.9.13, 0.9.14, 0.9.15 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
[ http://jira.qos.ch/browse/LBCLASSIC-139?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu moved LBCORE-102 to LBCLASSIC-139: --------------------------------------------- Project: logback-classic (was: logback-core) Key: LBCLASSIC-139 (was: LBCORE-102)
Deadlock because of logging ---------------------------
Key: LBCLASSIC-139 URL: http://jira.qos.ch/browse/LBCLASSIC-139 Project: logback-classic Issue Type: Sub-task Affects Versions: 0.9.9, 0.9.10, 0.9.11, 0.9.12, 0.9.13, 0.9.14, 0.9.15 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
participants (3)
-
Ceki Gulcu (JIRA) -
Joern Huxhorn (JIRA)
-
Olivier Cailloux (JIRA)