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