[logback-user] how to graceful shutdown logback with AsyncAppenders and without immediateFlush

[Gena Makhomed]

On 19.03.2014 16:51, Michael Reinhold wrote:

> I agree that logging should be reliable and fast, however this is not
> always possible with some targets - particular cloud logging services
> such as Loggly, Logentries, Papertrail, Splunk Storm, Loggr, etc.

However it is possible to make logging even to remote services
reliable and fast, from application code point of view. Making
process of logging to remote services true asynchronous:

- write all log events to ordinary log file at local file system

- in background (daemon) thread scan log files, check at remote
service which files should be synced and in which offset, after
this first "handshake" - just monitor tail of log file, and all
new events asynchronously read from log file and send to remote
log collection service, even fashionable cloud logging services

In this case - logging events to log file and sending events
to remote logging service are asynchronous, and without event
lost even after fast application restart, even with big queue
of not yet reported to remote service log events in the log.

Algorithm the same as in case of AsyncAppender from logback,
but as temporary storage for queued events used persistent storage
(disk subsystem) instead of java heap - this is only one difference.

Existing AsyncAppender not help in case of temporary network failure,
you will get event lost, - there is not guaranteed log events delivery.

With true asynchronous conversation with remote logging service,
(with queue located at persistent storage service, not in java heap)
all events queued in log file will be send to remote logging service,
without lost in events delivery process. (fast, asynchronous, reliable)

> The AsyncAppender was created to prevent target latency from impacting
> application performance by buffering the events and processing them
> asynchronously.

Yes, and AsyncAppender even help in case of using RollingFileAppender,
allow application to process client request at maximum available speed,
with all logging work with log file executed in separate daemon thread.

If not use AsyncAppender before RollingFileAppender - all logging
work with underlying OutputStream are done in application thread,
and time wasted for logging instead of client request processing.

> You describe a number of situations in which the discussed ShutdownHook
> implementations don't work. I don't want to argue a bunch of
> hypothetical scenarios on the mailing list, these were just descriptions
> of how it is possible to extend the ShutdownHooks in Logback. Please
> understand, I am not proposing that those are the (or the only)
> ShutdownHooks that get implemented - this was merely attempting to
> describe how different shutdown hooks could be developed that best meet
> different needs. Additionally, it was intended to show how the user
> could develop something that meets their specific application needs in
> the event that one of the Logback provided ShutdownHooks is not
> sufficient. Those examples may have been simplistic, but more complex
> options are possible. For instance, an InstrumentationShutdownHook that
> adds instrumentation into the Logback API to determine when it is safe
> to shutdown. Or a HeapWalkerShutdownHook that investigates the JVM heap
> to find Logger references. Or a ThreadHeuristicShutdownHook that
> analyzes the threads present in the JVM to determine when the Logback
> shutdown hook is the last relevant thread remaining. The point is that
> the ShutdownHookAction framework can be used to extend Logback's
> built-in shutdown cleanup functionality, either by the Logback team
> itself, by contributors to the project, or by the end application developer.

Such approach imply minimally invasive changes to Logback
and forcing users to write own non-trivial ShutdownHooks.

If implement my proposed solution - user not need write any code at all.
User just need to answer to one simple question: application shutdown
means JVM shutdown (for example in case of UNIX service/daemon) or
application shutdown possible without JVM shutdown (OSGi, webapp, etc)

if application shutdown == JVM shutdown user add to logback.xml
one line, for enabling built-in logback shutdown hook,
which after activation turn logback from "maximum speed"
to "maximum safe" mode of work, and in this case
logback will be ready for forthcoming JVM shutdown.
event lost in this case will be minimal, because
after logback shutdown hook complete work -
all events from AsyncAppender queue will be
written to its underlying appender, queue size set to 0,
and AsyncAppender will be switched into transparent sync mode.
also, all appenders switched to immediateFlush = true mode.
in this case each log event from any shutdown hook will be
guaranteed to be written into log file.
without any additional work from user.

