[logback-user] how to graceful shutdown logback with AsyncAppenders and without immediateFlush

[Gena Makhomed]

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
-------------- next part --------------

public class TestApplication {

    public static void main(String[] args) {

        Thread logbackShutdownHook = new Thread(new LogbackShutdownHook());
        Runtime.getRuntime().addShutdownHook(logbackShutdownHook);

        Thread appShutdownHook = new Thread(new AppShutdownHook());
        Runtime.getRuntime().addShutdownHook(appShutdownHook);

        try {
            Thread.sleep(30000);
        } catch (InterruptedException ignored) {
        }
        System.err.println("TestApplication exited normally");
    }

    private static class LogbackShutdownHook implements Runnable {

        @Override
        public void run() {
            System.err.println("LogbackShutdownHook started");
            try {
                Thread.sleep(2000);
            } catch (InterruptedException ignored) {
            }
            System.err.println("LogbackShutdownHook finished");
        }
    }

    private static class AppShutdownHook implements Runnable {

        @Override
        public void run() {
            System.err.println("AppShutdownHook started");
            try {
                Thread.sleep(10000);
            } catch (InterruptedException ignored) {
            }
            System.err.println("AppShutdownHook finished");
        }
    }
}