Conflicts between JVM application and j.u.l logging shutdown hooks

[Laurent Bourgès]

Anybody wants to look at this logging issue I reported several months ago?

Le 27 juin 2013 11:57, "Laurent Bourgès" <bourges.laurent at gmail.com> a
écrit :
>
> Dear members,
>
> I have a problem within an external library using one JVM Shutdown hook
to perform resource cleanup (socket, lock file deletion ...) that seems
buggy in java web start environment: sometimes the JVM reports an
IllegalStateException happenning during that shutdown hook.
>
> This library uses java.util.logging to log warnings and exceptions but
none is logged (console or java trace files).
>
> The 'lost' log messages is related to the LogManager's shutdown hook:
>     // This private class is used as a shutdown hook.
>     // It does a "reset" to close all open handlers.
>     private class Cleaner extends Thread {
>
>         private Cleaner() {
>             /* Set context class loader to null in order to avoid
>              * keeping a strong reference to an application classloader.
>              */
>             this.setContextClassLoader(null);
>         }
>
>         public void run() {
>             // This is to ensure the LogManager.<clinit> is completed
>             // before synchronized block. Otherwise deadlocks are
possible.
>             LogManager mgr = manager;
>
>             // If the global handlers haven't been initialized yet, we
>             // don't want to initialize them just so we can close them!
>             synchronized (LogManager.this) {
>                 // Note that death is imminent.
>                 deathImminent = true;
>                 initializedGlobalHandlers = true;
>             }
>
>             // Do a reset to close all active handlers.
>             reset();
>         }
>     }
>
> Without any log handler, the log messages are lost during shutdown !
> I think it is annoying as it avoids me getting log and exceptions ...
>
> FYI, the ApplicationShutdownHooks class executes all 'application' hooks
concurrently:
>     static void runHooks() {
>         Collection<Thread> threads;
>         synchronized(ApplicationShutdownHooks.class) {
>             threads = hooks.keySet();
>             hooks = null;
>         }
>
>         for (Thread hook : threads) {
>             hook.start();
>         }
>         for (Thread hook : threads) {
>             try {
>                 hook.join();
>             } catch (InterruptedException x) { }
>         }
>     }
> So it is not possible to define hook priorities ...
>
> However, I looked at the JVM Shutdown class which supports hook
priorities and I think that the J.U.L Cleaner hook should run after all
application hooks.
> Here are the current Shutdown priorities:
>     // The system shutdown hooks are registered with a predefined slot.
>     // The list of shutdown hooks is as follows:
>     // (0) Console restore hook
>     // (1) Application hooks
>     // (2) DeleteOnExit hook
>
> Moreover, as a RFE, it could be useful for applications to be able to
define hook priorities within an application:
> I did that several times registering only 1 shutdown hook and handling
correct ordering on my own ... but could be supported by the JDK itself.
>
> Finally, here are (below) the Open JDK8 usages of Runtime.addShutdownHook
[19 occurrences] which are more system hooks than application hooks:
> com.sun.imageio.stream
> StreamCloser.java
> StreamCloser
> addToQueue
> <anonymous java.security.PrivilegedAction>
> run
>   101:  Runtime.getRuntime().addShutdownHook(streamCloser);
> java.util.logging
> LogManager.java
> LogManager
> LogManager
>   255:  Runtime.getRuntime().addShutdownHook(new Cleaner());
> sun.font
> SunFontManager.java
> SunFontManager
> createFont2D
> <anonymous java.security.PrivilegedAction>
> run
> 2538:  Runtime.getRuntime().addShutdownHook(fileCloser);
> sun.rmi.server
> Activation.java
> Activation
> init
>   240:  Runtime.getRuntime().addShutdownHook(shutdownHook);
> sun.tools.jstat
>
> sun.awt.shell
> Win32ShellFolderManager2.java
> Win32ShellFolderManager2
> ComInvoker
> ComInvoker
> <anonymous java.security.PrivilegedAction<java.lang.Void>>
> run
>   493:  Runtime.getRuntime().addShutdownHook(
> sun.awt.windows
> WToolkit.java
> WToolkit
> registerShutdownHook
> <anonymous java.security.PrivilegedAction<java.lang.Void>>
> run
>   285:  Runtime.getRuntime().addShutdownHook(shutdown);
> sun.java2d.d3d
> D3DScreenUpdateManager.java
> D3DScreenUpdateManager
> D3DScreenUpdateManager
> <anonymous java.security.PrivilegedAction>
> run
>   112:  Runtime.getRuntime().addShutdownHook(shutdown);
> java.util.prefs
> FileSystemPreferences.java
> FileSystemPreferences
> <anonymous java.security.PrivilegedAction<java.lang.Void>>
> run
>   439:  Runtime.getRuntime().addShutdownHook(new Thread() {
> sun.awt.X11
> XToolkit.java
> XToolkit
> init
> <anonymous java.security.PrivilegedAction<java.lang.Void>>
> run
>   350:  Runtime.getRuntime().addShutdownHook(shutdownThread);
> sun.awt
> X11GraphicsDevice.java
> X11GraphicsDevice
> setDisplayMode
> <anonymous java.security.PrivilegedAction<java.lang.Void>>
> run
>   445:  Runtime.getRuntime().addShutdownHook(t);
> java.util.prefs
> MacOSXPreferencesFile.java
> MacOSXPreferencesFile
> timer
>   356:  Runtime.getRuntime().addShutdownHook(flushThread);
> sun.font
> CFontManager.java
> CFontManager
> createFont2D
> <anonymous java.security.PrivilegedAction<java.lang.Object>>
> run
>   232:  Runtime.getRuntime().addShutdownHook(fileCloser);
> sun.lwawt
> LWToolkit.java
> LWToolkit
> init
>     83:  Runtime.getRuntime().addShutdownHook(
>
> I hope that these hooks are already supporting concurrency execution (awt
?) but someone should check if there is no dependencies between them (like
systemd or rc scripts does).
>
> PS: As shutdown hooks are given by the application as Thread class
instances, I suspect also a possible classloader leak ? In Java web start
environment, it may be the cause of my problems as I do not know if the
hook thread is still within the application class loader ...
>
> Laurent Bourgès