Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.0.13
-
None
Description
We recently introduced sysout-over-slf4j into an application that has been running steadily for a couple of years. No other code changes were made other than adding the sysout-over-slf4j dependency and the one line of code to initialize it. We immediately started seeing nightly deadlocks when Logback went to roll log files. It occurred most nights. Upon removing sysout-over-slf4j, the deadlocks stopped.
I've opened a bug report with the sysout-over-slf4j developer. But since the deadlock is occurring in the Logback I thought there might be a root cause within Logback (that sysout-over-slf4j) was simply exposing.
We've used sysout-over-slf4j in past projects without this issue. A primary difference is that this application does a lot of very rapid logging across numerous threads. (That, and we're using more recent versions of sl4fj and Logback, the most recent version for both).
Below is the pertinent portion of a thread dump. The full thread dump is attached.
Found one Java-level deadlock: "pool-19-thread-1": waiting to lock monitor 0x00007fd5381c2718 (object 0x000000043eb38cd0, a ch.qos.logback.core.rolling.TimeBasedRollingPolicy), which is held by "ipl-doc-processing-pool-0" "ipl-doc-processing-pool-0": waiting to lock monitor 0x000000000085ce50 (object 0x000000043eaf0178, a ch.qos.logback.core.spi.LogbackLock), which is held by "pool-19-thread-1" Java stack information for the threads listed above: "pool-19-thread-1": at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:170) - waiting to lock (a ch.qos.logback.core.rolling.TimeBasedRollingPolicy) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) at ch.qos.logback.classic.Logger.info(Logger.java:599) at uk.org.lidalia.sysoutslf4j.context.LogLevel$3.log(LogLevel.java:62) at uk.org.lidalia.sysoutslf4j.context.LoggerAppenderImpl.log(LoggerAppenderImpl.java:81) at uk.org.lidalia.sysoutslf4j.context.LoggerAppenderImpl.logOrPrint(LoggerAppenderImpl.java:71) at uk.org.lidalia.sysoutslf4j.context.LoggerAppenderImpl.appendAndLog(LoggerAppenderImpl.java:58) at uk.org.lidalia.sysoutslf4j.system.SLF4JPrintStreamDelegate.appendAndLog(SLF4JPrintStreamDelegate.java:76) at uk.org.lidalia.sysoutslf4j.system.SLF4JPrintStreamDelegate.delegatePrint(SLF4JPrintStreamDelegate.java:66) at uk.org.lidalia.sysoutslf4j.system.SLF4JPrintStreamImpl.print(SLF4JPrintStreamImpl.java:246) - locked (a uk.org.lidalia.sysoutslf4j.system.SLF4JPrintStreamImpl) at ch.qos.logback.core.status.OnPrintStreamStatusListenerBase.print(OnPrintStreamStatusListenerBase.java:44) at ch.qos.logback.core.status.OnPrintStreamStatusListenerBase.addStatusEvent(OnPrintStreamStatusListenerBase.java:50) at ch.qos.logback.core.status.OnConsoleStatusListener.addStatusEvent(OnConsoleStatusListener.java:25) at ch.qos.logback.core.BasicStatusManager.fireStatusAddEvent(BasicStatusManager.java:87) - locked (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.BasicStatusManager.add(BasicStatusManager.java:59) at ch.qos.logback.core.spi.ContextAwareBase.addStatus(ContextAwareBase.java:79) at ch.qos.logback.core.spi.ContextAwareBase.addInfo(ContextAwareBase.java:84) at ch.qos.logback.core.rolling.helper.Compressor.gzCompress(Compressor.java:193) at ch.qos.logback.core.rolling.helper.Compressor.compress(Compressor.java:55) at ch.qos.logback.core.rolling.helper.CompressionRunnable.run(CompressionRunnable.java:33) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722) "ipl-doc-processing-pool-0": at ch.qos.logback.core.BasicStatusManager.fireStatusAddEvent(BasicStatusManager.java:86) - waiting to lock (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.BasicStatusManager.add(BasicStatusManager.java:59) at ch.qos.logback.core.spi.ContextAwareBase.addStatus(ContextAwareBase.java:79) at ch.qos.logback.core.spi.ContextAwareBase.addInfo(ContextAwareBase.java:84) at ch.qos.logback.core.rolling.helper.DefaultArchiveRemover.clean(DefaultArchiveRemover.java:68) at ch.qos.logback.core.rolling.TimeBasedRollingPolicy.rollover(TimeBasedRollingPolicy.java:165) at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:138) - locked (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:171) - locked (a ch.qos.logback.core.rolling.TimeBasedRollingPolicy) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:432) at ch.qos.logback.classic.Logger.info(Logger.java:607) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.processCompletedSuccessfullyMessage(AbstractWorkflowStep.java:77) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.processCompletedMessage(AbstractWorkflowProcessorStep.java:47) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.submit(AbstractWorkflowProcessorStep.java:136) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.submit(AbstractWorkflowStep.java:64 at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.send(AbstractWorkflowProcessorStep.java:195) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.submit(AbstractWorkflowProcessorStep.java:140) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.submit(AbstractWorkflowStep.java:64) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.send(AbstractWorkflowProcessorStep.java:195) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.submit(AbstractWorkflowProcessorStep.java:140) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.submit(AbstractWorkflowStep.java:64) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.send(AbstractWorkflowProcessorStep.java:195) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.submit(AbstractWorkflowProcessorStep.java:140) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.submit(AbstractWorkflowStep.java:64) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.send(AbstractWorkflowProcessorStep.java:195) at com.obfuscated.company.name.workflow.step.AbstractWorkflowProcessorStep.submit(AbstractWorkflowProcessorStep.java:140) at com.obfuscated.company.name.workflow.step.AbstractWorkflowStep.submit(AbstractWorkflowStep.java:64) at com.obfuscated.company.name.workflow.processor.DocumentProcessor$1.call(DocumentProcessor.java:83) at com.obfuscated.company.name.workflow.processor.DocumentProcessor$1.call(DocumentProcessor.java:75) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722) Found 1 deadlock. Heap par new generation total 231680K, used 174203K [0x00000003fae00000, 0x000000040a960000, 0x000000043e790000) eden space 205952K, 80% used [0x00000003fae00000, 0x000000040508c3b8, 0x0000000407720000) from space 25728K, 30% used [0x0000000409040000, 0x00000004097d2a18, 0x000000040a960000) to space 25728K, 0% used [0x0000000407720000, 0x0000000407720000, 0x0000000409040000) concurrent mark-sweep generation total 2706712K, used 2318580K [0x000000043e790000, 0x00000004e3ad6000, 0x00000007fae00000) concurrent-mark-sweep perm gen total 83968K, used 53433K [0x00000007fae00000, 0x0000000800000000, 0x0000000800000000)