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

[Michael Reinhold]

Hi Gena,

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. The
AsyncAppender was created to prevent target latency from impacting
application performance by buffering the events and processing them
asynchronously.

My comment around delaying the JVM shutdown was with respect to appenders
that exhibit higher latencies - not local file system appenders.

Once again, I agree completely with you regarding the need for a shutdown
hook to address some modes of shutdown (including both implicit JVM exit
and signals from the OS). This, in combination with shutdown hooks that try
to send log events, are the reasons I began working on the issue of
AsyncAppender not properly flushing its queue. Originally I was working on
a point solution that only addressed AsyncAppender. After some discussion
on the mailing list and in the pull request comments, it was decided to
proceed with a more generic solution than my original proposal -
configurable thread join timeouts for the AsyncAppender and the
ShutdownHookAction. The reason for this is that, with minimally invasive
changes to Logback and no API changes (just configuration elements), we
could reduce the risk of lost events and provide a framework which can be
further built upon in the future.

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.

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?
Are the Shutdown hooks inserted by your code and by the libraries
deterministic in terms of name or quantity? 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...

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. 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.

I appreciate the discussion - I think your scenario will help to shape the
other types of shutdown hooks that Logback may need to consider adding in
the future.

Regards,

Mike Reinhold




On Wed, Mar 19, 2014 at 9:07 AM, Gena Makhomed <gmm at csdoc.com> wrote:

> 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
> _______________________________________________
> 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/20140319/b3aa6c22/attachment-0001.html>