Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-394

Deadlock while configuring at runtime and requesting a new logger

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 0.9.11
    • Fix Version/s: 0.9.14
    • Component/s: logback-classic
    • Labels:
      None
    • Environment:

      Windows XP
      Sun JDK 1.5.0_15
      Logback 0.9.11

      Description

      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.

        Attachments

          Activity

            People

            • Assignee:
              ceki Ceki Gülcü
              Reporter:
              holger.mense Holger Mense
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: