[JIRA] Created: (LBCLASSIC-81) Deadlock while configuring at runtime and requesting a new logger
Deadlock while configuring at runtime and requesting a new logger ----------------------------------------------------------------- Key: LBCLASSIC-81 URL: http://jira.qos.ch/browse/LBCLASSIC-81 Project: logback-classic Issue Type: Bug Components: joran Affects Versions: 0.9.11 Environment: Windows XP Sun JDK 1.5.0_15 Logback 0.9.11 Reporter: Holger Mense Assignee: Logback dev list Priority: Critical In a multithreaded environment a request of a logger instance can led to a deadlock, when another thread tries to apply a new configuration. In GenericConfigurator.doConfigure(InputSource):97 a lock is set on a Context instance. Then the new configuration will be applied. During this, a lock on the logger is required. When now a new logger instance is requested by LoggerFactory, LoggerContext.getLogger(String) is called. The operation sets a lock on the root logger to create a new child logger. At the end the method LoggerContext.incSize() is called to increase the number of entries in the loggerCache. This method is declared as "synchronized" and needs a lock on LoggerContext. Requesting a new logger instance while starting a reconfiguration of logback leds to a deadlock. LoggerContext.incSize() waits for a lock of the context (which is locked by GenericConfigurator), while waiting for lock of logger in Logger.setLevel() - which is locked by LoggerContext. For further information, see the thread dump: ManagedService Update Queue@5, priority=5, in group 'main', status: 'MONITOR' blocks Start Level Event Dispatcher@6 waiting for Start Level Event Dispatcher@6 at ch.qos.logback.classic.Logger.setLevel(Logger.java:188) at ch.qos.logback.classic.joran.action.LoggerAction.begin(LoggerAction.java:63) at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:262) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:136) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:118) at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:36) at ch.qos.logback.core.joran.spi.Interpreter.play(Interpreter.java:321) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:98) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:74) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:48) Start Level Event Dispatcher@6 daemon, priority=5, in group 'main', status: 'MONITOR' blocks ManagedService Update Queue@5 waiting for ManagedService Update Queue@5 at ch.qos.logback.classic.LoggerContext.incSize(LoggerContext.java:153) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:142) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:46) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:161) at org.slf4j.bridge.SLF4JBridgeHandler.getSLF4JLogger(SLF4JBridgeHandler.java:149) at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:234) at java.util.logging.Logger.log(Logger.java:452) at java.util.logging.Logger.doLog(Logger.java:474) at java.util.logging.Logger.log(Logger.java:497) at java.util.logging.Logger.info(Logger.java:1.016) A quick fix is to set a lock on the LoggerContext in LoggerContext.getLogger(String). I am not sure, if this is the best solution, but it seems to work. -- 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-81?page=com.atlassian.jira.plugin.system... ] Holger Mense updated LBCLASSIC-81: ---------------------------------- Attachment: LoggerContext_LockContext.patch Possible patch for fixing the documented deadlock issue.
Deadlock while configuring at runtime and requesting a new logger -----------------------------------------------------------------
Key: LBCLASSIC-81 URL: http://jira.qos.ch/browse/LBCLASSIC-81 Project: logback-classic Issue Type: Bug Components: joran Affects Versions: 0.9.11 Environment: Windows XP Sun JDK 1.5.0_15 Logback 0.9.11 Reporter: Holger Mense Assignee: Logback dev list Priority: Critical Attachments: LoggerContext_LockContext.patch
In a multithreaded environment a request of a logger instance can led to a deadlock, when another thread tries to apply a new configuration. In GenericConfigurator.doConfigure(InputSource):97 a lock is set on a Context instance. Then the new configuration will be applied. During this, a lock on the logger is required. When now a new logger instance is requested by LoggerFactory, LoggerContext.getLogger(String) is called. The operation sets a lock on the root logger to create a new child logger. At the end the method LoggerContext.incSize() is called to increase the number of entries in the loggerCache. This method is declared as "synchronized" and needs a lock on LoggerContext. Requesting a new logger instance while starting a reconfiguration of logback leds to a deadlock. LoggerContext.incSize() waits for a lock of the context (which is locked by GenericConfigurator), while waiting for lock of logger in Logger.setLevel() - which is locked by LoggerContext. For further information, see the thread dump: ManagedService Update Queue@5, priority=5, in group 'main', status: 'MONITOR' blocks Start Level Event Dispatcher@6 waiting for Start Level Event Dispatcher@6 at ch.qos.logback.classic.Logger.setLevel(Logger.java:188) at ch.qos.logback.classic.joran.action.LoggerAction.begin(LoggerAction.java:63) at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:262) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:136) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:118) at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:36) at ch.qos.logback.core.joran.spi.Interpreter.play(Interpreter.java:321) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:98) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:74) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:48) Start Level Event Dispatcher@6 daemon, priority=5, in group 'main', status: 'MONITOR' blocks ManagedService Update Queue@5 waiting for ManagedService Update Queue@5 at ch.qos.logback.classic.LoggerContext.incSize(LoggerContext.java:153) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:142) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:46) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:161) at org.slf4j.bridge.SLF4JBridgeHandler.getSLF4JLogger(SLF4JBridgeHandler.java:149) at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:234) at java.util.logging.Logger.log(Logger.java:452) at java.util.logging.Logger.doLog(Logger.java:474) at java.util.logging.Logger.log(Logger.java:497) at java.util.logging.Logger.info(Logger.java:1.016) A quick fix is to set a lock on the LoggerContext in LoggerContext.getLogger(String). I am not sure, if this is the best solution, but it seems to work.
-- 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-81?page=com.atlassian.jira.plugin.system... ] Ceki Gulcu resolved LBCLASSIC-81. --------------------------------- Fix Version/s: 0.9.14 Resolution: Fixed Fixed in revision 2073
Deadlock while configuring at runtime and requesting a new logger -----------------------------------------------------------------
Key: LBCLASSIC-81 URL: http://jira.qos.ch/browse/LBCLASSIC-81 Project: logback-classic Issue Type: Bug Components: joran Affects Versions: 0.9.11 Environment: Windows XP Sun JDK 1.5.0_15 Logback 0.9.11 Reporter: Holger Mense Assignee: Ceki Gulcu Priority: Critical Fix For: 0.9.14
Attachments: LoggerContext_LockContext.patch
In a multithreaded environment a request of a logger instance can led to a deadlock, when another thread tries to apply a new configuration. In GenericConfigurator.doConfigure(InputSource):97 a lock is set on a Context instance. Then the new configuration will be applied. During this, a lock on the logger is required. When now a new logger instance is requested by LoggerFactory, LoggerContext.getLogger(String) is called. The operation sets a lock on the root logger to create a new child logger. At the end the method LoggerContext.incSize() is called to increase the number of entries in the loggerCache. This method is declared as "synchronized" and needs a lock on LoggerContext. Requesting a new logger instance while starting a reconfiguration of logback leds to a deadlock. LoggerContext.incSize() waits for a lock of the context (which is locked by GenericConfigurator), while waiting for lock of logger in Logger.setLevel() - which is locked by LoggerContext. For further information, see the thread dump: ManagedService Update Queue@5, priority=5, in group 'main', status: 'MONITOR' blocks Start Level Event Dispatcher@6 waiting for Start Level Event Dispatcher@6 at ch.qos.logback.classic.Logger.setLevel(Logger.java:188) at ch.qos.logback.classic.joran.action.LoggerAction.begin(LoggerAction.java:63) at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:262) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:136) at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:118) at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:36) at ch.qos.logback.core.joran.spi.Interpreter.play(Interpreter.java:321) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:98) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:74) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:48) Start Level Event Dispatcher@6 daemon, priority=5, in group 'main', status: 'MONITOR' blocks ManagedService Update Queue@5 waiting for ManagedService Update Queue@5 at ch.qos.logback.classic.LoggerContext.incSize(LoggerContext.java:153) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:142) at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:46) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:161) at org.slf4j.bridge.SLF4JBridgeHandler.getSLF4JLogger(SLF4JBridgeHandler.java:149) at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:234) at java.util.logging.Logger.log(Logger.java:452) at java.util.logging.Logger.doLog(Logger.java:474) at java.util.logging.Logger.log(Logger.java:497) at java.util.logging.Logger.info(Logger.java:1.016) A quick fix is to set a lock on the LoggerContext in LoggerContext.getLogger(String). I am not sure, if this is the best solution, but it seems to work.
-- 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 (2)
-
Ceki Gulcu (JIRA) -
Holger Mense (JIRA)