[logback-user] AsyncAppenderBase not flushing queue during JVM shutdown
Michael Reinhold
mike at coursescheduler.io
Thu Mar 6 13:51:44 CET 2014
Hi David,
I forgot to mention this in my original note and it is a good thought, but
yes I have tried to cleanly shutdown Logback. Even when the LogbackContext
stop method is invoked prior to JVM exit, the async queue is not flushed
completely. When Logback is stopped cleanly, the async worker thread exits
the "waiting for events in the queue" while loop and moves on to the "flush
remaining elements from the queue" for loop (confirmed by the info message
when debug is enabled and via breakpoint). Ultimately, because the thread
is a daemon thread - this process is still interrupted by JVM shutdown.
There is no guarantee that the async worker will get enough time to process
all events.
>From a theoretical standpoint, stopping Logback properly does not solve
flushing issues with the AsycAppender in a number of cases (it may be fair
to argue that it should not attempt to cover all of these cases):
- Queue is relatively full or wrapped appender latency is high - the
async worker may not be able to finish processing the queued items between
when the LogbackContext.stop method is invoked and when the JVM actually
exits
- Implicit JVM exit upon end of last user thread - some applications
don't explicitly call System.exit but rather rely on implicit JVM exit. In
that case, where would you cleanly shutdown Logback? It can probably be
done, but would require an application redesign to avoid reliance on
implicit exit or some form of thread tracking thread.
- Shutdown hooks are used to clean up resources - some applications have
components or modules that need to clean up after themselves when the JVM
shuts down. Typically, shutdown hooks are used for this purpose, however
the AsyncAppender's worker thread is unable to process queued events after
shutdown has been initiated (while the shutdown hooks are running). This
also prevents shutdown hooks from being able to log events
- Signal handling on *nix systems - signals can be sent to the
application for a number of reasons, most often to request graceful
shutdown or to terminate something that is non-responsive. If the signal
corresponds to something that generally means "graceful shutdown" on the
host system, normal cleanup routines should execute in the application
(typically implemented as shutdown hooks, so maybe this is the same as the
previous one).
>From a practical standpoint, I am running into the first and the third
scenarios. Even shutting down cleanly, the latency and queue depth can
cause elements to be missed; additionally, I have shutdown hooks that clean
up resources and expect the ability to log events and errors.
My thought is that a modified AsyncAppenderBase implementation could
(optionally) install a shutdown hook that continues watching the queue for
new events. A configurable "queue idle time" could be used to tell the
shutdown hook that it has probably caught all events and can safely
shutdown (not foolproof, I'm still thinking about other ways of handling
it). Additionally, the hook could have a configurable "max processing time"
so that it doesn't keep the JVM alive for an undesirable amount of time
(thinking in the context of automation software where shutdown requests
typically have a max execution time before they are considered as "failed
online").
I hope this helps clarify the scenario I am considering and a proposed
solution!
Regards,
Mike Reinhold
On Wed, Mar 5, 2014 at 5:30 PM, David Roussel
<nabble at diroussel.xsmail.com>wrote:
> Did you try shutting down logback cleanly. Like this
> http://stackoverflow.com/questions/3678755/do-i-need-to-flush-events-when-shutting-down-using-logback
>
> David
>
> On 5 Mar 2014, at 20:44, Michael Reinhold <mike at coursescheduler.io> wrote:
>
> Hi Ceki,
>
> 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.
>
> Looking through the source code for the AsyncAppenderBase, I saw the
> following:
>
> You create the Async sender thread as a Daemon thread
>
>
> addInfo("Setting discardingThreshold to " + discardingThreshold);
> worker.setDaemon(true);
> worker.setName("AsyncAppender-Worker-" + worker.getName());
> // make sure this instance is marked as "started" before staring the
> worker Thread
> super.start();
> worker.start();
>
>
> 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.
>
>
> while (parent.isStarted()) {
> try {
> E e = parent.blockingQueue.take();
> aai.appendLoopOnAppenders(e);
> } catch (InterruptedException ie) {
> break;
> }
> }
>
> addInfo("Worker thread will flush remaining events before exiting.
> ");
> for (E e : parent.blockingQueue) {
> aai.appendLoopOnAppenders(e);
> }
>
> aai.detachAndStopAllAppenders();
>
>
> 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.
>
> From Brian Goetz in Java Concurrency in Practice:
> "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."
>
> 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.
>
> 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.
>
> 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 *x* 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).
>
> Let me know what you think. I'll let you know if I feel that my mockup may
> be viable...
>
> Regards,
>
> Mike Reinhold
>
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
>
>
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20140306/33891089/attachment.html>
More information about the Logback-user
mailing list