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@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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user