Hi Gena, Thanks for the detailed response - I'll try to be as thorough in return! 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. For other environments, the log events may be important enough to stall the JVM shutdown indefinitely. For this reason, we determined that it made the most sense to make the join call timeout configurable, using the previously hardcoded value as a default in order to keep the semantics the same. This way, the application developer can determine what is correct for the application by specifying an appropriate timeout value. 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. I mis-understood your solution - I got the impression that you were suggesting that the user code would have to change the Logback mode. 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. 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). 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. 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> 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. Because of this flexibility and extensibility, I don't believe that the ShutdownHookAction would be useless in your scenario. Depending on your application needs and specific scenario, you should be able to define a ShutdownHook implementation that meets your requirements. Generally speaking, it is difficult to define a "universally perfect" solution because every application has different requirements and acceptable tolerances. 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. 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. - 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 - 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... 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. That being said, for some use-cases it may be necessary to design additional flexibility into Logback - for instance, my described idle time based shutdown hook would require some way of tracking logger use statistics which could be a sizable modification. Thank you again for your input! I look forward to hearing your thoughts on the described framework. Regards, Mike Reinhold On Tue, Mar 18, 2014 at 6:08 PM, Gena Makhomed <gmm@csdoc.com> wrote:

On 18.03.2014 17:27, Michael Reinhold wrote:

In my opinion, the solution that Ceki and I have been working on is

...

somewhat simpler and probably easier to implement. The full conversation can be viewed in the pull request comments, but basically we have settled on a small alteration to AsyncAppenderBase in Logback-core that makes the worker.join(long) call have a configurable timeout instead of hardcoded to 1000ms. By doing this, LoggerContext.stop is now guaranteed to flush as many queued events as possible within the specified timeout - which can be tuned via the maxShutdownTime configuration element for AsyncAppender. Additionally, since the maxShutdownTime configuration element has the same semantics as Thread.join(long), using a value of 0 will cause the LoggerContext.stop method to wait for all queued events to flush regardless of how long it takes.

If using AsyncAppender with RollingFileAppender on local file system - IMHO the best solution is to flush all events from AsyncAppender queue with call Thread.join(0) - without any possible information lost here. Queued log events is more valuable than JVM process shutdown speed. I can't find any reason to change this timeout from 0 to anything else.

Ok, but this is partial solution - it only flush events which already in the AsyncAppender queue.

After LoggerContext.stop() finished - all subsequent logger.info(...) calls will lost information and do not write messages into log file.

This solution is better in my

...

mind because it involves very few code changes and does not alter shutdown semantics for any existing users (no additional calls to change the Logback mode), while still making it possible for AsyncAppender to fully flush its queue by adjusting the timeout.

In my proposed solution also not need any additional calls to change the Logback mode - all work will be done by Logback shutdown handler, transparently and completely invisible for all logback users.

The second piece of the design that we have been working on is how to

...

allow for flushing the queue when it is not possible to call LoggerContext.stop prior to application exit (such as when an application exits implicitly or from) or when shutdown hooks expect the ability to log events. This is a little more complex, but per Ceki's description in the pull request comments, adding a new action to Joran to allow the installation of a shutdown hook that calls LoggerContext.stop is pretty flexible.

"when shutdown hooks expect the ability to log events" - yes, this is my case.

also, if System.exit() called manually - in this case any application thread expect the ability to log events - they don't know about exiting.

in any case of shutdown hook, after calling LoggerContext.stop - all rest events will be lost.

how to solve this problem/bug - I describe in previous message:

do not call LoggerContext.stop at all, and just turn logback into failsafe mode, with AsyncAppender working in transparent sync mode, and with all FileAppenders turned immediateFlush into true.

in attach - TestApplication.java with two shutdown hooks.

imagine, what logback shutdown hook wait 2 seconds before call LoggerContext.stop and application shutdown hook work 10 seconds before completion.

so - all events logged from application shutdown hook (and all other live application threads) will be lost.

add many odd timeouts to logback is not optimal solution, IMHO, because it will be well known "race condition" and nonoptimal work:

even if I force logback shutdown hook wait 15 seconds before LoggerContext.stop - this is not solve problem of events lost, because in rare cases application shutdown hook can work 20 seconds. - this is "race condition".

