[
https://issues.apache.org/jira/browse/LOG4J2-620?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ralph Goers reassigned LOG4J2-620:
----------------------------------
Assignee: Ralph Goers
> 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
> Assignee: Ralph Goers
> 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
