[jira] [Created] (LOG4J2-3333) Classloader deadlock in ThreadContextDataInjector

["Ryan Schmitt (Jira)" <ji...@apache.org>]

Ryan Schmitt created LOG4J2-3333:
------------------------------------

             Summary: 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


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)}}
{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)