also, if application shutdown hook complete work in 1 or 2 seconds - logback shutdown hook will force wait complete 15 seconds before application exit - this is nonoptimal work (unnecessary waste time).

see http://www.qos.ch/shop/index "Quality Open Software [...] mission-critical enterprise software"

possible workaround - call LoggerContext.stop() manually in own application shutdown hook after all work completed. but in this case, - ShutdownHookAction in joran will be useless.

and this is partial workaround, it can help only in case of single application shutdown hook. if present multiple application/libraries shutdown hooks - we in trouble again.

===============================================================

in my proposed solution - application exits as soon as possible, and without any lost events from all application shutdown hooks.

event lost from (daemon) threads still possible, but this is unavoidable race condition between JVM successful exit and between (daemon) thread attempt to log any info.

to minimize "deleterious consequences" all what we can do - is to forcibly set immediateFlush into true and call outputStream.flush() for all FileAppenders and forcibly turn AsyncAppenders into transparent sync mode.

in this case is (daemon) threads attempt to log any info can cause partially written log file lines or not - I not investigate so deeply. Probably it can. In this case we lost only two log lines, this partially written, and first line of other process written to this log file in future.

obvious workaround - always firstly call logger.info("") to write empty line to log file at every application startup. in this case we can lost only one partially written log file line.

P.S.

It is slightly uncomfortable to lost log events, so I prefer perfect or almost perfect solutions.

right now I use such solution:

public class LogbackConfigurator {

public void init() {

// ...

Runtime.getRuntime().addShutdownHook(new Thread(new LogbackShutdownHook(), "LogbackShutdownHook")); }

private static class LogbackShutdownHook implements Runnable {

@Override public void run() { try { Thread.sleep(LOGBACK_STOP_DELAY_MILLIS); } catch (InterruptedException ignored) { } LoggerContext loggerContext = (LoggerContext) LoggerFactory. getILoggerFactory(); loggerContext.stop(); } } }

but it is not perfect.

On Tue, Mar 18, 2014 at 6:37 AM, Gena Makhomed wrote:

...

Re: AsyncAppenderBase not flushing queue during JVM shutdown

Michael Reinhold, I can propose better solution of described problem:

we just need make two modes of work for logback:

1. normal mode, as it work all time after configuration finishing.

2. ready to shutdown mode, - fail safe mode, without messages lost.

switching from "normal mode" to "ready to shutdown mode" do via JVM shutdown hook, - just one shutdown hook for logback.

if logback turned from "normal mode" to "ready to shutdown mode", logback change own behavior in such way:

1. all appenders turn "immediateFlush = true", regardless of initial value in logback configuration, to prevent message lost during forthcoming JVM shutdown.

2. all AsyncAppenders turns into transparent and sync mode. if AsyncAppender work in this "transparent and sync mode", all behavior of

app -> AsyncAppender -> RollingFileAppender -> file

completly identical to behaviour of

app -> RollingFileAppender -> file

after switching from "normal mode" to "ready to shutdown mode", JVM shutdown hook finished work and now logback is ready to continue logging and also ready to forthcoming JVM shutdown.

all other components of system still can use logback for logging during JVM/application shutdown process.

here is only one unobvious nuance: how to transparently switch each logback AsyncAppender from async to sync mode without messages lost and without messages reordering in log.

but I am almost sure this is possible to do using java

without perceptible performance degrade for AsyncAppender when it work in normal (async) mode.

==============================__==================

IMHO, this is the most robust and most useful way to almost completly prevent any log messages lost during application and JVM shutdown.

LoggerContext.stop() not prevent messages lost, so it should not be called before JVM shutdown.

as I understand it mostly will be useful only for web applications, to be called in ServletContextListener.__contextDestroyed() callback.

Let me know, what you think about this new proposed solution.

-- Best regards, Gena

_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user

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

