Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2965

Deadlock between JUL and Disruptor using async logging

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 2.14.0
    • 2.15.0
    • Core, JUL adapter
    • None

    Description

      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!

      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(java.base@11.0.8/Native Method)
      	- parking to wait for  <0x00000007b91be220> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
      	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.8/LockSupport.java:194)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.8/AbstractQueuedSynchronizer.java:885)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.8/AbstractQueuedSynchronizer.java:917)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.8/AbstractQueuedSynchronizer.java:1240)
      	at java.util.concurrent.locks.ReentrantLock.lock(java.base@11.0.8/ReentrantLock.java:267)
      	at java.util.logging.LogManager.ensureLogManagerInitialized(java.logging@11.0.8/LogManager.java:356)
      	at java.util.logging.LogManager.getLogManager(java.logging@11.0.8/LogManager.java:430)
      	at java.util.logging.Logger.demandLogger(java.logging@11.0.8/Logger.java:648)
      	at java.util.logging.Logger.getLogger(java.logging@11.0.8/Logger.java:717)
      	at java.util.logging.Logger.getLogger(java.logging@11.0.8/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(java.logging@11.0.8/LogManager.java:571)
      	at java.util.logging.LogManager$LoggingProviderAccess.demandLoggerFor(java.logging@11.0.8/LogManager.java:2710)
      	at sun.util.logging.internal.LoggingProviderImpl.demandJULLoggerFor(java.logging@11.0.8/LoggingProviderImpl.java:411)
      	at sun.util.logging.internal.LoggingProviderImpl.demandLoggerFor(java.logging@11.0.8/LoggingProviderImpl.java:436)
      	at jdk.internal.logger.DefaultLoggerFinder.getLogger(java.base@11.0.8/DefaultLoggerFinder.java:157)
      	at jdk.internal.logger.LazyLoggers.getLoggerFromFinder(java.base@11.0.8/LazyLoggers.java:389)
      	at jdk.internal.logger.LazyLoggers$1.apply(java.base@11.0.8/LazyLoggers.java:353)
      	at jdk.internal.logger.LazyLoggers$1.apply(java.base@11.0.8/LazyLoggers.java:350)
      	at jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.createLogger(java.base@11.0.8/LazyLoggers.java:278)
      	at jdk.internal.logger.BootstrapLogger.getLogger(java.base@11.0.8/BootstrapLogger.java:956)
      	at jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.platform(java.base@11.0.8/LazyLoggers.java:197)
      	at jdk.internal.logger.LazyLoggers$LazyLoggerAccessor.release(java.base@11.0.8/LazyLoggers.java:232)
      	at jdk.internal.logger.BootstrapLogger$RedirectedLoggers.replaceSurrogateLoggers(java.base@11.0.8/BootstrapLogger.java:1015)
      	at jdk.internal.logger.BootstrapLogger.redirectTemporaryLoggers(java.base@11.0.8/BootstrapLogger.java:1060)
      	at java.util.logging.LogManager.readPrimordialConfiguration(java.logging@11.0.8/LogManager.java:448)
      	at java.util.logging.LogManager$2.run(java.logging@11.0.8/LogManager.java:394)
      	at java.security.AccessController.doPrivileged(java.base@11.0.8/Native Method)
      	at java.util.logging.LogManager.ensureLogManagerInitialized(java.logging@11.0.8/LogManager.java:382)
      	at java.util.logging.LogManager.getLogManager(java.logging@11.0.8/LogManager.java:430)
      	at java.util.logging.Logging.<clinit>(java.logging@11.0.8/Logging.java:50)
      	at java.util.logging.LogManager.getLoggingMXBean(java.logging@11.0.8/LogManager.java:2572)
      	- locked <0x00000007b8f0b388> (a java.lang.Class for java.util.logging.LogManager)
      	at jdk.internal.reflect.NativeMethodAccessorImpl.$$YJP$$invoke0(java.base@11.0.8/Native Method)
      	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.8/NativeMethodAccessorImpl.java)
      	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.8/NativeMethodAccessorImpl.java:62)
      	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.8/DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(java.base@11.0.8/Method.java:566)
      	at sun.management.ManagementFactoryHelper$LoggingMXBeanAccess.getMXBeanImplementation(java.management@11.0.8/ManagementFactoryHelper.java:238)
      	at sun.management.ManagementFactoryHelper$LoggingMXBeanAccess.<init>(java.management@11.0.8/ManagementFactoryHelper.java:254)
      	at sun.management.ManagementFactoryHelper$PlatformLoggingImpl.getInstance(java.management@11.0.8/ManagementFactoryHelper.java:334)
      	at sun.management.ManagementFactoryHelper$PlatformLoggingImpl.<clinit>(java.management@11.0.8/ManagementFactoryHelper.java:337)
      	at sun.management.ManagementFactoryHelper.getPlatformLoggingMXBean(java.management@11.0.8/ManagementFactoryHelper.java:156)
      	at java.lang.management.DefaultPlatformMBeanProvider$9.nameToMBeanMap(java.management@11.0.8/DefaultPlatformMBeanProvider.java:386)
      	at java.lang.management.ManagementFactory.lambda$getPlatformMBeanServer$0(java.management@11.0.8/ManagementFactory.java:487)
      	at java.lang.management.ManagementFactory$$Lambda$30/0x00000008000d3840.apply(java.management@11.0.8/Unknown Source)
      	at java.util.stream.ReferencePipeline$7$1.accept(java.base@11.0.8/ReferencePipeline.java:271)
      	at java.util.stream.ReferencePipeline$2$1.accept(java.base@11.0.8/ReferencePipeline.java:177)
      	at java.util.HashMap$ValueSpliterator.forEachRemaining(java.base@11.0.8/HashMap.java:1675)
      	at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.8/AbstractPipeline.java:484)
      	at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.8/AbstractPipeline.java:474)
      	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(java.base@11.0.8/ForEachOps.java:150)
      	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(java.base@11.0.8/ForEachOps.java:173)
      	at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.8/AbstractPipeline.java:234)
      	at java.util.stream.ReferencePipeline.forEach(java.base@11.0.8/ReferencePipeline.java:497)
      	at java.lang.management.ManagementFactory.getPlatformMBeanServer(java.management@11.0.8/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.
      

      Attachments

        Activity

          People

            ckozak Carter Kozak
            ckozak Carter Kozak
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: