[ https://issues.apache.org/jira/browse/LOG4J2-620?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Stefan Wehner updated LOG4J2-620: --------------------------------- 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: {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} was: 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) > Deadlock on reconfiguration with Appenders that use log4j > --------------------------------------------------------- > > Key: LOG4J2-620 > URL: https://issues.apache.org/jira/browse/LOG4J2-620 > Project: Log4j 2 > Issue Type: Bug > Components: Configurators > Affects Versions: 2.0-rc1 > Reporter: Stefan Wehner > Attachments: deadlock.tgz, real_app_trace.txt, sample_app_trace.txt > > > 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} -- This message was sent by Atlassian JIRA (v6.2#6252) --------------------------------------------------------------------- To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-dev-h...@logging.apache.org