[
https://issues.apache.org/jira/browse/LOG4J2-3333?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ryan Schmitt updated LOG4J2-3333:
---------------------------------
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:
{code}
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)
{code}
Additionally, I noticed a thread safety issue in {{LoggerContext}}'s
constructors:
{code:java}
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();
}
{code}
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.
was:
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:
{code}
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)
{code}
Additionally, I noticed a thread safety issue in {{LoggerContext}}'s
constructors:
{code:java}
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();
}
{code}
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.
> Classloader deadlock in ThreadContextDataInjector
> -------------------------------------------------
>
> Key: LOG4J2-3333
> URL: https://issues.apache.org/jira/browse/LOG4J2-3333
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.17.1
> Reporter: Ryan Schmitt
> Priority: Major
>
> 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:
> {code}
> 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)
> {code}
> Additionally, I noticed a thread safety issue in {{LoggerContext}}'s
> constructors:
> {code:java}
> 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();
> }
> {code}
> 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.
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