Hi Gena, The method described for a disk-cached AsyncAppender of course makes perfect sense. I think it would make a good alternative to the current AsyncAppender for some scenarios and would be a solid addition to the current Logback appenders. I agree that AsyncAppender does not handle network failures, but in my opinion that is the responsibility of the target appender since it best knows how to handle different failure cases. For instance, some appenders may choose to retry immediately or may round-robin to an alternate server, etc. I agree completely that AsyncAppender has many uses not limited to remote log targets. Generally speaking, the purpose of AsyncAppender is the same for local and remote targets - to reduce the impact of target latency on application performance, whether that latency is network or disk or something else doesn't really matter. I feel like we are speaking past each other a little bit in that I am not proposing any of the specific shutdown hooks discussed so far at a theoretical level (without being fully thought through or developed, they are of course flawed). Rather, I am proposing that my solution be implemented as a framework for Logback, contributors to Logback, and/or end users of Logback to build shutdown hooks that fulfill specific needs. Some of the theoretical hooks discussed could be implemented, knowing that they are not general solutions, but rather niche solutions that may be acceptable for some applications. Then, leveraging Logback's community of contributors (including you and me), more general solutions can be developed and included as part of Logback. Based on this back and forth discussion, I don't think there is any resistance to your proposed solution as it has the potential to be a reasonably generic shutdown hook that could be applicable to many common use cases. Furthermore, it could be implemented as one of the pluggable classes usable by the ShutdownHookAction. If your implementation is as generic and effective in practice as you have described, it could actually be the default ShutdownHook implementation. If for some reason a user found that your solution was non-optimal for their application, they could implement (or work with the Logback community to implement) an alternate ShutdownHook that does meet their needs. I hope this helps explain my position adequately - I don't see our two solutions as competing alternatives, but rather as complimentary components of the shutdown cleanup functionality of Logback. My portion provides a framework for creating shutdown hooks that cleanup the Logback context (possibly including some simple implementations) and your portion includes a more complex, but fairly general implementation of that shutdown hook framework. This gives us the best of both worlds - the flexibility to plug different hooks in if needed as well as a solid default implementation that should cover most use cases. This would seem to fit with the methodology of design that Logback generally uses where multiple implementations are possible and generally speaking a few options are included in the library, but a default implementation that covers most scenarios is also included in the library and, unless specified otherwise, is the preferred option. Once again, thank you for the good discussion! Regards, Mike Reinhold On Wed, Mar 19, 2014 at 5:25 PM, Gena Makhomed <gmm@csdoc.com> wrote:

On 19.03.2014 16:51, Michael Reinhold wrote:

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.

However it is possible to make logging even to remote services reliable and fast, from application code point of view. Making process of logging to remote services true asynchronous:

- write all log events to ordinary log file at local file system

- in background (daemon) thread scan log files, check at remote service which files should be synced and in which offset, after this first "handshake" - just monitor tail of log file, and all new events asynchronously read from log file and send to remote log collection service, even fashionable cloud logging services

In this case - logging events to log file and sending events to remote logging service are asynchronous, and without event lost even after fast application restart, even with big queue of not yet reported to remote service log events in the log.

Algorithm the same as in case of AsyncAppender from logback, but as temporary storage for queued events used persistent storage (disk subsystem) instead of java heap - this is only one difference.

Existing AsyncAppender not help in case of temporary network failure, you will get event lost, - there is not guaranteed log events delivery.

With true asynchronous conversation with remote logging service, (with queue located at persistent storage service, not in java heap) all events queued in log file will be send to remote logging service, without lost in events delivery process. (fast, asynchronous, reliable)

The AsyncAppender was created to prevent target latency from impacting

...

application performance by buffering the events and processing them asynchronously.

Yes, and AsyncAppender even help in case of using RollingFileAppender, allow application to process client request at maximum available speed, with all logging work with log file executed in separate daemon thread.

If not use AsyncAppender before RollingFileAppender - all logging work with underlying OutputStream are done in application thread, and time wasted for logging instead of client request processing.

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.

Such approach imply minimally invasive changes to Logback and forcing users to write own non-trivial ShutdownHooks.

If implement my proposed solution - user not need write any code at all. User just need to answer to one simple question: application shutdown means JVM shutdown (for example in case of UNIX service/daemon) or application shutdown possible without JVM shutdown (OSGi, webapp, etc)

