<html><head><meta http-equiv="content-type" content="text/html; charset=utf-8"></head><body dir="auto"><div>Did you try shutting down logback cleanly. Like this <a href="http://stackoverflow.com/questions/3678755/do-i-need-to-flush-events-when-shutting-down-using-logback">http://stackoverflow.com/questions/3678755/do-i-need-to-flush-events-when-shutting-down-using-logback</a><br><br>David</div><div><br>On 5 Mar 2014, at 20:44, Michael Reinhold <<a href="mailto:mike@coursescheduler.io">mike@coursescheduler.io</a>> wrote:<br><br></div><blockquote type="cite"><div><div dir="ltr"><div dir="ltr"><div style="font-family:arial,sans-serif;font-size:13px">Hi Ceki, </div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
I am currently using the AsyncAppender in combination with the LogglyAppender from the Logback extensions project. While working on a number of aspects of my application, I found that I was not consistently getting all of the log messages that I expected. In particular, when the application shuts down immediately (or very shortly) after a burst of logging activity, the tail of those log events is often not present in Loggly. From a number of tests, this issue is not restricted to use with the LogglyAppender, but is simply more evident because of the latency involved.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">Looking through the source code for the AsyncAppenderBase, I saw the following:</div><div style="font-family:arial,sans-serif;font-size:13px">
<br></div><div style="font-family:arial,sans-serif;font-size:13px">You create the Async sender thread as a Daemon thread</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
<br></div><div style="font-family:arial,sans-serif;font-size:13px">addInfo("Setting discardingThreshold to " + discardingThreshold);</div><div style="font-family:arial,sans-serif;font-size:13px"> worker.setDaemon(true);</div>
<div style="font-family:arial,sans-serif;font-size:13px"> worker.setName("AsyncAppender-Worker-" + worker.getName());</div><div style="font-family:arial,sans-serif;font-size:13px"> // make sure this instance is marked as "started" before staring the worker Thread</div>
<div style="font-family:arial,sans-serif;font-size:13px"> super.start();</div><div style="font-family:arial,sans-serif;font-size:13px"> worker.start();</div><div style="font-family:arial,sans-serif;font-size:13px"><br>
</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">In the sender thread, if you determine that the parent thread has stopped or the async sender thread has been interrupted, you allow the worker thread to flush remaining log events in the queue.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">while (parent.isStarted()) {</div>
<div style="font-family:arial,sans-serif;font-size:13px"> try {</div><div style="font-family:arial,sans-serif;font-size:13px"> E e = parent.blockingQueue.take();</div><div style="font-family:arial,sans-serif;font-size:13px">
aai.appendLoopOnAppenders(e);</div><div style="font-family:arial,sans-serif;font-size:13px"> } catch (InterruptedException ie) {</div><div style="font-family:arial,sans-serif;font-size:13px"> break;</div>
<div style="font-family:arial,sans-serif;font-size:13px"> }</div><div style="font-family:arial,sans-serif;font-size:13px"> }</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
addInfo("Worker thread will flush remaining events before exiting. ");</div><div style="font-family:arial,sans-serif;font-size:13px"> for (E e : parent.blockingQueue) {</div><div style="font-family:arial,sans-serif;font-size:13px">
aai.appendLoopOnAppenders(e);</div><div style="font-family:arial,sans-serif;font-size:13px"> }</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
aai.detachAndStopAllAppenders();</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
From what I can tell, during JVM shutdown (for a standalone SE instance, the same is probably not true for EE instances with application servers) daemon threads may be terminated without allowing the the AsyncAppenderBase to escape the while loop and proceed onto the queue flush for loop. </div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">From Brian Goetz in Java Concurrency in Practice:</div><div style="font-family:arial,sans-serif;font-size:13px">
"When a thread exits, the JVM performs an inventory of running threads, and if the only threads that are left are daemon threads, it initiates an orderly shutdown. When the JVM halts, any remaining daemon threads are abandoned finally blocks are not executed, stacks are not unwound the JVM just exits. Daemon threads should be used sparingly few processing activities can be safely abandoned at any time with no cleanup. In particular, it is dangerous to use daemon threads for tasks that might perform any sort of I/O. Daemon threads are best saved for "housekeeping" tasks, such as a background thread that periodically removes expired entries from an in-memory cache."</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">To test this, I inserted a break point in the AsyncAppenderBase at the call to addInfo and ran a variety of different scenarios. At no point in time was I able to get the breakpoint to stop at the addInfo line. </div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">I don't think there are any clear cut solutions to this. Making the worker thread a user thread instead of daemon thread has its own implications, particularly that if all other user threads have exited the async threads would keep the JVM instance alive (unless System.exit has been called, in which case I believe that you will still have lost log events even if the async processing thread is not a daemon). It might be possible to create a shutdown hook that does the queue flushing for the async worker - though you may need to consider the possibility of other shutdown hooks wanting to log events as well.</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">I'm currently mocking up a version of the AsyncAppenderBase and AsyncAppender that installs a shutdown hook as described previously. I think a "queue idle time" configuration might be the best way to handle other shutdown hooks adding log events (aka - after processing whatever was in the queue, if no new events are added within <i><b>x</b></i> ms then the shutdown hook can assume nothing else will be adding log events and can exit). An alternative might be to have the shutdown hook query the ThreadMXBean API to determine if other shutdown hooks are still executing and possibly adding log events (though the threads that are expected to be running during shutdown may be not only application specific but also JVM implementation specific... I'm not sure).</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">Let me know what you think. I'll let you know if I feel that my mockup may be viable...</div>
<div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">Regards,</div><div style="font-family:arial,sans-serif;font-size:13px"><br></div><div style="font-family:arial,sans-serif;font-size:13px">
Mike Reinhold</div><div><br></div></div></div>
</div></blockquote><blockquote type="cite"><div><span>_______________________________________________</span><br><span>Logback-user mailing list</span><br><span><a href="mailto:Logback-user@qos.ch">Logback-user@qos.ch</a></span><br><span><a href="http://mailman.qos.ch/mailman/listinfo/logback-user">http://mailman.qos.ch/mailman/listinfo/logback-user</a></span></div></blockquote></body></html>