<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8" />
<meta name="viewport" content="width=device-width, initial-scale=1.0, maximum-scale=1.0" /> <base href="https://jira.qos.ch" />
<title>Message Title</title>
</head>
<body class="jira" style="color: #333; font-family: Arial, sans-serif; font-size: 14px; line-height: 1.429">
<table id="background-table" cellpadding="0" cellspacing="0" width="100%" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt; background-color: #f5f5f5; border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<!-- header here -->
<tr>
<td id="header-pattern-container" style="padding: 0px; border-collapse: collapse; padding: 10px 20px">
<table id="header-pattern" cellspacing="0" cellpadding="0" border="0" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<tr>
<td id="header-avatar-image-container" valign="top" style="padding: 0px; border-collapse: collapse; vertical-align: top; width: 32px; padding-right: 8px"> <img id="header-avatar-image" class="image_fix" src="cid:jira-generated-image-avatar-387a7645-d6fc-4cc9-95e0-ab7acd357c21" height="32" width="32" border="0" style="border-radius: 3px; vertical-align: top" />
</td>
<td id="header-text-container" valign="middle" style="padding: 0px; border-collapse: collapse; vertical-align: middle; font-family: Arial, sans-serif; font-size: 14px; line-height: 20px; mso-line-height-rule: exactly; mso-text-raise: 1px"> <a class="user-hover" rel="richardfearn" id="email_richardfearn" href="https://jira.qos.ch/secure/ViewProfile.jspa?name=richardfearn" style="color:#3b73af;; color: #3b73af; text-decoration: none">Richard Fearn</a> <strong>commented</strong> on <a href="https://jira.qos.ch/browse/LOGBACK-1238" style="color: #3b73af; text-decoration: none"><img src="cid:jira-generated-image-static-bug-96862760-f542-4625-9102-e68a9a3bd0c9" height="16" width="16" border="0" align="absmiddle" alt="Bug" /> LOGBACK-1238</a>
</td>
</tr>
</table>
</td>
</tr>
<tr>
<td id="email-content-container" style="padding: 0px; border-collapse: collapse; padding: 0 20px">
<table id="email-content-table" cellspacing="0" cellpadding="0" border="0" width="100%" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt; border-spacing: 0; border-collapse: separate">
<tr>
<!-- there needs to be content in the cell for it to render in some clients -->
<td class="email-content-rounded-top mobile-expand" style="padding: 0px; border-collapse: collapse; color: #fff; padding: 0 15px 0 16px; height: 15px; background-color: #fff; border-left: 1px solid #ccc; border-top: 1px solid #ccc; border-right: 1px solid #ccc; border-bottom: 0; border-top-right-radius: 5px; border-top-left-radius: 5px; height: 10px; line-height: 10px; padding: 0 15px 0 16px; mso-line-height-rule: exactly">
</td>
</tr>
<tr>
<td class="email-content-main mobile-expand " style="padding: 0px; border-collapse: collapse; border-left: 1px solid #ccc; border-right: 1px solid #ccc; border-top: 0; border-bottom: 0; padding: 0 15px 0 16px; background-color: #fff">
<table class="page-title-pattern" cellspacing="0" cellpadding="0" border="0" width="100%" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<tr>
<td style="vertical-align: top;; padding: 0px; border-collapse: collapse; padding-right: 5px; font-size: 20px; line-height: 30px; mso-line-height-rule: exactly" class="page-title-pattern-header-container"> <span class="page-title-pattern-header" style="font-family: Arial, sans-serif; padding: 0; font-size: 20px; line-height: 30px; mso-text-raise: 2px; mso-line-height-rule: exactly; vertical-align: middle"> <a href="https://jira.qos.ch/browse/LOGBACK-1238" style="color: #3b73af; text-decoration: none">Re: RollingFileAppender generating a large numbers of .tmp files</a> </span>
</td>
</tr>
</table>
</td>
</tr>
<tr>
<td id="text-paragraph-pattern-top" class="email-content-main mobile-expand comment-top-pattern" style="padding: 0px; border-collapse: collapse; border-left: 1px solid #ccc; border-right: 1px solid #ccc; border-top: 0; border-bottom: 0; padding: 0 15px 0 16px; background-color: #fff; border-bottom: none; padding-bottom: 0">
<table class="text-paragraph-pattern" cellspacing="0" cellpadding="0" border="0" width="100%" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt; font-family: Arial, sans-serif; font-size: 14px; line-height: 20px; mso-line-height-rule: exactly; mso-text-raise: 2px">
<tr>
<td class="text-paragraph-pattern-container mobile-resize-text " style="padding: 0px; border-collapse: collapse; padding: 0 0 10px 0">
<p style="margin: 10px 0 0 0">I think this problem has got worse with 1.1.7 because as time goes on, Logback is being changed to execute tasks using a per-context <tt>ExecutorService</tt> backed by a 2-thread pool.</p>
<p style="margin: 10px 0 0 0">We use a central log server that both receives log events from other processes (through a <tt>SimpleSocketServer</tt>) and can forward those log events to other consumers (using a <tt>ServerSocketAppender</tt>). (The consumers are usually standalone log panels, running on different machines.)</p>
<p style="margin: 10px 0 0 0">In our scenario the problem is that the task that accepts new connections to the <tt>ServerSocketAppender</tt> is submitted to the context executor. <tt>ServerSocketAppender</tt> extends <tt>AbstractServerSocketAppender</tt>, which does:</p>
<div class="preformatted panel" style="border-width: 1px;; border: 1px solid #ccc; background: #f5f5f5; font-size: 12px; line-height: 1.333; font-family: monospace; border: 1px solid #ccc; -moz-border-radius: 3px 3px 3px 3px; border-radius: 3px 3px 3px 3px; margin: 9px 0">
<div class="preformattedContent panelContent" style="padding: 9px 12px">
<pre style="margin: 10px 0 0 0; max-height: 30em; overflow: auto; white-space: pre-wrap; word-wrap: normal; white-space: pre; word-break: normal; word-wrap: break-word; word-break: break-word; white-space: pre-wrap">runner = createServerRunner(listener, getContext().getExecutorService());
runner.setContext(getContext());
getContext().getExecutorService().execute(runner);
</pre>
</div>
</div>
<p style="margin: 10px 0 0 0">and you can see this in a thread dump:</p>
<div class="preformatted panel" style="border-width: 1px;; border: 1px solid #ccc; background: #f5f5f5; font-size: 12px; line-height: 1.333; font-family: monospace; border: 1px solid #ccc; -moz-border-radius: 3px 3px 3px 3px; border-radius: 3px 3px 3px 3px; margin: 9px 0">
<div class="preformattedContent panelContent" style="padding: 9px 12px">
<pre style="margin: 10px 0 0 0; max-height: 30em; overflow: auto; white-space: pre-wrap; word-wrap: normal; white-space: pre; word-break: normal; word-wrap: break-word; word-break: break-word; white-space: pre-wrap">"logback-1" #9 daemon prio=5 os_prio=0 tid=0x00007fcc0c239800 nid=0x42e6 runnable [0x00007fcbf7dfc000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at ch.qos.logback.core.net.server.ServerSocketListener.acceptClient(ServerSocketListener.java:44)
at ch.qos.logback.core.net.server.ConcurrentServerRunner.run(ConcurrentServerRunner.java:132)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
</pre>
</div>
</div>
<p style="margin: 10px 0 0 0">When a connection to the <tt>ServerSocketAppender</tt> is accepted, the task for that connection is also submitted to the context executor. In <tt>ConcurrentServerRunner</tt>:</p>
<div class="preformatted panel" style="border-width: 1px;; border: 1px solid #ccc; background: #f5f5f5; font-size: 12px; line-height: 1.333; font-family: monospace; border: 1px solid #ccc; -moz-border-radius: 3px 3px 3px 3px; border-radius: 3px 3px 3px 3px; margin: 9px 0">
<div class="preformattedContent panelContent" style="padding: 9px 12px">
<pre style="margin: 10px 0 0 0; max-height: 30em; overflow: auto; white-space: pre-wrap; word-wrap: normal; white-space: pre; word-break: normal; word-wrap: break-word; word-break: break-word; white-space: pre-wrap">T client = listener.acceptClient();
[...]
executor.execute(new ClientWrapper(client));
</pre>
</div>
</div>
<p style="margin: 10px 0 0 0">and this task can also be seen in a thread dump:</p>
<div class="preformatted panel" style="border-width: 1px;; border: 1px solid #ccc; background: #f5f5f5; font-size: 12px; line-height: 1.333; font-family: monospace; border: 1px solid #ccc; -moz-border-radius: 3px 3px 3px 3px; border-radius: 3px 3px 3px 3px; margin: 9px 0">
<div class="preformattedContent panelContent" style="padding: 9px 12px">
<pre style="margin: 10px 0 0 0; max-height: 30em; overflow: auto; white-space: pre-wrap; word-wrap: normal; white-space: pre; word-break: normal; word-wrap: break-word; word-break: break-word; white-space: pre-wrap">"logback-2" #13 daemon prio=5 os_prio=0 tid=0x00007ff994001800 nid=0x48aa waiting on condition [0x00007ff9e9484000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076db192d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
at ch.qos.logback.core.net.server.RemoteReceiverStreamClient.run(RemoteReceiverStreamClient.java:106)
at ch.qos.logback.core.net.server.ConcurrentServerRunner$ClientWrapper.run(ConcurrentServerRunner.java:209)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
</pre>
</div>
</div>
<p style="margin: 10px 0 0 0">With one client connected, two long-running tasks are being executed by the executor, meaning both threads in the pool are busy, and new tasks that are submitted will be queued, but not executed immediately.</p>
<p style="margin: 10px 0 0 0">Log file compression is also a task that gets submitted to the executor. From <tt>Compressor</tt>:</p>
<div class="preformatted panel" style="border-width: 1px;; border: 1px solid #ccc; background: #f5f5f5; font-size: 12px; line-height: 1.333; font-family: monospace; border: 1px solid #ccc; -moz-border-radius: 3px 3px 3px 3px; border-radius: 3px 3px 3px 3px; margin: 9px 0">
<div class="preformattedContent panelContent" style="padding: 9px 12px">
<pre style="margin: 10px 0 0 0; max-height: 30em; overflow: auto; white-space: pre-wrap; word-wrap: normal; white-space: pre; word-break: normal; word-wrap: break-word; word-break: break-word; white-space: pre-wrap">public Future<?> asyncCompress(String nameOfFile2Compress, String nameOfCompressedFile, String innerEntryName) throws RolloverFailure {
CompressionRunnable runnable = new CompressionRunnable(nameOfFile2Compress, nameOfCompressedFile, innerEntryName);
ExecutorService executorService = context.getExecutorService();
Future<?> future = executorService.submit(runnable);
return future;
}
</pre>
</div>
</div>
<p style="margin: 10px 0 0 0">So one client connected to a <tt>ServerSocketAppender</tt> means that log files won't be compressed when they are rolled over.</p>
<p style="margin: 10px 0 0 0">I'll attach an example config that can be used to test this.</p>
</td>
</tr>
</table>
</td>
</tr>
<tr>
<td class="email-content-main mobile-expand " style="padding: 0px; border-collapse: collapse; border-left: 1px solid #ccc; border-right: 1px solid #ccc; border-top: 0; border-bottom: 0; padding: 0 15px 0 16px; background-color: #fff">
<table id="actions-pattern" cellspacing="0" cellpadding="0" border="0" width="100%" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt; font-family: Arial, sans-serif; font-size: 14px; line-height: 20px; mso-line-height-rule: exactly; mso-text-raise: 1px">
<tr>
<td id="actions-pattern-container" valign="middle" style="padding: 0px; border-collapse: collapse; padding: 10px 0 10px 24px; vertical-align: middle; padding-left: 0">
<table align="left" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<tr>
<td class="actions-pattern-action-icon-container" style="padding: 0px; border-collapse: collapse; font-family: Arial, sans-serif; font-size: 14px; line-height: 20px; mso-line-height-rule: exactly; mso-text-raise: 0px; vertical-align: middle"> <a href="https://jira.qos.ch/browse/LOGBACK-1238#add-comment" target="_blank" title="Add Comment" style="color: #3b73af; text-decoration: none"> <img class="actions-pattern-action-icon-image" src="cid:jira-generated-image-static-comment-icon-aea962da-5664-4453-8f7c-2ba49e6eb67a" alt="Add Comment" title="Add Comment" height="16" width="16" border="0" style="vertical-align: middle" /> </a>
</td>
<td class="actions-pattern-action-text-container" style="padding: 0px; border-collapse: collapse; font-family: Arial, sans-serif; font-size: 14px; line-height: 20px; mso-line-height-rule: exactly; mso-text-raise: 4px; padding-left: 5px"> <a href="https://jira.qos.ch/browse/LOGBACK-1238#add-comment" target="_blank" title="Add Comment" style="color: #3b73af; text-decoration: none">Add Comment</a>
</td>
</tr>
</table>
</td>
</tr>
</table>
</td>
</tr>
<!-- there needs to be content in the cell for it to render in some clients -->
<tr>
<td class="email-content-rounded-bottom mobile-expand" style="padding: 0px; border-collapse: collapse; color: #fff; padding: 0 15px 0 16px; height: 5px; line-height: 5px; background-color: #fff; border-top: 0; border-left: 1px solid #ccc; border-bottom: 1px solid #ccc; border-right: 1px solid #ccc; border-bottom-right-radius: 5px; border-bottom-left-radius: 5px; mso-line-height-rule: exactly">
</td>
</tr>
</table>
</td>
</tr>
<tr>
<td id="footer-pattern" style="padding: 0px; border-collapse: collapse; padding: 12px 20px">
<table id="footer-pattern-container" cellspacing="0" cellpadding="0" border="0" style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<tr>
<td id="footer-pattern-text" class="mobile-resize-text" width="100%" style="padding: 0px; border-collapse: collapse; color: #999; font-size: 12px; line-height: 18px; font-family: Arial, sans-serif; mso-line-height-rule: exactly; mso-text-raise: 2px">
This message was sent by Atlassian JIRA <span id="footer-build-information">(v6.4.12#64027-<span title="e3691cc1283c0f3cef6d65d3ea82d47743692b57" data-commit-id="e3691cc1283c0f3cef6d65d3ea82d47743692b57}">sha1:e3691cc</span>)</span>
</td>
<td id="footer-pattern-logo-desktop-container" valign="top" style="padding: 0px; border-collapse: collapse; padding-left: 20px; vertical-align: top">
<table style="border-collapse: collapse; mso-table-lspace: 0pt; mso-table-rspace: 0pt">
<tr>
<td id="footer-pattern-logo-desktop-padding" style="padding: 0px; border-collapse: collapse; padding-top: 3px"> <img id="footer-pattern-logo-desktop" src="cid:jira-generated-image-static-footer-desktop-logo-8318590a-e67b-429e-a650-da8a6ede177c" alt="Atlassian logo" title="Atlassian logo" width="169" height="36" class="image_fix" />
</td>
</tr>
</table>
</td>
</tr>
</table>
</td>
</tr>
</table>
</body>
</html>