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