Carter Kozak created LOG4J2-2965:
------------------------------------
Summary: Deadlock between JUL and Disruptor using async logging
Key: LOG4J2-2965
URL: https://issues.apache.org/jira/browse/LOG4J2-2965
Project: Log4j 2
Issue Type: Bug
Components: Core, JUL adapter
Affects Versions: 2.14.0
Reporter: Carter Kozak
A colleague discovered a reproducible deadlock any time the yourkit profiler is
use while starting one of our services.
I don't think there's really any connection to yourkit beyond using a JUL
logger early in startup. The scenario appears to be:
Threads T1, T2:
T1: non-JUL logger access begins log4j initialization.
T1: creates the AsyncLoggerContext and configuration, enters
AsyncLoggerDisruptor.start holding the object monitor
T2: Requests a JUL logger
T2: JUL hasn't initialized yet, based on system properties the
org.apache.logging.log4j.jul.LogManager is added
T2: The logger receives an "initialized" context, and attempts to start it in
parallel with T1
T2: Reaches AsyncLoggerDisruptor.start and blocks wiating for T1 to release the
lock
T1: Disruptor requests JUL logger "com.lmax.disruptor.FatalExceptionHandler",
but the JUL LogManager lock is held by T2. Oh no!
{code}
Found one Java-level deadlock:
=============================
"main":
waiting for ownable synchronizer 0x00000007b91be220, (a
java.util.concurrent.locks.ReentrantLock$NonfairSync),
which is held by "YJPAgent-Telemetry"
"YJPAgent-Telemetry":
waiting to lock monitor 0x00005620b2f73780 (object 0x00000007bc07ad20, a
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor),
which is held by "main"
Java stack information for the threads listed above:
===================================================
"main":
at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
- parking to wait for <0x00000007b91be220> (a
java.util.concurrent.locks.ReentrantLock$NonfairSync)
at
java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:194)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt([email protected]/AbstractQueuedSynchronizer.java:885)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued([email protected]/AbstractQueuedSynchronizer.java:917)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:1240)
at
java.util.concurrent.locks.ReentrantLock.lock([email protected]/ReentrantLock.java:267)
at
java.util.logging.LogManager.ensureLogManagerInitialized([email protected]/LogManager.java:356)
at
java.util.logging.LogManager.getLogManager([email protected]/LogManager.java:430)
at
java.util.logging.Logger.demandLogger([email protected]/Logger.java:648)
at
java.util.logging.Logger.getLogger([email protected]/Logger.java:717)
at
java.util.logging.Logger.getLogger([email protected]/Logger.java:701)
at
com.lmax.disruptor.FatalExceptionHandler.<clinit>(FatalExceptionHandler.java:27)
at
com.lmax.disruptor.dsl.ExceptionHandlerWrapper.<init>(ExceptionHandlerWrapper.java:8)
at com.lmax.disruptor.dsl.Disruptor.<init>(Disruptor.java:65)
at com.lmax.disruptor.dsl.Disruptor.<init>(Disruptor.java:136)
at
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.start(AsyncLoggerDisruptor.java:108)
- locked <0x00000007bc07ad20> (a
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor)
at
org.apache.logging.log4j.core.async.AsyncLoggerContext.start(AsyncLoggerContext.java:75)
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:194)
at
org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:138)
at
org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:45)
at
org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48)
at
org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:30)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:383)
"YJPAgent-Telemetry":
at
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.start(AsyncLoggerDisruptor.java:83)
- waiting to lock <0x00000007bc07ad20> (a
org.apache.logging.log4j.core.async.AsyncLoggerDisruptor)
at
org.apache.logging.log4j.core.async.AsyncLoggerContext.start(AsyncLoggerContext.java:75)
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:194)
at
org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:138)
at
org.apache.logging.log4j.jul.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:34)
at
org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48)
at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:96)
at
java.util.logging.LogManager.demandSystemLogger([email protected]/LogManager.java:571)
at
java.util.logging.LogManager$LoggingProviderAccess.demandLoggerFor([email protected]/LogManager.java:2710)
at
sun.util.logging.internal.LoggingProviderImpl.demandJULLoggerFor([email protected]/LoggingProviderImpl.java:411)
at
sun.util.logging.internal.LoggingProviderImpl.demandLoggerFor([email protected]/LoggingProviderImpl.java:436)
at
jdk.internal.logger.DefaultLoggerFinder.getLogger([email protected]/DefaultLoggerFinder.java:157)
at
jdk.internal.logger.LazyLoggers.getLoggerFromFinder([email protected]/LazyLoggers.java:389)
at
jdk.internal.logger.LazyLoggers$1.apply([email protected]/LazyLoggers.java:353)
at
jdk.internal.logger.LazyLoggers$1.apply([email protected]/LazyLoggers.java:350)
at
jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.createLogger([email protected]/LazyLoggers.java:278)
at
jdk.internal.logger.BootstrapLogger.getLogger([email protected]/BootstrapLogger.java:956)
at
jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.platform([email protected]/LazyLoggers.java:197)
at
jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.release([email protected]/LazyLoggers.java:232)
at
jdk.internal.logger.BootstrapLogger$RedirectedLoggers.replaceSurrogateLoggers([email protected]/BootstrapLogger.java:1015)
at
jdk.internal.logger.BootstrapLogger.redirectTemporaryLoggers([email protected]/BootstrapLogger.java:1060)
at
java.util.logging.LogManager.readPrimordialConfiguration([email protected]/LogManager.java:448)
at
java.util.logging.LogManager$2.run([email protected]/LogManager.java:394)
at java.security.AccessController.doPrivileged([email protected]/Native
Method)
at
java.util.logging.LogManager.ensureLogManagerInitialized([email protected]/LogManager.java:382)
at
java.util.logging.LogManager.getLogManager([email protected]/LogManager.java:430)
at
java.util.logging.Logging.<clinit>([email protected]/Logging.java:50)
at
java.util.logging.LogManager.getLoggingMXBean([email protected]/LogManager.java:2572)
- locked <0x00000007b8f0b388> (a java.lang.Class for
java.util.logging.LogManager)
at
jdk.internal.reflect.NativeMethodAccessorImpl.$$YJP$$invoke0([email protected]/Native
Method)
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke0([email protected]/NativeMethodAccessorImpl.java)
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke([email protected]/NativeMethodAccessorImpl.java:62)
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke([email protected]/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke([email protected]/Method.java:566)
at
sun.management.ManagementFactoryHelper$LoggingMXBeanAccess.getMXBeanImplementation([email protected]/ManagementFactoryHelper.java:238)
at
sun.management.ManagementFactoryHelper$LoggingMXBeanAccess.<init>([email protected]/ManagementFactoryHelper.java:254)
at
sun.management.ManagementFactoryHelper$PlatformLoggingImpl.getInstance([email protected]/ManagementFactoryHelper.java:334)
at
sun.management.ManagementFactoryHelper$PlatformLoggingImpl.<clinit>([email protected]/ManagementFactoryHelper.java:337)
at
sun.management.ManagementFactoryHelper.getPlatformLoggingMXBean([email protected]/ManagementFactoryHelper.java:156)
at
java.lang.management.DefaultPlatformMBeanProvider$9.nameToMBeanMap([email protected]/DefaultPlatformMBeanProvider.java:386)
at
java.lang.management.ManagementFactory.lambda$getPlatformMBeanServer$0([email protected]/ManagementFactory.java:487)
at
java.lang.management.ManagementFactory$$Lambda$30/0x00000008000d3840.apply([email protected]/Unknown
Source)
at
java.util.stream.ReferencePipeline$7$1.accept([email protected]/ReferencePipeline.java:271)
at
java.util.stream.ReferencePipeline$2$1.accept([email protected]/ReferencePipeline.java:177)
at
java.util.HashMap$ValueSpliterator.forEachRemaining([email protected]/HashMap.java:1675)
at
java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:484)
at
java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474)
at
java.util.stream.ForEachOps$ForEachOp.evaluateSequential([email protected]/ForEachOps.java:150)
at
java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential([email protected]/ForEachOps.java:173)
at
java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234)
at
java.util.stream.ReferencePipeline.forEach([email protected]/ReferencePipeline.java:497)
at
java.lang.management.ManagementFactory.getPlatformMBeanServer([email protected]/ManagementFactory.java:488)
- locked <0x00000007ae871e80> (a java.lang.Class for
java.lang.management.ManagementFactory)
at com.yourkit.runtime.OomeDumper.setVMOption(OomeDumper.java:75)
at com.yourkit.runtime.OomeDumper.enable(OomeDumper.java:49)
at com.yourkit.runtime.TelemetryThread.run(TelemetryThread.java:526)
Found 1 deadlock.
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
