java - Use of readConfiguration method in logging activities

Question

In order to use logging in a small Java desktop application I'm trying to understand in depth the operation of some methods. I use a very stupid and small Java program to test them.

In particular, when testing the behaviour of the LogManager.readConfiguration() method I've found something strange. In all tests the LogManager reads its configuration from the properties files located in lib/logging.properties in the JRE directory. At this time, the contents of this file is as follows :

handlers=java.util.logging.ConsoleHandler
myapp2.handlers=java.util.logging.ConsoleHandler
myapp2.MyApp2.handlers=java.util.logging.ConsoleHandler
.level=OFF
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n
myapp2.level=WARNING
myapp2.MyApp2.level=INFO

The code of the java program is :

package myapp2;

import java.io.IOException;
import java.util.logging.LogManager;
import java.util.logging.Logger;

public class MyApp2 {

    private static final Logger LOGGER = Logger.getLogger(MyApp2.class.getPackage().getName());
    private static final Logger LOGGER1 = Logger.getLogger(MyApp2.class.getName());

    /**
     * @param args the command line arguments
     */
    public static void main(String[] args) {
        LOGGER.severe("severe at MyApp2");
        LOGGER.warning("warning at MyApp2");
        LOGGER.info("info at MyApp2");
        LOGGER1.severe("severe1 at MyApp2");
        LOGGER1.warning("warning1 at MyApp2");
        LOGGER1.info("info1 at MyApp2");
        LOGGER1.setLevel(null);
        LOGGER1.setUseParentHandlers(false);
        LOGGER1.severe("severe2 at MyApp2");
        LOGGER1.warning("warning2 at MyApp2");
        LOGGER1.info("info2 at MyApp2");
        try {
            LogManager.getLogManager().readConfiguration();
        } catch (IOException ex) {
            System.out.println("I/O Exception found");
        } catch (SecurityException ex) {
            System.out.println("Error SecurityException found");
        }
        LOGGER.severe("severe3 at MyApp2"); 
        LOGGER1.severe("severe4 at MyApp2");
    }
}

If we execute it WITHOUT the try-catch surrounding the readConfiguration(), works as expected and the output is the following :

SEVERE: severe at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe at MyApp2 [dc. maig 08 14:45:38 CEST 2013] 
WARNING: warning at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:45:38 CEST 2013] 
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe2 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
WARNING: warning2 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]
SEVERE: severe4 at MyApp2 [dc. maig 08 14:45:38 CEST 2013]

but, if we execute WITH the try-catch, the output is :

SEVERE: severe at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
INFO: info1 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe2 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
WARNING: warning2 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]
SEVERE: severe3 at MyApp2 [dc. maig 08 14:46:51 CEST 2013]

Reading the API of the readConfiguration() method it is supposed to reinitialize the logging properties and reread the logging configuration from the file named previously. If so, why severe3 is only showing once (I expect to be displayed two times because of the two LOGGERs present in the program and the forwarding behaviour) and severe4 is missing (I expect to be displayed once)?. May anyone help me undestand this?.

Answer 1

As far as I have seen, the readConfiguration methods have only one flaw, which I found by debugging through the JDK Code because I also missed log messages. They do not load per-logger handlers. If you do not use per-logger handlers, the readConfiguration method should work just fine. The readConfiguration first resets all loggers, removing the handlers amongst other things and then forgets to check for per-logger handlers. Because of that you miss your log messages. You originally had three handlers, the root handler, the handler on your package and the handler on your class. Then you switched off useParentHandlers on your class and called readConfiguration. Now - as useParentHandlers is not reset, probably it should - and your per-logger handlers are not setup anymore, severe3 is only logged once through the root handler and severe4 is not logged at all as useParentHandlers is false and so no fallback to the root handler is done.

The "many more mistakes" described by Dieter are btw. exactly the same issue.

You can also easily work-around the bug if you prefer using a logging configuration file. Just iterate over the already existing loggers after you called readConfiguration and call LogManager.loadLoggerHandlers for each of them. In Groovy this would be

def logManager = LogManager.logManager
logManager.loggerNames.each {
    logManager.loadLoggerHandlers logManager.getLogger(it), it, "${it}.handlers"
}

I tested this and it works. For Java you have to use reflection as it is a private method. Should be something like

LogManager logManager = LogManager.getLogManager();
Method loadLoggerHandlers = LogManager.class.getDeclaredMethod("loadLoggerHandlers", Logger.class, String.class, String.class);
loadLoggerHandlers.setAccessible(true);
for (String loggerName : logManager.getLoggerNames()) {
    loadLoggerHandlers.invoke(logManager, logManager.getLogger(loggerName), loggerName, loggerName + ".handlers");
}