if application shutdown == JVM shutdown user add to logback.xml one line, for enabling built-in logback shutdown hook, which after activation turn logback from "maximum speed" to "maximum safe" mode of work, and in this case logback will be ready for forthcoming JVM shutdown. event lost in this case will be minimal, because after logback shutdown hook complete work - all events from AsyncAppender queue will be written to its underlying appender, queue size set to 0, and AsyncAppender will be switched into transparent sync mode. also, all appenders switched to immediateFlush = true mode. in this case each log event from any shutdown hook will be guaranteed to be written into log file. without any additional work from user.

if application shutdown possible without JVM shutdown, user just need to activate proper context listener for graceful shutdown of logback via LoggerContext.stop

if none on this two methods of graceful shutdown activated - logback can write warning about misconfiguration to StatusManager.

for user - logback will work very easy, fast and reliable without any headache.

call LoggerContext.stop only required for case when application shutdown != JVM shutdown,

and if application shutdown == JVM shutdown calling LoggerContext.stop is not the best solution, because it can lead to logging events lost.

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?

Yes.

Are the Shutdown hooks inserted by your code and by the

...

libraries deterministic in terms of name or quantity?

No.

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

Yes, this is working solution, but it is very uncomfortable, because I need permanently monitor list of used shutdown hooks. and permamently update list of whitelisted shutdown hooks, which must exit before my logback shutdown hook should call LoggerContext.stop

Better approach - just after starting my own shutdown hook get list of all application shutdown hooks and wait all rest shutdown hooks termination before calling LoggerContext.stop

in this case - deadlock can be reached if any other shutdown hook use same approach and wait for all rest shutdown hooks completion.

for almost always working solution - we need whitelist parameter for this shutdown hook, allowing to exclude other shutdown hook with same algorithm from logback shutdown hook wait list.

yes, this work, with the same reliability as my proposal.

Such approach imply minimally invasive changes to Logback, but need manual deadlock detection and manual deadlock prevention. this is small probability, but still it is headache and annoyance. also, ApplicationShutdownHooks - this is implementation details, on any other JVM your shutdown hook may not work correctly at all.

My approach - deadlock not possible, not need whitelist, no headache, no annoyances, no reflection, work on any JVM, but need slightly more code changes of logback.

compare, which variant is easier to implement and to use by users?

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.

if implement my proposal - ShutdownHookAction will be only one for all cases, where application shutdown == JVM shutdown, in this case we just not need many different shutdown hooks, because this one (switching logback into "ready to shutdown" mode) will work very well for all possible use cases.

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.

If application shutdown == JVM shutdown LoggerContext.stop not need to be called at all.

After JVM shutdown and process exit - operating system close all open log files without assistance.

Timing & race condition problems exists after all shutdown hooks finished if any other thread still try to write something in log file. Such event can be lost, but it also definitely will be lost if LoggerContext.stop already was called by your shutdown hook.

So - it is no any difference here about timing & race condition.

This, last events lost generally unavoidable at all.

-- Best regards, Gena _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user

Hi Gena, Again, I agree with most of your points at a high-level and don't doubt that your solution can work. I do disagree with your comment about the main requirement of logging subsystems: it does depend on application requirements. For instance, in my application, speed is of utmost importance - I am willing to lose debug and warning messages in favor of keeping application performance at its maximum. The only messages that require full reliability for my application are warning and error events (this model is supported by AsyncAppender's current design with its discardingThreshold). All that being said, I'm not quite sure why you are resistant to a framework for implementing shutdown hooks. Is there a particular reason you object to the user being able to select which shutdown mechanism should be employed by Logback? I understand that you feel your solution covers most or all cases, but is it not possible that the end user of Logback may disagree and prefer to apply their own shutdown procedure or policy? As a side question, how long would you estimate it would take to modify logback-core (and/or the other logback components) to implement your proposed solution? Are you currently working on implementing this switchToFailSafe functionality or are you proposing that someone else from the logback community develop it? Thanks! Regards, Mike Reinhold On Thu, Mar 20, 2014 at 6:00 AM, Gena Makhomed <gmm@csdoc.com> wrote:

On 20.03.2014 2:45, Michael Reinhold wrote:

I feel like we are speaking past each other a little bit in that I am

...

not proposing any of the specific shutdown hooks discussed so far at a theoretical level (without being fully thought through or developed, they are of course flawed). Rather, I am proposing that my solution be implemented as a framework for Logback, contributors to Logback, and/or end users of Logback to build shutdown hooks that fulfill specific needs. Some of the theoretical hooks discussed could be implemented, knowing that they are not general solutions, but rather niche solutions that may be acceptable for some applications. Then, leveraging Logback's community of contributors (including you and me), more general solutions can be developed and included as part of Logback.

framework for logback shutdown hooks just not need at all, if only two simple solutions cover all possible use cases:

1) LoggerContext.stop for case app shutdown without JVM shutdown 2) LoggerContext.switchToFailSafe for case app shutdown == JVM shutdown

register logback shutdown hook, which switch logback from "normal" to "failsafe" mode have sense even for web-applications, because tomcat can be stopped via signal SIGTERM, and such shutdown hook will flush all AsyncAppenders and FileAppenders memory bufffers.

so, it is even not need any configuration option for enabling such logback shutdown hook, it should be enabled always for all contexts.

Based on this back and forth discussion, I don't think there is any

...

resistance to your proposed solution as it has the potential to be a reasonably generic shutdown hook that could be applicable to many common use cases.

can you provide any case in which my proposed solution not applicable?

Furthermore, it could be implemented as one of the pluggable

...

classes usable by the ShutdownHookAction.

java code is trivial: run(){ LoggerContext.switchToFailSafeMode(); }

If your implementation is as

...

generic and effective in practice as you have described, it could actually be the default ShutdownHook implementation. If for some reason a user found that your solution was non-optimal for their application, they could implement (or work with the Logback community to implement) an alternate ShutdownHook that does meet their needs.

right now exists only three available alternatives:

1. do nothing and lost all event in various memory buffers 2. use LoggerContext.stop and lost all events after stopping 3. use LoggerContext.switchToFailSafeMode for maximum reliability

can you provide any other alternatives for these three?

if even theoretically other possible use cases not exists here, may be not need implement framework for alternatives right now?

I hope this helps explain my position adequately - I don't see our two

...

solutions as competing alternatives, but rather as complimentary components of the shutdown cleanup functionality of Logback.

I am talking not about only shutdown cleanup, I propose more generic solution, just add new, fail-safe mode. Switching logback to fail-safe mode useful in logback shutdown hook to prevent messages lost, and also switching logback into fail-safe mode will be useful for low-memory conditions.

for example, we have one huge desktop application with many plugins. I wrote memory monitor, which continuously monitor java heap size, and continuously provide "live set" size of java objects in heap. also this monitor have "low memory" handler, which called in case if free heap memory (max heap memory - live set size) less then 50 MiB. ("live set" size == min used heap size for rolling window of last 5 min)

switching logback into fail-safe mode will be very useful for this handler too, for preventing logback events lost in case if application will be stopped via forthcoming OutOfMemoryError.

if AsyncAppenders not used and all FileAppenders configured with "immediateFlush = true" mode - for this special case "normal" and "fail-safe" mode will be identical. for other cases - not.

My portion

...

provides a framework for creating shutdown hooks that cleanup the Logback context (possibly including some simple implementations) and your portion includes a more complex, but fairly general implementation of that shutdown hook framework. This gives us the best of both worlds - the flexibility to plug different hooks in if needed as well as a solid default implementation that should cover most use cases.

There exists only one way for "cleanup the Logback context" - just call LoggerContext.stop method.

there is only one question - when do this cleanup. and only one strict answer, when LoggerContext.stop is required: this is case if application shutdown != JVM shutdown. In other cases "cleanup the Logback context" is not required at all, and switching logback into fail-safe mode is always better approach, because it prevent undesirable events lost.

if user required to stop logging before actual JVM shutdown - they always can manually call LoggerContext.stop in own code.

again, no need any special framework, LoggerContext.stop already exists.

what you really need - it is configurable timeout for stopping AsyncAppender worker thread, if AsyncAppender used as frontend for appender working with remote logging service and because now in logback not exists any way for making reliable logging to remove/cloud logging services without log events lost.

