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. sample_app_trace.txt
        2 kB
        Stefan Wehner
      2. real_app_trace.txt
        4 kB
        Stefan Wehner
      3. deadlock.tgz
        3 kB
        Stefan Wehner

        Issue Links

          Activity

          Hide
          Stefan Wehner added a comment -

          Yep - the sample app seems to work now! Thanks!

          Show
          Stefan Wehner added a comment - Yep - the sample app seems to work now! Thanks!
          Hide
          Ralph Goers added a comment -

          Fixed in revision 1595741. Please verify and close.

          Show
          Ralph Goers added a comment - Fixed in revision 1595741. Please verify and close.
          Hide
          Stefan Wehner added a comment -

          Sample application with its stacktrace when the deadlock occurs.
          Sample stacktrace of our application when the deadlock occurs.

          Show
          Stefan Wehner added a comment - Sample application with its stacktrace when the deadlock occurs. Sample stacktrace of our application when the deadlock occurs.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development