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@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@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user