-
Bug
-
Resolution: Unresolved
-
P4
-
8, 9
-
generic
-
os_x
FULL PRODUCT VERSION :
java version "1.8.0_74"
Java(TM) SE Runtime Environment (build 1.8.0_74-b02)
Java HotSpot(TM) 64-Bit Server VM (build 25.74-b02, mixed mode)
ADDITIONAL OS VERSION INFORMATION :
Darwin LANELSON-mac 15.5.0 Darwin Kernel Version 15.5.0: Tue Apr 19 18:36:36 PDT 2016; root:xnu-3248.50.21~8/RELEASE_X86_64 x86_64
A DESCRIPTION OF THE PROBLEM :
I have a class that adds a shutdown hook. The shutdown hook retains a strong reference to a Logger. This Logger does not have a level set on it, so it inherits the effective level from whatever its parent is.
The Logger's parent is set elsewhere before the class (or its shutdown hook) is initialized. That parent Logger has its level set explicitly (to Level.FINER). This parent Logger is created and configured, and then added (before any Logger#getLogger(String) call would ever find it) to the LogManager, via LogManager#addLogger(Logger), which completes successfully. A strong reference is kept to this parent Logger, preventing its garbage collection.
At shutdown time, I observe that my shutdown hook's logging "quits" halfway through, sometimes. Mystified, I guessed that somewhere else there was a shutdown hook that must have been reconfiguring the parent Logger somehow to have a level that causes MY logger to conclude that isLoggable should return false.
Sure enough, I found LogManager$Cleaner(), which calls resetLogger() as it goes about its business, effectively setting the level on the parent logger to null before my shutdown hook's logger has "finished up". The observable result is that depending on the race, my shutdown hook will log about half of what's expected.
REPRODUCIBILITY :
This bug can be reproduced often.
java version "1.8.0_74"
Java(TM) SE Runtime Environment (build 1.8.0_74-b02)
Java HotSpot(TM) 64-Bit Server VM (build 25.74-b02, mixed mode)
ADDITIONAL OS VERSION INFORMATION :
Darwin LANELSON-mac 15.5.0 Darwin Kernel Version 15.5.0: Tue Apr 19 18:36:36 PDT 2016; root:xnu-3248.50.21~8/RELEASE_X86_64 x86_64
A DESCRIPTION OF THE PROBLEM :
I have a class that adds a shutdown hook. The shutdown hook retains a strong reference to a Logger. This Logger does not have a level set on it, so it inherits the effective level from whatever its parent is.
The Logger's parent is set elsewhere before the class (or its shutdown hook) is initialized. That parent Logger has its level set explicitly (to Level.FINER). This parent Logger is created and configured, and then added (before any Logger#getLogger(String) call would ever find it) to the LogManager, via LogManager#addLogger(Logger), which completes successfully. A strong reference is kept to this parent Logger, preventing its garbage collection.
At shutdown time, I observe that my shutdown hook's logging "quits" halfway through, sometimes. Mystified, I guessed that somewhere else there was a shutdown hook that must have been reconfiguring the parent Logger somehow to have a level that causes MY logger to conclude that isLoggable should return false.
Sure enough, I found LogManager$Cleaner(), which calls resetLogger() as it goes about its business, effectively setting the level on the parent logger to null before my shutdown hook's logger has "finished up". The observable result is that depending on the race, my shutdown hook will log about half of what's expected.
REPRODUCIBILITY :
This bug can be reproduced often.
- duplicates
-
JDK-8277880 Log message is not logged in Shutdownhook
- Closed
-
JDK-8029834 LogManager's shutdown hook resets handlers before application shutdown hooks have completed
- Closed
- relates to
-
JDK-6326669 The java logging package needs to allow explicit control of when it shuts down
- Closed