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

[Michael Reinhold]

Hi Gena,

Thank you for your suggestion - it always appreciated to have additional
input into a design.

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

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.

Regards,

Mike Reinhold


On Tue, Mar 18, 2014 at 6:37 AM, Gena Makhomed <gmm at csdoc.com> 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.
>
> bit 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 at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20140318/a26b4e47/attachment.html>