Log4j 2
  1. Log4j 2
  2. LOG4J2-620

Deadlock on reconfiguration with Appenders that use log4j

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0-rc2
    • Component/s: Configurators
    • Labels:
      None

      Description

      We're using the JDBC appender to log to database and provide connections from a C3P0 pool.
      We're finding deadlocks when reconfiguring the log4j2 configuration under heavy load.
      It seems like C3P0 writes to log4j when getting/returning connections from/to the pool and the application deadlocks.
      I think what happens is: When the appender gets a connection from the pool, the call to log4j from C3P0 notices the configuration change, tries to reconfigure, and waits for all appenders (including itself) to finish...

      To simplify things I've written a small sample application (Maven project) with a custom appender that uses log4j in its append method.
      As you can see the application deadlocks soon (usually on the first reconfiguration)

      You can run it with:
      mvn compile exec:java -Dexec.mainClass=logdeadlock.Test

      It should print a few log messages:

      Log: 19:13:54.689 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 0
      Log: 19:13:55.696 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 1
      Log: 19:13:56.703 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 2
      Log: 19:13:57.709 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 3
      Log: 19:13:58.715 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 4
      2014-04-28 19:13:59,883 DEBUG Reconfiguration started for context java.net.URLClassLoader@2ddf7c93
      ...
      

      And then deadlock after the reconfiguration.

      "logdeadlock.Test.main()" prio=10 tid=0x00007fb38883c800 nid=0x2a38 in Object.wait() [0x00007fb37e80b000]
         java.lang.Thread.State: TIMED_WAITING (on object monitor)
      	at java.lang.Object.wait(Native Method)
      	- waiting on <0x00000007d894be20> (a org.apache.logging.log4j.core.config.LoggerConfig)
      	at org.apache.logging.log4j.core.config.LoggerConfig.waitForCompletion(LoggerConfig.java:382)
      	- locked <0x00000007d894be20> (a org.apache.logging.log4j.core.config.LoggerConfig)
      	at org.apache.logging.log4j.core.config.LoggerConfig.clearAppenders(LoggerConfig.java:225)
      	at org.apache.logging.log4j.core.config.BaseConfiguration.stop(BaseConfiguration.java:228)
      	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:346)
      	- locked <0x00000007d74a0840> (a org.apache.logging.log4j.core.LoggerContext)
      	at org.apache.logging.log4j.core.LoggerContext.onChange(LoggerContext.java:423)
      	- locked <0x00000007d74a0840> (a org.apache.logging.log4j.core.LoggerContext)
      	at org.apache.logging.log4j.core.config.FileConfigurationMonitor.checkConfiguration(FileConfigurationMonitor.java:79)
      	- locked <0x00000007d7bca408> (a org.apache.logging.log4j.core.config.FileConfigurationMonitor)
      	at org.apache.logging.log4j.core.Logger$PrivateConfig.filter(Logger.java:318)
      	at org.apache.logging.log4j.core.Logger.isEnabled(Logger.java:132)
      	at org.apache.logging.log4j.spi.AbstractLogger.isEnabled(AbstractLogger.java:1096)
      	at logdeadlock.SomethingThatUsesLogging.doSomething(SomethingThatUsesLogging.java:15)
      	at logdeadlock.MyAppender.append(MyAppender.java:41)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
      	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
      	at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
      	at org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:577)
      	at logdeadlock.Test.main(Test.java:42)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:606)
      	at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293)
      	at java.lang.Thread.run(Thread.java:744)
      
      1. deadlock.tgz
        3 kB
        Stefan Wehner
      2. sample_app_trace.txt
        2 kB
        Stefan Wehner
      3. real_app_trace.txt
        4 kB
        Stefan Wehner

        Issue Links

          Activity

          Ralph Goers made changes -
          Link This issue relates to LOG4J2-619 [ LOG4J2-619 ]
          Stefan Wehner made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Ralph Goers made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 2.0-rc2 [ 12326292 ]
          Resolution Fixed [ 1 ]
          Ralph Goers made changes -
          Assignee Ralph Goers [ ralph.goers@dslextreme.com ]
          Stefan Wehner made changes -
          Description We're using the JDBC appender to log to database and provide connections from a C3P0 pool.
          We're finding deadlocks when reconfiguring the log4j2 configuration under heavy load.
          It seems like C3P0 writes to log4j when getting/returning connections from/to the pool and the application deadlocks.
          I think what happens is: When the appender gets a connection from the pool, the call to log4j from C3P0 notices the configuration change, tries to reconfigure, and waits for all appenders (including itself) to finish...

          To simplify things I've written a small sample application (Maven project) with a custom appender that uses log4j in its append method.
          As you can see the application deadlocks soon (usually on the first reconfiguration)

          We're using the JDBC appender to log to database and provide connections from a C3P0 pool.
          We're finding deadlocks when reconfiguring the log4j2 configuration under heavy load.
          It seems like C3P0 writes to log4j when getting/returning connections from/to the pool and the application deadlocks.
          I think what happens is: When the appender gets a connection from the pool, the call to log4j from C3P0 notices the configuration change, tries to reconfigure, and waits for all appenders (including itself) to finish...

          To simplify things I've written a small sample application (Maven project) with a custom appender that uses log4j in its append method.
          As you can see the application deadlocks soon (usually on the first reconfiguration)

          You can run it with:
          {{mvn compile exec:java -Dexec.mainClass=logdeadlock.Test}}

          It should print a few log messages:
          {code}
          Log: 19:13:54.689 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 0
          Log: 19:13:55.696 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 1
          Log: 19:13:56.703 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 2
          Log: 19:13:57.709 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 3
          Log: 19:13:58.715 [logdeadlock.Test.main()] ERROR logdeadlock.Test - Test! 4
          2014-04-28 19:13:59,883 DEBUG Reconfiguration started for context java.net.URLClassLoader@2ddf7c93
          ...
          {code}

          And then deadlock after the reconfiguration.

          {code}
          "logdeadlock.Test.main()" prio=10 tid=0x00007fb38883c800 nid=0x2a38 in Object.wait() [0x00007fb37e80b000]
             java.lang.Thread.State: TIMED_WAITING (on object monitor)
          at java.lang.Object.wait(Native Method)
          - waiting on <0x00000007d894be20> (a org.apache.logging.log4j.core.config.LoggerConfig)
          at org.apache.logging.log4j.core.config.LoggerConfig.waitForCompletion(LoggerConfig.java:382)
          - locked <0x00000007d894be20> (a org.apache.logging.log4j.core.config.LoggerConfig)
          at org.apache.logging.log4j.core.config.LoggerConfig.clearAppenders(LoggerConfig.java:225)
          at org.apache.logging.log4j.core.config.BaseConfiguration.stop(BaseConfiguration.java:228)
          at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:346)
          - locked <0x00000007d74a0840> (a org.apache.logging.log4j.core.LoggerContext)
          at org.apache.logging.log4j.core.LoggerContext.onChange(LoggerContext.java:423)
          - locked <0x00000007d74a0840> (a org.apache.logging.log4j.core.LoggerContext)
          at org.apache.logging.log4j.core.config.FileConfigurationMonitor.checkConfiguration(FileConfigurationMonitor.java:79)
          - locked <0x00000007d7bca408> (a org.apache.logging.log4j.core.config.FileConfigurationMonitor)
          at org.apache.logging.log4j.core.Logger$PrivateConfig.filter(Logger.java:318)
          at org.apache.logging.log4j.core.Logger.isEnabled(Logger.java:132)
          at org.apache.logging.log4j.spi.AbstractLogger.isEnabled(AbstractLogger.java:1096)
          at logdeadlock.SomethingThatUsesLogging.doSomething(SomethingThatUsesLogging.java:15)
          at logdeadlock.MyAppender.append(MyAppender.java:41)
          at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
          at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
          at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
          at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
          at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
          at org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:577)
          at logdeadlock.Test.main(Test.java:42)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:606)
          at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293)
          at java.lang.Thread.run(Thread.java:744)
          {code}
          Stefan Wehner made changes -
          Field Original Value New Value
          Attachment deadlock.tgz [ 12642274 ]
          Attachment sample_app_trace.txt [ 12642275 ]
          Attachment real_app_trace.txt [ 12642276 ]
          Stefan Wehner created issue -

            People

            • Assignee:
              Ralph Goers
              Reporter:
              Stefan Wehner
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development