New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sysout-over-slf4j causes deadlock on log rolling #3

Open
Javaru opened this Issue Aug 5, 2013 · 4 comments

Comments

Projects
None yet
4 participants
@Javaru

Javaru commented Aug 5, 2013

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.

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. Below is a thread dump.

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)

@Mahoney

This comment has been minimized.

Show comment
Hide comment
@Mahoney

Mahoney Jan 8, 2014

Owner

I'm really sorry, for some reason Github had stopped emailing notifications to me so I've only just seen this. I'll look into it.

Owner

Mahoney commented Jan 8, 2014

I'm really sorry, for some reason Github had stopped emailing notifications to me so I've only just seen this. I'll look into it.

@Mahoney

This comment has been minimized.

Show comment
Hide comment
@Mahoney

Mahoney May 5, 2014

Owner

Yes, this is a genuine issue - OnConsoleStatusListener is being redirected by sysout-over-slf4j back to Logback and that's causing the deadlock. I'll think about a solution.

Owner

Mahoney commented May 5, 2014

Yes, this is a genuine issue - OnConsoleStatusListener is being redirected by sysout-over-slf4j back to Logback and that's causing the deadlock. I'll think about a solution.

@edpike109

This comment has been minimized.

Show comment
Hide comment
@edpike109

edpike109 Oct 8, 2015

First thanks for writing this. However, I am having the same problem. Took me forever to figure it out because it is somewhat intermittent and apparently I'm not heavy enough to do a thread dump. When the roll fails, the tmp file is created, the original file is deleted and logback says that it is about to zip the file, then hangs. If it fails on root logger, the deadlock is hard and the server has to be rebooted. I am running this in Tomcat 7 as windows service, Java 7 SDK, Windows 7, sysout-overslf4j-1.0.2.jar, slf4j 1.7.7.jar, logback 1.1.2. If I turn off zip compression, it seems to be working fine. If I remove the lidalia listener from server/conf/web.xml, i can use zip compression. All testing is using a size based policy of 3kb and loading a page that populates that logger. I say "seems" because I might just be getting a string of good luck.

edpike109 commented Oct 8, 2015

First thanks for writing this. However, I am having the same problem. Took me forever to figure it out because it is somewhat intermittent and apparently I'm not heavy enough to do a thread dump. When the roll fails, the tmp file is created, the original file is deleted and logback says that it is about to zip the file, then hangs. If it fails on root logger, the deadlock is hard and the server has to be rebooted. I am running this in Tomcat 7 as windows service, Java 7 SDK, Windows 7, sysout-overslf4j-1.0.2.jar, slf4j 1.7.7.jar, logback 1.1.2. If I turn off zip compression, it seems to be working fine. If I remove the lidalia listener from server/conf/web.xml, i can use zip compression. All testing is using a size based policy of 3kb and loading a page that populates that logger. I say "seems" because I might just be getting a string of good luck.

@JWood48

This comment has been minimized.

Show comment
Hide comment
@JWood48

JWood48 Jan 19, 2017

From the logback documentation setting debug=true when configuring logback will send output to system.out (specifically when rolling) using the OnConsoleStatusListener. This causes the deadlock in my case.

Setting debug=false should use the NopStatusListener

http://logback.qos.ch/manual/configuration.html

JWood48 commented Jan 19, 2017

From the logback documentation setting debug=true when configuring logback will send output to system.out (specifically when rolling) using the OnConsoleStatusListener. This causes the deadlock in my case.

Setting debug=false should use the NopStatusListener

http://logback.qos.ch/manual/configuration.html

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment