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

[Holger Mense (JIRA)]

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 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