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

[David M. Lloyd]

Given that this issue has existed (and been known) since 1.4, I doubt 
anyone is particularly inclined to fix it.  The most common workaround I 
know of is to simply use or create a LogManager that implements reset() 
as a no-op.  Just subclassing the built-in LogManager is sufficient to 
do this.

On 12/09/2013 11:59 AM, Laurent Bourgès wrote:
> 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


-- 
- DML