[LOG4J2-620] Deadlock on reconfiguration with Appenders that use log4j

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0-rc1
• Fix Version/s: 2.0-rc2
• Component/s: Configurators
• Assignee: Ralph Goers
• Reporter: Stefan Wehner
• Created: 28/Apr/14 17:11
• Updated: 06/Nov/20 12:44
• Resolved: 19/May/14 04:54

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)

Issue Links

• relates to: LOG4J2-619 Unable to recover after loading corrupted XML