[logback-dev] [JIRA] Updated: (LBCLASSIC-81) Deadlock while configuring at runtime and requesting a new logger

[Holger Mense (JIRA)]

     [ http://jira.qos.ch/browse/LBCLASSIC-81?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

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 at 5, priority=5, in group 'main', status: 'MONITOR'
>              blocks Start Level Event Dispatcher at 6
>              waiting for Start Level Event Dispatcher at 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 at 6 daemon, priority=5, in group 'main', status: 'MONITOR'
>              blocks ManagedService Update Queue at 5
>              waiting for ManagedService Update Queue at 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