[jira] [Commented] (LOG4J2-620) Deadlock on reconfiguration with Appenders that use log4j

["ASF subversion and git services (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-620?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17200710#comment-17200710 ] 

ASF subversion and git services commented on LOG4J2-620:
--------------------------------------------------------

Commit b68b29986115da7f487e7ee825e11ef95e3366a9 in logging-log4j2's branch refs/heads/release-2.x from Volkan Yazici
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=b68b299 ]

LOG4J2-620 ReconfigurationDeadlockTest rewrite to prevent spurious failures.


> 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
>            Priority: Major
>             Fix For: 2.0-rc2
>
>         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
(v8.3.4#803005)