JDK-7016208 : null sometimes returned by java.util.logging.Logger.getLogger(String name) in -server -Xcomp
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.logging
  • Affected Version: hs20
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2011-02-01
  • Updated: 2011-07-18
  • Resolved: 2011-07-18
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 7
7 b143Fixed
Related Reports
Relates :  
JDK-6814140 - deadlock due to synchronized demandLogger() code that locks ServerLogManager
Relates :  
JDK-7045441 - locking analysis and other possible improvements for Logging API
Relates :  
JDK-6487638 - Calling LogManager.addLogger() and Logger.getLogger() cause deadlock
Description
The test

nsk/logging/stress/threads/scmhml001

failed in JDK 7 b124 (HS 20.0-b05) promotion testing with the following message:

[2011-01-11T22:31:42.19] # Actual: C:/local/common/jdk/baseline/windows-i586/bin/java -server -Xcomp -XX:+StartAttachListener -XX:+UseParallelGC nsk.logging.stress.threads.scmhml001 25 25 25
[2011-01-11T22:31:42.19] # Test level exit status: 151
[2011-01-11T23:01:43.30] # Cygwin watchdog kill: 9740 4936
[2011-01-11T23:01:43.49] Exception in thread "main" java.lang.NullPointerException
[2011-01-11T23:01:43.55]           at nsk.logging.stress.threads.scmhml001.doTest(scmhml001.java:81)
[2011-01-11T23:01:43.55]           at nsk.logging.stress.threads.scmhml001.run(scmhml001.java:53)
[2011-01-11T23:01:43.55]           at nsk.logging.stress.threads.scmhml001.main(scmhml001.java:31)
[2011-01-11T23:01:43.55] # Host info: CYGWIN_NT-5.2-WOW64 vmsqe-p4-04 1.5.25(0.156/4/2) 2008-06-12 19:34 i686 Cygwin

http://vmsqe.russia.sun.com/execution/results/JDK7/PROMOTION/VM/7/b124/ParallelGC/vm/windows-i586/server/comp/windows-i586_vm__server_comp_nsk.logging.testlist/ResultDir/scmhml001/scmhml001.log

The test appeares to hang, because by the time the main thread dies of NPE, it has started a number of handler threads that seat and wait in socket reads.

Platform: windows-i586
Machine: vmsqe-p4-04.russia.sun.com
Options: -server -Xcomp -XX:+StartAttachListener -XX:+UseParallelGC


Relevant part of the test code:

 73        for (int n=0; n<controllers.length; n++) {
 74            controllers[n] = new SocketController();
 75            Handler handler = controllers[n].getHandler();
 76
 77            for (int i=0; i<loggers.length; i++) {
 78                String name_n_i = testName.replace('/','.')
 79                    + ".logger_" + n + "_" + i;
 80                loggers[n][i] = Logger.getLogger(name_n_i);
 81                loggers[n][i].addHandler(handler);
 82                loggers[n][i].setLevel(Level.FINEST);
 83                //
 84                threads[n][i] = new MyThread(n,i,loggers[n][i]);
 85            };
 86        };


Apparently, Logger.getLogger(name_n_i) returned null.
Comments
EVALUATION LogManager.demandLogger() was originally added by the following bug fix: 6487638 3/3 Calling LogManager.addLogger() and Logger.getLogger() cause deadlock as a "synchronized" method. "synchronized" was removed by the following bug fix: 6814140 2/2 deadlock due to synchronized demandLogger() code that locks ServerLogManager While removing "synchronized" fixed the deadlock in 6814140, it opened the window for the race between addLogger() finding another thread had added the new Logger and getLogger() observing null when it tried to fetch it.
16-05-2011
SUGGESTED FIX Here is the context diff version of this fix: $ hg diff -r 2ecb989b6fcc -r b2db38eb3b13 src/share/cla sses/java/util/logging/LogManager.java diff -r 2ecb989b6fcc -r b2db38eb3b13 src/share/classes/java/util/logging/LogManager.java --- a/src/share/classes/java/util/logging/LogManager.java Mon May 16 12:56:29 2011 -0700 +++ b/src/share/classes/java/util/logging/LogManager.java Mon May 16 12:57:40 2011 -0700 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -342,12 +342,35 @@ public class LogManager { // already been created with the given name it is returned. // Otherwise a new logger instance is created and registered // in the LogManager global namespace. + + // This method will always return a non-null Logger object. + // Synchronization is not required here. All synchronization for + // adding a new Logger object is handled by addLogger(). Logger demandLogger(String name) { Logger result = getLogger(name); if (result == null) { - result = new Logger(name, null); - addLogger(result); - result = getLogger(name); + // only allocate the new logger once + Logger newLogger = new Logger(name, null); + do { + if (addLogger(newLogger)) { + // We successfully added the new Logger that we + // created above so return it without refetching. + return newLogger; + } + + // We didn't add the new Logger that we created above + // because another thread added a Logger with the same + // name after our null check above and before our call + // to addLogger(). We have to refetch the Logger because + // addLogger() returns a boolean instead of the Logger + // reference itself. However, if the thread that created + // the other Logger is not holding a strong reference to + // the other Logger, then it is possible for the other + // Logger to be GC'ed after we saw it in addLogger() and + // before we can refetch it. If it has been GC'ed then + // we'll just loop around and try again. + result = getLogger(name); + } while (result == null); } return result; }
16-05-2011
SUGGESTED FIX See 6977677 for this fix in webrev format.
16-05-2011
EVALUATION Changeset: b2db38eb3b13 Author: dcubed Date: 2011-05-16 12:57 -0700 URL: http://hg.openjdk.java.net/jdk7/tl/jdk/rev/b2db38eb3b13 7016208: 4/3 null sometimes returned by java.util.logging.Logger.getLogger(String name) in -server -Xcomp Summary: Logger can be GC'ed between LogManager.addLogger() and LogManager.getLogger() Reviewed-by: dsamersoff, never, acorn, mchung ! src/share/classes/java/util/logging/LogManager.java
16-05-2011
EVALUATION The code in LogManager.demandLogger is using weak references and isn't being careful to keep strong references. // in the LogManager global namespace. Logger demandLogger(String name) { Logger result = getLogger(name); if (result == null) { result = new Logger(name, null); addLogger(result); result = getLogger(name); } return result; } The new Logger line allocates the logger and then hands it off to addLogger. THe compiler considers that value to be dead once it enters that call. Once addLogger puts that into a WeakReference it becomes reclaimable so the next getLogger call can return null if it happens to get in between. The javadoc for addLogger specifically mentions this as a concern but the JLS is very vague on what constitutes maintaining a strong reference to a value. It does state that objects which are no longer involved in computations can be reclaimed and the lack of any use of result after the addLogger call meets that criteria. Using a while (result == null) loop instead would work as you would just retry until it isn't reclaimed. You could also do this I think: Logger result2 = getLogger(name); if (result2 != result) result = result2;
08-04-2011