<style>
/* Changing the layout to use less space for mobiles */
@media screen and (max-device-width: 480px), screen and (-webkit-min-device-pixel-ratio: 2) {
#email-body { min-width: 30em !important; }
#email-page { padding: 8px !important; }
#email-banner { padding: 8px 8px 0 8px !important; }
#email-avatar { margin: 1px 8px 8px 0 !important; padding: 0 !important; }
#email-fields { padding: 0 8px 8px 8px !important; }
#email-gutter { width: 0 !important; }
}
</style>
<div id="email-body">
<table id="email-wrap" align="center" border="0" cellpadding="0" cellspacing="0" style="background-color:#f0f0f0;color:#000000;width:100%;">
<tr valign="top">
<td id="email-page" style="padding:16px !important;">
<table align="center" border="0" cellpadding="0" cellspacing="0" style="background-color:#ffffff;border:1px solid #bbbbbb;color:#000000;width:100%;">
<tr valign="top">
<td bgcolor="#003366" style="background-color:#003366;color:#ffffff;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;line-height:1;"><img src="http://jira.qos.ch/s/en_USb9v8he-418945332/850/25/_/jira-logo-scaled.png" alt="" style="vertical-align:top;" /></td>
</tr><tr valign="top">
<td id="email-banner" style="padding:32px 32px 0 32px;">
<table align="left" border="0" cellpadding="0" cellspacing="0" width="100%" style="width:100%;">
<tr valign="top">
<td style="color:#505050;font-family:Arial,FreeSans,Helvetica,sans-serif;padding:0;">
<img id="email-avatar" src="http://jira.qos.ch/secure/useravatar?avatarId=10122" alt="" height="48" width="48" border="0" align="left" style="padding:0;margin: 0 16px 16px 0;" />
<div id="email-action" style="padding: 0 0 8px 0;font-size:12px;line-height:18px;">
<a class="user-hover" rel="markv" id="email_markv" href="http://jira.qos.ch/secure/ViewProfile.jspa?name=markv" style="color:#326ca6;">Mark Vedder</a>
created <img src="http://jira.qos.ch/images/icons/issuetypes/bug.png" height="16" width="16" border="0" align="absmiddle" alt="Bug"> <a style='color:#326ca6;text-decoration:none;' href='http://jira.qos.ch/browse/LOGBACK-891'>LOGBACK-891</a>
</div>
<div id="email-summary" style="font-size:16px;line-height:20px;padding:2px 0 16px 0;">
<a style='color:#326ca6;text-decoration:none;' href='http://jira.qos.ch/browse/LOGBACK-891'><strong>Deadlock in RollingFileAppender</strong></a>
</div>
</td>
</tr>
</table>
</td>
</tr>
<tr valign="top">
<td id="email-fields" style="padding:0 32px 32px 32px;">
<table border="0" cellpadding="0" cellspacing="0" style="padding:0;text-align:left;width:100%;" width="100%">
<tr valign="top">
<td id="email-gutter" style="width:64px;white-space:nowrap;"></td>
<td>
<table border="0" cellpadding="0" cellspacing="0" width="100%">
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Issue Type:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<img src="http://jira.qos.ch/images/icons/issuetypes/bug.png" height="16" width="16" border="0" align="absmiddle" alt="Bug"> Bug
</td>
</tr> <tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Affects Versions:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
1.0.13 </td>
</tr>
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Assignee:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<a class="user-hover" rel="logback-dev@qos.ch" id="email_logback-dev@qos.ch" href="http://jira.qos.ch/secure/ViewProfile.jspa?name=logback-dev%40qos.ch" style="color:#326ca6;">Logback dev list</a>
</td>
</tr> <tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Attachments:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
Thread-Dump.txt </td>
</tr>
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Components:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
logback-core </td>
</tr>
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Created:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
05/Aug/13 3:49 PM
</td>
</tr> <tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Description:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<p style='margin-top:0;margin-bottom:10px;'>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. </p>
<p style='margin-top:0;margin-bottom:10px;'>I've opened a <a href="https://github.com/Mahoney/sysout-over-slf4j/issues/3" class="external-link">bug report</a> 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. </p>
<p style='margin-top:0;margin-bottom:10px;'>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).</p>
<p style='margin-top:0;margin-bottom:10px;'>Below is the pertinent portion of a thread dump. The full thread dump is attached. </p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="code-java">
Found one Java-level deadlock:
<span class="code-quote">"pool-19-thread-1"</span>:
waiting to lock monitor 0x00007fd5381c2718 (object 0x000000043eb38cd0, a ch.qos.logback.core.rolling.TimeBasedRollingPolicy),
which is held by <span class="code-quote">"ipl-doc-processing-pool-0"</span>
<span class="code-quote">"ipl-doc-processing-pool-0"</span>:
waiting to lock monitor 0x000000000085ce50 (object 0x000000043eaf0178, a ch.qos.logback.core.spi.LogbackLock),
which is held by <span class="code-quote">"pool-19-thread-1"</span>
Java stack information <span class="code-keyword">for</span> the threads listed above:
<span class="code-quote">"pool-19-thread-1"</span>:
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.<span class="code-object">Thread</span>.run(<span class="code-object">Thread</span>.java:722)
<span class="code-quote">"ipl-doc-processing-pool-0"</span>:
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.<span class="code-object">Thread</span>.run(<span class="code-object">Thread</span>.java:722)
Found 1 deadlock.
Heap
par <span class="code-keyword">new</span> 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)
</pre>
</div></div>
</td>
</tr>
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Project:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<a style="color:#326ca6;" href="http://jira.qos.ch/browse/LOGBACK">logback</a>
</td>
</tr> <tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Priority:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<img src="http://jira.qos.ch/images/icons/priorities/major.png" height="16" width="16" border="0" align="absmiddle" alt="Major"> Major
</td>
</tr>
<tr valign="top">
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 10px 10px 0;white-space:nowrap;">
<strong style="font-weight:normal;color:#505050;">Reporter:</strong>
</td>
<td style="color:#000000;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:12px;padding:0 0 10px 0;width:100%;">
<a class="user-hover" rel="markv" id="email_markv" href="http://jira.qos.ch/secure/ViewProfile.jspa?name=markv" style="color:#326ca6;">Mark Vedder</a>
</td>
</tr> </table>
</td>
</tr>
</table>
</td>
</tr>
</table>
</td><!-- End #email-page -->
</tr>
<tr valign="top">
<td style="color:#505050;font-family:Arial,FreeSans,Helvetica,sans-serif;font-size:10px;line-height:14px;padding: 0 16px 16px 16px;text-align:center;">
This message is automatically generated by JIRA.<br />
If you think it was sent incorrectly, please contact your JIRA administrators<br />
For more information on JIRA, see: <a style='color:#326ca6;' href='http://www.atlassian.com/software/jira'>http://www.atlassian.com/software/jira</a>
</td>
</tr>
</table><!-- End #email-wrap -->
</div><!-- End #email-body -->