Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-620

Deadlock on reconfiguration with Appenders that use log4j

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 2.0-rc1
    • 2.0-rc2
    • Configurators
    • 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)
      

      Attachments

        1. deadlock.tgz
          3 kB
          Stefan Wehner
        2. real_app_trace.txt
          4 kB
          Stefan Wehner
        3. sample_app_trace.txt
          2 kB
          Stefan Wehner

        Issue Links

          Activity

            People

              rgoers Ralph Goers
              stefanwehner Stefan Wehner
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: