<div dir="ltr">Hi Gena,<div><br></div><div>Thanks for the detailed response - I'll try to be as thorough in return!</div><div><br></div><div>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 <span style="font-family:arial,sans-serif;font-size:13px">RollingFileAppender</span><span style="font-family:arial,sans-serif;font-size:13px"> 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 (<a href="http://www.loggly.com">http://www.loggly.com</a>) 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.</span></div>
<div><br></div><div><span style="font-family:arial,sans-serif;font-size:13px">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.</span></div>
<div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div><div><span style="font-family:arial,sans-serif;font-size:13px">I mis-understood your solution - I got the impression that you were suggesting that the user code would have to change the Logback mode.</span></div>
</div><div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div><span style="font-family:arial,sans-serif;font-size:13px">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. </span></div>
<div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div><span style="font-family:arial,sans-serif;font-size:13px">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. </span></div>
<div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div><span style="font-family:arial,sans-serif;font-size:13px">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:</span></div>
<div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div><span style="font-family:arial,sans-serif;font-size:13px"><div><shutdownHook class="ch.qos.logback.classic.spi.DelayingCleanupHook"></div>
<div><span class="" style="white-space:pre"> </span><delay>1000</delay></div><div></shutdownHook></div></span></div><div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div><div>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:</div>
<div><br></div><div><div><shutdownHook class="com.foo.package.CustomCleanupHook"></div><div></shutdownHook></div></div><div><span style="font-family:arial,sans-serif;font-size:13px"><br></span></div>
<div>where the CustomCleanupHook checks against some globally accessible state (say a boolean value) to determine if it is safe to stop the LoggerContext. </div><div><br></div><div>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.</div>
<div><br></div><div>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:</div>
<div><ul><li>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.</li>
<li>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</li>
<li>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...</li>
</ul><div>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.</div>
</div><div><br></div><div>Thank you again for your input! I look forward to hearing your thoughts on the described framework.</div><div><br></div><div>Regards,</div><div><br></div><div>Mike Reinhold</div></div><div class="gmail_extra">
<br><br><div class="gmail_quote">On Tue, Mar 18, 2014 at 6:08 PM, 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:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div class="">On 18.03.2014 17:27, Michael Reinhold wrote:<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
In my opinion, the solution that Ceki and I have been working on is<br>
somewhat simpler and probably easier to implement. The full conversation<br>
can be viewed in the pull request comments, but basically we have<br>
settled on a small alteration to AsyncAppenderBase in Logback-core that<br>
makes the worker.join(long) call have a configurable timeout instead of<br>
hardcoded to 1000ms. By doing this, LoggerContext.stop is now guaranteed<br>
to flush as many queued events as possible within the specified timeout<br>
- which can be tuned via the maxShutdownTime configuration element for<br>
AsyncAppender. Additionally, since the maxShutdownTime configuration<br>
element has the same semantics as Thread.join(long), using a value of 0<br>
will cause the LoggerContext.stop method to wait for all queued events<br>
to flush regardless of how long it takes.<br>
</blockquote>
<br></div>
If using AsyncAppender with RollingFileAppender on local file system -<br>
IMHO the best solution is to flush all events from AsyncAppender queue<br>
with call Thread.join(0) - without any possible information lost here.<br>
Queued log events is more valuable than JVM process shutdown speed.<br>
I can't find any reason to change this timeout from 0 to anything else.<br>
<br>
Ok, but this is partial solution - it only flush<br>
events which already in the AsyncAppender queue.<br>
<br>
After LoggerContext.stop() finished - all subsequent <a href="http://logger.info" target="_blank">logger.info</a>(...)<br>
calls will lost information and do not write messages into log file.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
This solution is better in my<br>
mind because it involves very few code changes and does not alter<br>
shutdown semantics for any existing users (no additional calls to change<br>
the Logback mode), while still making it possible for AsyncAppender to<br>
fully flush its queue by adjusting the timeout.<br>
</blockquote>
<br></div>
In my proposed solution also not need any additional calls to change<br>
the Logback mode - all work will be done by Logback shutdown handler,<br>
transparently and completely invisible for all logback users.<div class=""><br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
The second piece of the design that we have been working on is how to<br>
allow for flushing the queue when it is not possible to call<br>
LoggerContext.stop prior to application exit (such as when an<br>
application exits implicitly or from) or when shutdown hooks expect the<br>
ability to log events. This is a little more complex, but per Ceki's<br>
description in the pull request comments, adding a new action to Joran<br>
to allow the installation of a shutdown hook that calls<br>
LoggerContext.stop is pretty flexible.<br>
</blockquote>
<br>
"when shutdown hooks expect the ability to log events"<br></div>
- yes, this is my case.<br>
<br>
also, if System.exit() called manually - in this case any application<br>
thread expect the ability to log events - they don't know about exiting.<br>
<br>
in any case of shutdown hook, after calling LoggerContext.stop<br>
- all rest events will be lost.<br>
<br>
how to solve this problem/bug - I describe in previous message:<br>
<br>
do not call LoggerContext.stop at all, and just turn logback into<br>
failsafe mode, with AsyncAppender working in transparent sync mode,<br>
and with all FileAppenders turned immediateFlush into true.<br>
<br>
in attach - TestApplication.java with two shutdown hooks.<br>
<br>
imagine, what logback shutdown hook wait 2 seconds<br>
before call LoggerContext.stop<br>
and application shutdown hook work 10 seconds before completion.<br>
<br>
so - all events logged from application shutdown hook<br>
(and all other live application threads) will be lost.<br>
<br>
add many odd timeouts to logback is not optimal solution, IMHO,<br>
because it will be well known "race condition" and nonoptimal work:<br>
<br>
even if I force logback shutdown hook wait 15 seconds before<br>
LoggerContext.stop - this is not solve problem of events lost,<br>
because in rare cases application shutdown hook can work 20 seconds.<br>
- this is "race condition".<br>
<br>
also, if application shutdown hook complete work in 1 or 2 seconds -<br>
logback shutdown hook will force wait complete 15 seconds before<br>
application exit - this is nonoptimal work (unnecessary waste time).<br>
<br>
see <a href="http://www.qos.ch/shop/index" target="_blank">http://www.qos.ch/shop/index</a><br>
"Quality Open Software [...] mission-critical enterprise software"<br>
<br>
possible workaround - call LoggerContext.stop() manually<br>
in own application shutdown hook after all work completed.<br>
but in this case, - ShutdownHookAction in joran will be useless.<br>
<br>
and this is partial workaround, it can help only in case<br>
of single application shutdown hook. if present multiple<br>
application/libraries shutdown hooks - we in trouble again.<br>
<br>
==============================<u></u>==============================<u></u>===<br>
<br>
in my proposed solution - application exits as soon as possible,<br>
and without any lost events from all application shutdown hooks.<br>
<br>
event lost from (daemon) threads still possible,<br>
but this is unavoidable race condition between<br>
JVM successful exit and between (daemon) thread<br>
attempt to log any info.<br>
<br>
to minimize "deleterious consequences" all what we can<br>
do - is to forcibly set immediateFlush into true<br>
and call outputStream.flush() for all FileAppenders<br>
and forcibly turn AsyncAppenders into transparent sync mode.<br>
<br>
in this case is (daemon) threads attempt to log any info<br>
can cause partially written log file lines or not -<br>
I not investigate so deeply. Probably it can.<br>
In this case we lost only two log lines,<br>
this partially written, and first line<br>
of other process written to this log file in future.<br>
<br>
obvious workaround - always firstly call <a href="http://logger.info" target="_blank">logger.info</a>("")<br>
to write empty line to log file at every application startup.<br>
in this case we can lost only one partially written log file line.<br>
<br>
P.S.<br>
<br>
It is slightly uncomfortable to lost log events,<br>
so I prefer perfect or almost perfect solutions.<br>
<br>
right now I use such solution:<br>
<br>
public class LogbackConfigurator {<br>
<br>
public void init() {<br>
<br>
// ...<br>
<br>
Runtime.getRuntime().<u></u>addShutdownHook(new Thread(new LogbackShutdownHook(), "LogbackShutdownHook"));<br>
}<br>
<br>
private static class LogbackShutdownHook implements Runnable {<br>
<br>
@Override<br>
public void run() {<br>
try {<br>
Thread.sleep(LOGBACK_STOP_<u></u>DELAY_MILLIS);<br>
} catch (InterruptedException ignored) {<br>
}<br>
LoggerContext loggerContext = (LoggerContext) LoggerFactory.<u></u>getILoggerFactory();<br>
loggerContext.stop();<br>
}<br>
}<br>
}<br>
<br>
but it is not perfect.<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div class="h5">
On Tue, Mar 18, 2014 at 6:37 AM, Gena Makhomed wrote:<br>
<br>
Re: AsyncAppenderBase not flushing queue during JVM shutdown<br>
<br>
Michael Reinhold,<br>
I can propose better solution of described problem:<br>
<br>
we just need make two modes of work for logback:<br>
<br>
1. normal mode, as it work all time after configuration finishing.<br>
<br>
2. ready to shutdown mode, - fail safe mode, without messages lost.<br>
<br>
switching from "normal mode" to "ready to shutdown mode"<br>
do via JVM shutdown hook, - just one shutdown hook for logback.<br>
<br>
if logback turned from "normal mode" to "ready to shutdown mode",<br>
logback change own behavior in such way:<br>
<br>
1. all appenders turn "immediateFlush = true",<br>
regardless of initial value in logback configuration,<br>
to prevent message lost during forthcoming JVM shutdown.<br>
<br>
2. all AsyncAppenders turns into transparent and sync mode.<br>
if AsyncAppender work in this "transparent and sync mode",<br>
all behavior of<br>
<br>
app -> AsyncAppender -> RollingFileAppender -> file<br>
<br>
completly identical to behaviour of<br>
<br>
app -> RollingFileAppender -> file<br>
<br>
after switching from "normal mode" to "ready to shutdown mode",<br>
JVM shutdown hook finished work and now logback is ready<br>
to continue logging and also ready to forthcoming JVM shutdown.<br>
<br>
all other components of system still can use logback<br>
for logging during JVM/application shutdown process.<br>
<br>
here is only one unobvious nuance: how to transparently<br>
switch each logback AsyncAppender from async to sync mode<br>
without messages lost and without messages reordering in log.<br>
<br></div></div>
but I am almost sure this is possible to do using java<div class=""><br>
without perceptible performance degrade for AsyncAppender<br>
when it work in normal (async) mode.<br>
<br></div>
==============================<u></u>__==================<div class=""><br>
<br>
IMHO, this is the most robust and most useful way to almost<br>
completly prevent any log messages lost during application and JVM<br>
shutdown.<br>
<br>
LoggerContext.stop() not prevent messages lost,<br>
so it should not be called before JVM shutdown.<br>
<br>
as I understand it mostly will be useful only for web applications,<br></div>
to be called in ServletContextListener.__<u></u>contextDestroyed() callback.<div class=""><br>
<br>
Let me know, what you think about this new proposed solution.<br>
</div></blockquote><span class="HOEnZb"><font color="#888888">
<br>
-- <br>
Best regards,<br>
Gena<br>
</font></span><br>_______________________________________________<br>
Logback-user mailing list<br>
<a href="mailto:Logback-user@qos.ch">Logback-user@qos.ch</a><br>
<a href="http://mailman.qos.ch/mailman/listinfo/logback-user" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-user</a><br></blockquote></div><br></div>