partial solution of remote logging is to play with timeout value and try to find acceptable tradeoff between application shutdown speed and application event lost rate from memory buffer on app shutdown.

optimal solution - just create reliable async appender for remote services, which buffer events on disk and provides fast application shutdown and also provides reliable events delivery to remote logging service even in cases of partial network troubles/failures/overloads.

main requirement for any logging subsystem: do not lost messages. all other wishes (speed,usability,etc) is secondary requirements.

This would seem

...

to fit with the methodology of design that Logback generally uses where multiple implementations are possible and generally speaking a few options are included in the library, but a default implementation that covers most scenarios is also included in the library and, unless specified otherwise, is the preferred option.

I can't imagine how multiple implementations of shutdown hook can better help prevent event lost if already exists almost perfect and safe algorithm for graceful shutdown of logback with minimal possible events lost via new "fail-safe" mode.

Once again, thank you for the good discussion!

...

You are welcome!

-- Best regards, Gena _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user

Hi Gena, The intent of the shutdown hook functionality is not to be a general application shutdown hook, but to provide reasonably ways of having logback wait for a some condition before shutting down (not just calling LoggerContext.stop immediately). Logback can provide one or more general mechanisms for performing this action, however if the user's needs differ they could implement their own. The benefit of utilizing a logback based shutdown hook for cleaning up logback resources is that logback can ensure that shutdown hook is properly removed when the context is reset (which reduces the complexity of using the Runtime hook methods directly). Additionally, the user can utilize existing, tested implementations if one of the Logback provided shutdown hook mechanisms is appropriate for the user's application or scenario. Just because a shutdown hook implementation is simple (such as a one-liner) does not make the logback managed mechanism invalid or irrelevant. The user still has the choice to implement a hook however they choose - via a predefined, managed hook or a completely custom hook. I'm not sure how this design is premature optimization. It is a very simple design for flexibility - there is no impact to speed, debuggability, or maintenance. Though some may qualify it as "you aren't going to need it", YAGNI more accurately refers to features which significantly take away from the development of core functionality, testing, documentation, etc or add significant complexity, limit future flexibility, etc. The ShutdownHookAction and associated classes are compact, well-defined, do not detract from the maintainability of logback as a whole, do not add significant complexity, nor limit future flexibility. To be completely honest, Ceki first suggested using a Joran action about a week ago. Since then I have only spent about 4 hours researching, developing, and testing the ShutdownActionHook solution - which is now 100% complete from a functionality standpoint and 95% complete overall (just pending documentation and some unit testing). The other changes to AsyncAppender had been built into a proof of concept and re-implemented with suggestions from the pull request over a week ago. I have probably spent more time debating the merits of your proposal vs mine than actually researching, developing, testing, and documenting! :) Not that I regret the debate by any means - it has been a healthy design discussion and has helped to clarify other use-cases and mechanisms that I may not have thought of otherwise. That being said, with buy-in from maintainers of Logback on this design (at least to this point), I don't see much point in debating further. It still seems to me that the best solution is the blending of our two proposals - using my structure to provide flexibility and your solution to transition the logback mode. Since my solution is nearly complete and yours may be a ways off, this seems like a natural fit both technically and logistically. That being said, if anyone from Logback team wants to weigh in on how they feel would be best to proceed in light of the proposals and discussion, I am open to proceeding with the result of the group decision. At the very least, regardless of what proposal or blending of proposals is approved, I believe that the changes already made to the AsyncAppender in the open pull request are still valid since that is what ensures that LoggerContext.stop does not return until AsyncAppender has flushed its queue or reached its configured timeout. From my perspective, it is just the discussion around the shutdown hook implementation components that is in contention, agreed? Thanks! Regards, Mike Reinhold On Thu, Mar 20, 2014 at 3:03 PM, Gena Makhomed <gmm@csdoc.com> wrote:

On 20.03.2014 17:17, Michael Reinhold wrote:

All that being said, I'm not quite sure why you are resistant to a

...

framework for implementing shutdown hooks. Is there a particular reason you object to the user being able to select which shutdown mechanism should be employed by Logback? I understand that you feel your solution covers most or all cases, but is it not possible that the end user of Logback may disagree and prefer to apply their own shutdown procedure or policy?

