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

[Gena Makhomed]

On 19.03.2014 3:48, Michael Reinhold wrote:

> I agree completely with you that a timeout of 0 (meaning wait for the
> worker thread to join, regardless of the time it takes) makes a lot of
> sense for local appenders, such as the RollingFileAppender example you
> gave. On the other hand, when the appender has a high latency, perhaps
> because the appender is sending the log events to a remote system
> (database, cloud service, syslog daemon, etc), it may not be feasible
> for the JVM to wait indefinitely for log events to flush. For instance,
> sending log events to Loggly (http://www.loggly.com) can have latencies
> between 200 and 600ms. Depending on the queue depth, this could take a
> very long time to flush completely. For some environments, it *may* be
> preferable to drop log events over taking multiple minutes to flush the
> log queue.

If log flush take multiple minutes - may something wrong in system 
architecture desing, logging must be fast and reliable in common case.

Useful and reliable logging infrastructure now can be easily created
using Logstash + Elasticsearch + Kibana or something soft like this.

> For other environments, the log events may be important
> enough to stall the JVM shutdown indefinitely.

If log files written into local file system - how we can get
case "JVM shutdown indefinitely" ? It is almost impossible.

> Of course any events posted to a logger after calling LoggerContext.stop
> will be ignored - Logback only makes guarantees about events submitted
> to loggers that have been started. Since LoggerContext.stop stops all
> loggers and appenders, any subsequent log messages will not be appended
> to the target, which makes perfect sense. The key aspect here is that
> LoggerContext.stop should not be called unless no more log events are
> expected. In some cases, the application may be able to call it right
> before System.exit, but as discussed in other scenarios it may need to
> be triggered via a shutdown hook.

exit from application by System.exit - this is one case,
mostly applicable to desktop software. Server software,
started in daemon mode terminated by SIGTERM signal,
and it is only one possible way for graceful shutdown,
only via shutdown hook. Java used mostly for server software,
desktop software on Java is very rare. So, common case -
is exiting from java service/daemon by SIGTERM signal.

third common case - is web-applications, started in servlet
containers, in this case robust and reliable solution already
exists inside logback - context listener for graceful shutdown.

> I mis-understood your solution - I got the impression that you were
> suggesting that the user code would have to change the Logback mode.

it can be user code (user create own very small shutdown hook)
or it can be logback built-in shutdown hook, not visible for users.

> The shutdown hook scenario is something that I also run into. The
> scenarios that you describe are completely valid! Any time an
> application has background threads (user or daemon) or shutdown hooks
> that may log events, there is the potential for lost log events due to
> timing / race conditions.

Yes, we can't completely avoid thread race conditions, but we can
minimize negative effect - lost as small part of events as possible.

In my proposed solution event lost will be minimal,
logging subsystem work in "ready to shutdown mode"
before complete JVM termination.

my proposition is just add to logback LoggerContext.prepareToShutdown
method which turn logback in transparent sync "ready to shutdown mode"
with all buffers disabled and all immediate flush enabled. logback API
changes minimally - only one additional method.

> As you said, using a timeout delay for the shutdown hook clearly is
> non-optimal for some scenarios (though it may be acceptable for others).

Yes. But my proposed solution will be optimal or near optimal for almost
all cases, with only one exception - servlet and OSGi environments -
need to graceful shutdown logger without shutdown of JVM.
For such exceptions LoggerContext.stop work very well.

btw, ShutdownHookAction for servlet/OSGi also can't help.

> The upside to a delayed cleanup shutdown hook is that the user can
> profile their application and determine a reasonable value for the delay
> parameter. Obviously this is still not failsafe, but with appropriate
> understanding of the work that the shutdown hook is attempting to do and
> the maximum amount of time that the task should take, a delay cleanup
> hook *could* work within the requirements of the application.

user can't reliable profile application, because main source
of shutdown hook delays is external components - sql database
or network latency/bandwidth. Today delay can be 2-3 seconds,
tomorrow - delay can be 20-30 seconds if database or network
is overloaded.

what user can do in this situation if lost log evens is very 
unacceptable? set logback delayed cleanup to huge values of
30-60 seconds? or lost events from many application/library
shutdown hooks? logs are written into local file system -
very fast and very reliable (via RollingFileAppender).

> Obviously this does not solve all scenarios for all applications. As a
> result, the ShutdownHookAction that I am adding to Joran will operate in
> a manner similar to the AppenderAction in that it will utilize a class
> parameter that defines which ShutdownHook implementation should be
> instantiated. For instance, if the application can reasonably expect
> that the other shutdown hooks will complete in 500 ms, a
> DelayedCleanupHook could be used with a delay twice the expected runtime
> of the other hooks:
>
> <shutdownHook class="ch.qos.logback.classic.spi.DelayingCleanupHook">
> <delay>1000</delay>
> </shutdownHook>

compare with my proposed solution - it solve all scenarios for all 
applications of logging before forthcoming JVM shutdown. it just
turn logback working mode from "very fast but very unreliable"
to "very reliable but not very fast" for very short time.
99.9999% if time logback work in very fast mode, and only
before shutdown logback switches to very reliable mode.

in any case of JVM shutdown (System.exit or signal SIGTERM)
we got minimal event lost, if proper shutdown hook used
for switching logback into "ready to shutdown" mode.

> If the application controlled all of the other shutdown hooks (no
> third-party shutdown hooks are utilized or need to log events), then a
> custom ShutdownHook could be written that looks for some condition set
> by the other shutdown hooks:
>
> <shutdownHook class="com.foo.package.CustomCleanupHook">
> </shutdownHook>
>
> where the CustomCleanupHook checks against some globally accessible
> state (say a boolean value) to determine if it is safe to stop the
> LoggerContext.

case of only one shutdown hook is easy and trivial,
but I am not sure, what all libraries not use own shutdown hooks.
it can. for example, for cleanup actions or for graceful shutdown.

only one shutdown hook is possible only for small applications, IMHO.
but logback not only for small applications, it for "mission-critical
enterprise software" too. enterprise software can be big or very big.
with many libraries and subsystems. "only one shutdown hook" impossible
for enterprise software in common case.

> Because of this flexibility and extensibility, I don't believe that the
> ShutdownHookAction would be useless in your scenario.

right now I already can install own shutdown hook
like DelayingCleanupHook without ShutdownHookAction at all.
difference is only in syntax - xml config or java code.

ShutdownHookAction would be useless in my scenario
because I can't precisely predict application shutdown time,
it can be 2-3 seconds, but it also can be 20-30 seconds.

and it is many shutdown hooks in code and libraries, not just only one.

> Depending on your
> application needs and specific scenario, you should be able to define a
> ShutdownHook implementation that meets your requirements.

I can't. Requirements:

1. don't lost log events as most as possible (main requirement)
2. don't delay application shutdown more than it actually required
3. exists multiple shutdown hooks in libraries and application code
4. shutdown hooks work time can be 2-3 seconds or 20-30-60-90 seconds

> Generally
> speaking, it is difficult to define a "universally perfect" solution
> because every application has different requirements and acceptable
> tolerances.

I am almost sure, what my proposed solution almost "universally perfect"
it can work on very wide range of applications with real JVM shutdown.

for "stop application without JVM shutdown" already exists
almost "universally perfect" solition - LoggerContext.stop

only two different cases,
and only two almost "universally perfect" solitions.

compare which way is "somewhat simpler and probably easier to implement"
- only two almost perfect methods or complete "shutdown hooks framework"
inside logback code with partial and limited solutions for many cases.

> Perhaps with more information about your specific scenario, we could
> come up with a ShutdownHook design that covers your needs adequately and
> include that in the pull request.

I am almost sure what this is practically impossible for my case.
All strict requirements I already described earlier in this message.

> There are other ShutdownHooks that I
> am interested in developing for inclusion such as:
>
>   * idle time based shutdown hook - when all Loggers have been idle (no
>     new events appender for a configurable time period), then trigger
>     LoggerContext.stop. This would require some level of Logback
>     internal statistics in order to implement.

It can work, but it is not reliable, if database is overloaded -
idle threshold can be easy overcomed. In normal case delay
is 1-2 seconds, in worst case delay can be 10-20 seconds.

>   * thread count shutdown hook - for applications where the number of
>     active threads is deterministic, it may be acceptable to have the
>     LoggerContext stop once all non-essential threads have stopped.
>     Threads can be queried via the ThreadMXBean API, though the number
>     and function of the JVM internal threads may vary by implementation,
>     making this design difficult

all non-daemon threads have stopped only if application shutdown
is done by exiting from main(). if user exit from application
via system.exit or signal SIGTERM - all user threads are in place.
and after all shutdown hooks completed - JVM process just exit,
without stopping all user and daemon threads. if shutdown hook
will try to monitor application threads count - we got deadlock here.

details how shutdown process work in case of System.exit
or exit by signal SIGTERM you can see in src.zip from JDK.

>   * synchronized variable state shutdown hook - if other shutdown hooks
>     & threads can set a variable indicating their state, perhaps a
>     semaphore or counting lock indicating the number of open threads,
>     which will stop the LoggerContext when all of the locks are
>     released. This would require co-operation of the other threads and
>     shutdown hooks - limited ability to support Third-Party threads or
>     hooks...

if shutdown hooks know about one shared state variable - this case
is totally equivalent to case of only one application shutdown hook.

> I hope this helps to explain how the ShutdownHook design is supposed to
> actually work. I think that it should provide a foundation that will
> support most scenarios.

looks like this is too complex way. logback is logging subsystem,
code for logback graceful shutdown should be as small as possible.

compare with YAGNI approach: http://en.wikipedia.org/wiki/YAGNI
excellent book about YAGNI is http://gettingreal.37signals.com/

-- 
Best regards,
  Gena