In one of the RMI regression tests, we have been seeing an intermittent (frequent but unfortunately not yet trivial to reproduce) NullPointerException getting thrown from Logger.getLogger(String):
...
# Caused by: java.lang.NullPointerException
# at java.util.logging.Logger.getLogger(Logger.java:180)
# at sun.rmi.runtime.Log$LoggerLogFactory.createLog(Log.java:161)
# at sun.rmi.runtime.Log.getLog(Log.java:128)
...
The particular failing test case is the RMI regression test in test/java/rmi/server/RMISocketFactory/useSocketFactory/activatable/UseCustomSocketFactory.java; it has failed several times, only on a particular NT machine, during automated runs of large test batches, but the failure hasn't yet been reproduced with a manual jtreg run of only that particular test (on the same machine).
From inspection of the code surrounding Logger.java:180:
public static synchronized Logger getLogger(String name) {
if (name.equals("")) {
throw new IllegalArgumentException("need a logger name");
}
LogManager manager = LogManager.getLogManager();
Logger result = manager.getLogger(name);
if (result == null) {
manager.addLogger(new Logger(name, null));
result = manager.getLogger(name);
*****> result.levelObject = manager.getLevel(name); <***** line 180
result.levelValue = result.levelObject.intValue();
}
return result;
}
it seems that the value "result" returned by manager.getLogger(name) must be null (because we know that "manager" can't be null if we've gotten to line 180), even though a Logger with the given name was added using manager.addLogger just two lines earlier.
My speculation is that because LogManager only holds on to added Loggers with weak references, and because the above method does not itself keep a strong reference to the Logger constructed on line 178, then it is possible that the Logger constructed and added on that line could be garbage collected before line 179 executes. It is surprising that this would occur as often as it has been for the failing test case, but at any rate, unless I am missing something, it does seem like the above code has this flaw: it should hold a strong reference to the constructed Logger through line 179.
I do not have a reliablily reproducible test case that proves this explanation of the regression test failure, but I have tried a different experiment that provides, I think, very strong evidence: after adding a "System.gc()" invocation in between lines 178 and 179 of Logger.java, which should not interfere with the correctness of the code, then even the most trivial invocation of Logger.getLog fails with a similar NullPointerException:
Exception in thread "main" java.lang.ExceptionInInitializerError
at LoggerTest.main(LoggerTest.java:13)
Caused by: java.lang.NullPointerException
at java.util.logging.Logger.getLogger(Logger.java:181)
at java.util.logging.Logger.<clinit>(Logger.java:123)
... 1 more
Furthermore, storing the newly constructed Logger in a local field eliminates this NPE, even in the presence of the experimental System.gc() addition:
public static synchronized Logger getLogger(String name) {
if (name.equals("")) {
throw new IllegalArgumentException("need a logger name");
}
LogManager manager = LogManager.getLogManager();
Logger result = manager.getLogger(name);
if (result == null) {
Logger logger = new Logger(name, null);
manager.addLogger(logger);
System.gc();
result = manager.getLogger(name);
result.levelObject = manager.getLevel(name);
result.levelValue = result.levelObject.intValue();
}
return result;
}
...
# Caused by: java.lang.NullPointerException
# at java.util.logging.Logger.getLogger(Logger.java:180)
# at sun.rmi.runtime.Log$LoggerLogFactory.createLog(Log.java:161)
# at sun.rmi.runtime.Log.getLog(Log.java:128)
...
The particular failing test case is the RMI regression test in test/java/rmi/server/RMISocketFactory/useSocketFactory/activatable/UseCustomSocketFactory.java; it has failed several times, only on a particular NT machine, during automated runs of large test batches, but the failure hasn't yet been reproduced with a manual jtreg run of only that particular test (on the same machine).
From inspection of the code surrounding Logger.java:180:
public static synchronized Logger getLogger(String name) {
if (name.equals("")) {
throw new IllegalArgumentException("need a logger name");
}
LogManager manager = LogManager.getLogManager();
Logger result = manager.getLogger(name);
if (result == null) {
manager.addLogger(new Logger(name, null));
result = manager.getLogger(name);
*****> result.levelObject = manager.getLevel(name); <***** line 180
result.levelValue = result.levelObject.intValue();
}
return result;
}
it seems that the value "result" returned by manager.getLogger(name) must be null (because we know that "manager" can't be null if we've gotten to line 180), even though a Logger with the given name was added using manager.addLogger just two lines earlier.
My speculation is that because LogManager only holds on to added Loggers with weak references, and because the above method does not itself keep a strong reference to the Logger constructed on line 178, then it is possible that the Logger constructed and added on that line could be garbage collected before line 179 executes. It is surprising that this would occur as often as it has been for the failing test case, but at any rate, unless I am missing something, it does seem like the above code has this flaw: it should hold a strong reference to the constructed Logger through line 179.
I do not have a reliablily reproducible test case that proves this explanation of the regression test failure, but I have tried a different experiment that provides, I think, very strong evidence: after adding a "System.gc()" invocation in between lines 178 and 179 of Logger.java, which should not interfere with the correctness of the code, then even the most trivial invocation of Logger.getLog fails with a similar NullPointerException:
Exception in thread "main" java.lang.ExceptionInInitializerError
at LoggerTest.main(LoggerTest.java:13)
Caused by: java.lang.NullPointerException
at java.util.logging.Logger.getLogger(Logger.java:181)
at java.util.logging.Logger.<clinit>(Logger.java:123)
... 1 more
Furthermore, storing the newly constructed Logger in a local field eliminates this NPE, even in the presence of the experimental System.gc() addition:
public static synchronized Logger getLogger(String name) {
if (name.equals("")) {
throw new IllegalArgumentException("need a logger name");
}
LogManager manager = LogManager.getLogManager();
Logger result = manager.getLogger(name);
if (result == null) {
Logger logger = new Logger(name, null);
manager.addLogger(logger);
System.gc();
result = manager.getLogger(name);
result.levelObject = manager.getLevel(name);
result.levelValue = result.levelObject.intValue();
}
return result;
}