<div dir="ltr">Hi Gena,<div><br></div><div>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. </div>
<div><br></div><div>My comment around delaying the JVM shutdown was with respect to appenders that exhibit higher latencies - not local file system appenders. </div><div><br></div><div>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.</div>
<div><br></div><div>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.</div>
<div><br></div><div>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 <a href="http://stackoverflow.com/questions/6865408/i-need-to-list-the-hooks-registered-with-java-lang-applicationshutdownhooks">java.lang.ApplicationShutdownHooks</a> 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...</div>
<div><br></div><div>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. </div>
<div><br></div><div>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.</div><div><br></div><div>Regards,</div><div>
<br></div><div>Mike Reinhold</div><div><br></div><div><br></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Wed, Mar 19, 2014 at 9:07 AM, Gena Makhomed <span dir="ltr"><<a href="mailto:gmm@csdoc.com" target="_blank">gmm@csdoc.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class="">On 19.03.2014 3:48, Michael Reinhold wrote:<br>

<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
I agree completely with you that a timeout of 0 (meaning wait for the<br>
worker thread to join, regardless of the time it takes) makes a lot of<br>
sense for local appenders, such as the RollingFileAppender example you<br>
gave. On the other hand, when the appender has a high latency, perhaps<br>
because the appender is sending the log events to a remote system<br>
(database, cloud service, syslog daemon, etc), it may not be feasible<br>
for the JVM to wait indefinitely for log events to flush. For instance,<br>
sending log events to Loggly (<a href="http://www.loggly.com" target="_blank">http://www.loggly.com</a>) can have latencies<br>
between 200 and 600ms. Depending on the queue depth, this could take a<br>
very long time to flush completely. For some environments, it *may* be<br>
preferable to drop log events over taking multiple minutes to flush the<br>
log queue.<br>
</blockquote>
<br></div>
If log flush take multiple minutes - may something wrong in system architecture desing, logging must be fast and reliable in common case.<br>
<br>
Useful and reliable logging infrastructure now can be easily created<br>
using Logstash + Elasticsearch + Kibana or something soft like this.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
For other environments, the log events may be important<br>
enough to stall the JVM shutdown indefinitely.<br>
</blockquote>
<br></div>
If log files written into local file system - how we can get<br>
case "JVM shutdown indefinitely" ? It is almost impossible.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Of course any events posted to a logger after calling LoggerContext.stop<br>
will be ignored - Logback only makes guarantees about events submitted<br>
to loggers that have been started. Since LoggerContext.stop stops all<br>
loggers and appenders, any subsequent log messages will not be appended<br>
to the target, which makes perfect sense. The key aspect here is that<br>
LoggerContext.stop should not be called unless no more log events are<br>
expected. In some cases, the application may be able to call it right<br>
before System.exit, but as discussed in other scenarios it may need to<br>
be triggered via a shutdown hook.<br>
</blockquote>
<br></div>
exit from application by System.exit - this is one case,<br>
mostly applicable to desktop software. Server software,<br>
started in daemon mode terminated by SIGTERM signal,<br>
and it is only one possible way for graceful shutdown,<br>
only via shutdown hook. Java used mostly for server software,<br>
desktop software on Java is very rare. So, common case -<br>
is exiting from java service/daemon by SIGTERM signal.<br>
<br>
third common case - is web-applications, started in servlet<br>
containers, in this case robust and reliable solution already<br>
exists inside logback - context listener for graceful shutdown.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
I mis-understood your solution - I got the impression that you were<br>
suggesting that the user code would have to change the Logback mode.<br>
</blockquote>
<br></div>
it can be user code (user create own very small shutdown hook)<br>
or it can be logback built-in shutdown hook, not visible for users.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
The shutdown hook scenario is something that I also run into. The<br>
scenarios that you describe are completely valid! Any time an<br>
application has background threads (user or daemon) or shutdown hooks<br>
that may log events, there is the potential for lost log events due to<br>
timing / race conditions.<br>
</blockquote>
<br></div>
Yes, we can't completely avoid thread race conditions, but we can<br>
minimize negative effect - lost as small part of events as possible.<br>
<br>
In my proposed solution event lost will be minimal,<br>
logging subsystem work in "ready to shutdown mode"<br>
before complete JVM termination.<br>
<br>
my proposition is just add to logback LoggerContext.<u></u>prepareToShutdown<br>
method which turn logback in transparent sync "ready to shutdown mode"<br>
with all buffers disabled and all immediate flush enabled. logback API<br>
changes minimally - only one additional method.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
As you said, using a timeout delay for the shutdown hook clearly is<br>
non-optimal for some scenarios (though it may be acceptable for others).<br>
</blockquote>
<br></div>
Yes. But my proposed solution will be optimal or near optimal for almost<br>
all cases, with only one exception - servlet and OSGi environments -<br>
need to graceful shutdown logger without shutdown of JVM.<br>
For such exceptions LoggerContext.stop work very well.<br>
<br>
btw, ShutdownHookAction for servlet/OSGi also can't help.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
The upside to a delayed cleanup shutdown hook is that the user can<br>
profile their application and determine a reasonable value for the delay<br>
parameter. Obviously this is still not failsafe, but with appropriate<br>
understanding of the work that the shutdown hook is attempting to do and<br>
the maximum amount of time that the task should take, a delay cleanup<br>
hook *could* work within the requirements of the application.<br>
</blockquote>
<br></div>
user can't reliable profile application, because main source<br>
of shutdown hook delays is external components - sql database<br>
or network latency/bandwidth. Today delay can be 2-3 seconds,<br>
tomorrow - delay can be 20-30 seconds if database or network<br>
is overloaded.<br>
<br>
what user can do in this situation if lost log evens is very unacceptable? set logback delayed cleanup to huge values of<br>
30-60 seconds? or lost events from many application/library<br>
shutdown hooks? logs are written into local file system -<br>
very fast and very reliable (via RollingFileAppender).<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Obviously this does not solve all scenarios for all applications. As a<br>
result, the ShutdownHookAction that I am adding to Joran will operate in<br>
a manner similar to the AppenderAction in that it will utilize a class<br>
parameter that defines which ShutdownHook implementation should be<br>
instantiated. For instance, if the application can reasonably expect<br>
that the other shutdown hooks will complete in 500 ms, a<br>
DelayedCleanupHook could be used with a delay twice the expected runtime<br>
of the other hooks:<br>
<br>
<shutdownHook class="ch.qos.logback.classic.<u></u>spi.DelayingCleanupHook"><br>
<delay>1000</delay><br>
</shutdownHook><br>
</blockquote>
<br></div>
compare with my proposed solution - it solve all scenarios for all applications of logging before forthcoming JVM shutdown. it just<br>
turn logback working mode from "very fast but very unreliable"<br>
to "very reliable but not very fast" for very short time.<br>
99.9999% if time logback work in very fast mode, and only<br>
before shutdown logback switches to very reliable mode.<br>
<br>
in any case of JVM shutdown (System.exit or signal SIGTERM)<br>
we got minimal event lost, if proper shutdown hook used<br>
for switching logback into "ready to shutdown" mode.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
If the application controlled all of the other shutdown hooks (no<br>
third-party shutdown hooks are utilized or need to log events), then a<br>
custom ShutdownHook could be written that looks for some condition set<br>
by the other shutdown hooks:<br>
<br>
<shutdownHook class="com.foo.package.<u></u>CustomCleanupHook"><br>
</shutdownHook><br>
<br>
where the CustomCleanupHook checks against some globally accessible<br>
state (say a boolean value) to determine if it is safe to stop the<br>
LoggerContext.<br>
</blockquote>
<br></div>
case of only one shutdown hook is easy and trivial,<br>
but I am not sure, what all libraries not use own shutdown hooks.<br>
it can. for example, for cleanup actions or for graceful shutdown.<br>
<br>
only one shutdown hook is possible only for small applications, IMHO.<br>
but logback not only for small applications, it for "mission-critical<br>
enterprise software" too. enterprise software can be big or very big.<br>
with many libraries and subsystems. "only one shutdown hook" impossible<br>
for enterprise software in common case.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Because of this flexibility and extensibility, I don't believe that the<br>
ShutdownHookAction would be useless in your scenario.<br>
</blockquote>
<br></div>
right now I already can install own shutdown hook<br>
like DelayingCleanupHook without ShutdownHookAction at all.<br>
difference is only in syntax - xml config or java code.<br>
<br>
ShutdownHookAction would be useless in my scenario<br>
because I can't precisely predict application shutdown time,<br>
it can be 2-3 seconds, but it also can be 20-30 seconds.<br>
<br>
and it is many shutdown hooks in code and libraries, not just only one.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Depending on your<br>
application needs and specific scenario, you should be able to define a<br>
ShutdownHook implementation that meets your requirements.<br>
</blockquote>
<br></div>
I can't. Requirements:<br>
<br>
1. don't lost log events as most as possible (main requirement)<br>
2. don't delay application shutdown more than it actually required<br>
3. exists multiple shutdown hooks in libraries and application code<br>
4. shutdown hooks work time can be 2-3 seconds or 20-30-60-90 seconds<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Generally<br>
speaking, it is difficult to define a "universally perfect" solution<br>
because every application has different requirements and acceptable<br>
tolerances.<br>
</blockquote>
<br></div>
I am almost sure, what my proposed solution almost "universally perfect"<br>
it can work on very wide range of applications with real JVM shutdown.<br>
<br>
for "stop application without JVM shutdown" already exists<br>
almost "universally perfect" solition - LoggerContext.stop<br>
<br>
only two different cases,<br>
and only two almost "universally perfect" solitions.<br>
<br>
compare which way is "somewhat simpler and probably easier to implement"<br>
- only two almost perfect methods or complete "shutdown hooks framework"<br>
inside logback code with partial and limited solutions for many cases.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
Perhaps with more information about your specific scenario, we could<br>
come up with a ShutdownHook design that covers your needs adequately and<br>
include that in the pull request.<br>
</blockquote>
<br></div>
I am almost sure what this is practically impossible for my case.<br>
All strict requirements I already described earlier in this message.<br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class="">
There are other ShutdownHooks that I<br>
am interested in developing for inclusion such as:<br>
<br></div>
  * idle time based shutdown hook - when all Loggers have been idle (no<div class=""><br>
    new events appender for a configurable time period), then trigger<br>
    LoggerContext.stop. This would require some level of Logback<br>
    internal statistics in order to implement.<br>
</div></blockquote>
<br>
It can work, but it is not reliable, if database is overloaded -<br>
idle threshold can be easy overcomed. In normal case delay<br>
is 1-2 seconds, in worst case delay can be 10-20 seconds.<br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
  * thread count shutdown hook - for applications where the number of<div class=""><br>
    active threads is deterministic, it may be acceptable to have the<br>
    LoggerContext stop once all non-essential threads have stopped.<br>
    Threads can be queried via the ThreadMXBean API, though the number<br>
    and function of the JVM internal threads may vary by implementation,<br>
    making this design difficult<br>
</div></blockquote>
<br>
all non-daemon threads have stopped only if application shutdown<br>
is done by exiting from main(). if user exit from application<br>
via system.exit or signal SIGTERM - all user threads are in place.<br>
and after all shutdown hooks completed - JVM process just exit,<br>
without stopping all user and daemon threads. if shutdown hook<br>
will try to monitor application threads count - we got deadlock here.<br>
<br>
details how shutdown process work in case of System.exit<br>
or exit by signal SIGTERM you can see in src.zip from JDK.<br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
  * synchronized variable state shutdown hook - if other shutdown hooks<div class=""><br>
    & threads can set a variable indicating their state, perhaps a<br>
    semaphore or counting lock indicating the number of open threads,<br>
    which will stop the LoggerContext when all of the locks are<br>
    released. This would require co-operation of the other threads and<br>
    shutdown hooks - limited ability to support Third-Party threads or<br>
    hooks...<br>
</div></blockquote>
<br>
if shutdown hooks know about one shared state variable - this case<br>
is totally equivalent to case of only one application shutdown hook.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
I hope this helps to explain how the ShutdownHook design is supposed to<br>
actually work. I think that it should provide a foundation that will<br>
support most scenarios.<br>
</blockquote>
<br></div>
looks like this is too complex way. logback is logging subsystem,<br>
code for logback graceful shutdown should be as small as possible.<br>
<br>
compare with YAGNI approach: <a href="http://en.wikipedia.org/wiki/YAGNI" target="_blank">http://en.wikipedia.org/wiki/<u></u>YAGNI</a><br>
excellent book about YAGNI is <a href="http://gettingreal.37signals.com/" target="_blank">http://gettingreal.37signals.<u></u>com/</a><div class=""><div class="h5"><br>
<br>
-- <br>
Best regards,<br>
 Gena<br>
______________________________<u></u>_________________<br>
Logback-user mailing list<br>
<a href="mailto:Logback-user@qos.ch" target="_blank">Logback-user@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/<u></u>listinfo/logback-user</a><br>
</div></div></blockquote></div><br></div></div>