if application shutdown possible without JVM shutdown,
user just need to activate proper context listener
for graceful shutdown of logback via LoggerContext.stop

if none on this two methods of graceful shutdown activated -
logback can write warning about misconfiguration to StatusManager.

for user - logback will work very easy,
fast and reliable without any headache.

call LoggerContext.stop only required for case
when application shutdown != JVM shutdown,

and if application shutdown == JVM shutdown
calling LoggerContext.stop is not the best solution,
because it can lead to logging events lost.

> For your scenario in particular: you say that you have shutdown hooks
> installed by both your code and by third party libraries you use,
> correct?

Yes.

> Are the Shutdown hooks inserted by your code and by the
> libraries deterministic in terms of name or quantity?

No.

> If so, you could
> whitelist those threads call LoggerContext.stop when they have exited
> (which you can confirm during your shutdown hook via either the Thread
> API or the ThreadMXBean API). If the shutdown hooks are not
> deterministic in quantity or name, you can use the protected
> java.lang.ApplicationShutdownHooks
> <http://stackoverflow.com/questions/6865408/i-need-to-list-the-hooks-registered-with-java-lang-applicationshutdownhooks>
> class during your application startup to determine the hooks that are
> installed and find the names of those hooks. Then your shutdown hook can
> check the status of those threads and call LoggerContext.stop once they
> have finished processing (excluding the Logbcack Shutdown hook of
> course). Actually, after thinking this through, it is possible that this
> type of a shutdown hook will work for my application as well...

Yes, this is working solution, but it is very uncomfortable,
because I need permanently monitor list of used shutdown hooks.
and permamently update list of whitelisted shutdown hooks,
which must exit before my logback shutdown hook should call
LoggerContext.stop

Better approach - just after starting my own shutdown hook
get list of all application shutdown hooks and wait all rest
shutdown hooks termination before calling LoggerContext.stop

in this case - deadlock can be reached if any other shutdown hook
use same approach and wait for all rest shutdown hooks completion.

for almost always working solution - we need whitelist parameter
for this shutdown hook, allowing to exclude other shutdown hook
with same algorithm from logback shutdown hook wait list.

yes, this work, with the same reliability as my proposal.

Such approach imply minimally invasive changes to Logback,
but need manual deadlock detection and manual deadlock prevention.
this is small probability, but still it is headache and annoyance.
also, ApplicationShutdownHooks - this is implementation details,
on any other JVM your shutdown hook may not work correctly at all.

My approach - deadlock not possible, not need whitelist,
no headache, no annoyances, no reflection, work on any JVM,
but need slightly more code changes of logback.

compare, which variant is easier to implement and to use by users?

> Don't misunderstand what I am saying - I think your proposal has its
> merits and has the potential to improve the reliability in these
> specific scenarios that we are discussing. In fact, I feel that if your
> solution does work as proposed it would work very well in conjunction
> with my changes to AsyncAppender and my addition of the
> ShutdownHookAction.

if implement my proposal - ShutdownHookAction will be only one
for all cases, where application shutdown == JVM shutdown,
in this case we just not need many different shutdown hooks,
because this one (switching logback into "ready to shutdown" mode)
will work very well for all possible use cases.

> That being said, your proposal is not without its
> challenges. For instance, even after you have called your proposed
> prepareToShutdown method you still need to avoid calling
> LoggerContext.stop until all other threads/hooks that log events are
> finished with their work, otherwise log events may still be dropped
> since the loggers are stopped. The same timing & race condition problems
> still exist, they have just been moved from one point in code to another.

If application shutdown == JVM shutdown
LoggerContext.stop not need to be called at all.

After JVM shutdown and process exit - operating system
close all open log files without assistance.

Timing & race condition problems exists after all shutdown hooks
finished if any other thread still try to write something in log file.
Such event can be lost, but it also definitely will be lost
if LoggerContext.stop already was called by your shutdown hook.

So - it is no any difference here about timing & race condition.

This, last events lost generally unavoidable at all.

-- 
Best regards,
  Gena