Right now what user can do inside logback shutdown hook - is just one action: calling LoggerContext.stop after stopping other app subsystems.

And, if user do graceful shutdown of other subsystems in shutdown hook called "logback shutdown hook" - in fact they write own java code for application shutdown hook, but falsely name it "logback shutdown hook"

This mismatch between name of logback shutdown hook and its role of application shutdown hook is the main reason why I am resistant to a creating yet one more framework for implementing shutdown hooks.

Second reason: framework for implementing shutdown hooks already exists. it is Runtime.addShutdownHook() and Runtime.removeShutdownHook() methods

Third reason: if implement my proposed solution in logback, the code of logback shutdown hook will look like this:

public void run() { loggerContext.switchToFailSafeMode(); }

If user want to call LoggerContext.stop in own application shutdown hook it still can do it in own APPLICATION shutdown hook without any problems

Fourth reason:

I suppose additional attribute <configuration shutdownHook="false"> (with default value "true") can be added to logback, if some user need completely turn off build-in logback shutdown hook and want to write own application shutdown hook, using already existing framework for implementing shutdown hooks from JVM. But right now this is looks like premature optimization:

========================================================================

http://c2.com/cgi/wiki?PrematureOptimization

"Programmers waste enormous amounts of time thinking about, or worrying about, the speed of noncritical parts of their programs, and these attempts at efficiency actually have a strong negative impact when debugging and maintenance are considered. We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3%."

========================================================================

Fifth reason:

see arguments from page https://en.wikipedia.org/wiki/You_aren%27t_gonna_need_it

"Always implement things when you actually need them, never when you just foresee that you need them".

"Until the feature is actually needed, it is difficult to fully define what it should do and to test it. If the new feature is not properly defined and tested, it may not work correctly, even if it eventually is needed".

"Adding the new feature may suggest other new features. If these new features are implemented as well, this may result in a snowball effect towards feature creep".

As a side question, how long would you estimate it would take to modify

...

logback-core (and/or the other logback components) to implement your proposed solution?

I am not learn all details of code, but suppose that this is not very difficult task. May be few weeks, if work in spare time (need to read all sources of logback and understand internal logic).

Are you currently working on implementing

...

this switchToFailSafe functionality

Right now - not, because I don't know if this code will be accepted or rejected, my first try was to ask about such idea - if idea accepted, as the next step I can try to write patch with this idea implementation.

or are you proposing that someone else from the logback community develop

...

it?

I just proposing idea how to make logback graceful shutdown solution. If this idea will be accepted and approved, then next step can be done.

If someone else from the logback community want to code this idea - I have nothing against this.

-- Best regards, Gena _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user

Hi Gena, I agree - a solid implementation of a fail-safe transparent sync mode could be the default as it will likely cover most scenarios. Once my pull request is merged into Logback, I would be interested in working with you on the implementation of such a switch to fail-safe mode. At the very least, I could assist with testing since my application has similar requirements and characteristics. As always, thank you for the great discussion! Let me know if you would like assistance working on this in the future! Regards, Mike Reinhold On Fri, Mar 21, 2014 at 7:44 AM, Gena Makhomed <gmm@csdoc.com> wrote:

On 20.03.2014 22:35, Michael Reinhold wrote:

The intent of the shutdown hook functionality is not to be a general

...

application shutdown hook, but to provide reasonably ways of having logback wait for a some condition before shutting down (not just calling LoggerContext.stop immediately). Logback can provide one or more general mechanisms for performing this action, however if the user's needs differ they could implement their own.

Ok. Most likely you are right, such approach is useful for flexibility. Particularly if exotic appenders are used, like cloud logging services.

And user can select how logback should react to system-wide message "JVM will be shutdown soon" - by completely shutting down logback or just by flushing all memory buffers and switching logback info fail-safe mode and continue logging.

I prefer switching into fail-safe transparent sync mode to be the default, which guarantee flushing all events from memory buffers and also allow subsequent events from other components of system not to be lost during JVM shutdown sequence.

And only in very exotic situations such default behavior should be changed by user manually into something else.

Thank you for the good discussion!

-- Best regards, Gena _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user