Major Description
I ran into a deadlock involving ThreadContextDataInjector and the "Thread Context Data Task" background thread. The basic idea is that the "main" thread holds the classloader lock (since log4j2 is initialized during class loading, as a rule) and tries to acquire the provider lock, while the "Thread Context Data Task" thread holds the provider lock and tries to load classes:
Found one Java-level deadlock: ============================= "Thread Context Data Task": waiting to lock monitor 0x00007fde50835958 (object 0x000000077bbf51c8, a org.powermock.core.classloader.MockClassLoader), which is held by "main" "main": waiting for ownable synchronizer 0x0000000773e77ae8, (a java.util.concurrent.locks.ReentrantLock$NonfairSync), which is held by "Thread Context Data Task" Java stack information for the threads listed above: =================================================== "Thread Context Data Task": at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:348) at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:370) at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404) at java.util.ServiceLoader$1.next(ServiceLoader.java:480) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.getServiceProviders(ThreadContextDataInjector.java:85) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.initServiceProviders(ThreadContextDataInjector.java:73) at org.apache.logging.log4j.core.LoggerContext$ThreadContextDataTask.run(LoggerContext.java:785) at java.lang.Thread.run(Thread.java:748) "main": at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000773e77ae8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.initServiceProviders(ThreadContextDataInjector.java:70) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.getProviders(ThreadContextDataInjector.java:285) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.access$000(ThreadContextDataInjector.java:55) at org.apache.logging.log4j.core.impl.ThreadContextDataInjector$ForDefaultThreadContextMap.<init>(ThreadContextDataInjector.java:108) at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createDefaultInjector(ContextDataInjectorFactory.java:91) at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:71) at org.apache.logging.log4j.core.impl.Log4jLogEvent.<clinit>(Log4jLogEvent.java:58) at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:643) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:699) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:716) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:270) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:155) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:47) at org.apache.logging.log4j.LogManager.getContext(LogManager.java:196) at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:137) at org.apache.logging.log4j.jcl.LogAdapter.getContext(LogAdapter.java:40) at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:47) at org.apache.logging.log4j.jcl.LogFactoryImpl.getInstance(LogFactoryImpl.java:40) at org.apache.logging.log4j.jcl.LogFactoryImpl.getInstance(LogFactoryImpl.java:55) at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:685) at com.amazon.coral.service.Context.<clinit>(Context.java:31) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:348) at org.powermock.core.transformers.impl.TestClassTransformer.restoreOriginalConstructorsAccesses(TestClassTransformer.java:261) at org.powermock.core.transformers.impl.TestClassTransformer.transform(TestClassTransformer.java:205) at org.powermock.core.classloader.MockClassLoader.loadMockClass(MockClassLoader.java:251) at org.powermock.core.classloader.MockClassLoader.loadModifiedClass(MockClassLoader.java:180) at org.powermock.core.classloader.DeferSupportingClassLoader.loadClass(DeferSupportingClassLoader.java:68) at java.lang.ClassLoader.loadClass(ClassLoader.java:351) at java.lang.Class.getDeclaredConstructors0(Native Method) at java.lang.Class.privateGetDeclaredConstructors(Class.java:2671) at java.lang.Class.getConstructors(Class.java:1651) at org.junit.runners.model.TestClass.<init>(TestClass.java:47)
Additionally, I noticed a thread safety issue in LoggerContext's constructors:
public LoggerContext(final String name, final Object externalContext, final URI configLocn) {
// ...
Thread runner = new Thread(new ThreadContextDataTask(), "Thread Context Data Task");
runner.setDaemon(true);
runner.start();
}
Since ThreadContextDataTask is non-static, this means that a reference to an unconstructed object (that is, the unfinished LoggerContext) is escaping the thread that is constructing it. This is highly thread-unsafe and can result in undefined behavior. Marking the inner class static would fix the issue.
Attachments
Issue Links
- links to