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?.

Pettifer

Answer 1

I have encountered many more mistakes with the readConfiguration method. It does not what you would expect it to do. I have created a small Unit Test to illustrate this:

package com.demo;

import java.io.IOException;
import java.io.InputStream;
import java.util.logging.LogManager;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * @author dhubau
 */
public class LogTest {

    private static final Logger logger = LoggerFactory.getLogger(LogTest.class.getCanonicalName());

    @Test
    public void testLogs() throws IOException {
        logger.trace("BEFORE");
        logger.debug("BEFORE");
        logger.info("BEFORE");
        logger.warn("BEFORE");
        logger.error("BEFORE");

        InputStream is = LogTest.class.getResourceAsStream("/logging.properties");

        LogManager.getLogManager().readConfiguration(is);

        logger.trace("AFTER");
        logger.debug("AFTER");
        logger.info("AFTER");
        logger.warn("AFTER");
        logger.error("AFTER");
    }
}

When starting the unit test, the default logging.properties is read (defaulting everything to INFO logging). I log every level once and then read in my own logging.properties file:

# Specify the handlers to create in the root logger
handlers = java.util.logging.ConsoleHandler

# Set the default logging level for the root logger
.level = INFO

# Do not use the root handlers
com.demo.useParentHandlers = false

# DEMO log handlers
com.demo.handlers = java.util.logging.ConsoleHandler

# DEMO log level
com.demo.level = ALL

# Set the default logging level for new ConsoleHandler instances
java.util.logging.ConsoleHandler.level = ALL

After which I get the following output:

May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: AFTER

So you see, the com.demo package is not logging TRACE or DEBUG levels. When I pass the following parameter to the unit test:

java.util.logging.config.file = C:\TEMP\logging.properties

It gives me the following output:

May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
FINEST: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
FINE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: BEFORE
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
INFO: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
WARNING: AFTER
May 24, 2013 11:27:29 AM com.demo.LogTest testLogs
SEVERE: AFTER

Umbles

I agree with you Dieter, this method does not do what you expect. Instead of relying on this method for accessing a file containing logging properties in my applications I've moved to a solution which consists on defining programatically my Logger and all components associated with it. I feel more confident and comfortable with this. – Pettifer

Answer 2

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");
}

Shaniqua

Answer 3

In JDK 9, JDK-8033661: readConfiguration does not cleanly reinitialize the logging system has been marked as resolved. The LogManager.readConfiguration has been respecified to only setup loggers during initialization of the LogManager.

To update loggers after initialization the LogManager.updateConfiguration(java.util.function.Function) method is supposed to be used. An example remapper function can be found in the HandlersOnComplexResetUpdate.java test:

static void updateConfigurationWith(Properties propertyFile, boolean append) {
    try {
        ByteArrayOutputStream bytes = new ByteArrayOutputStream();
        propertyFile.store(bytes, propertyFile.getProperty("test.name"));
        ByteArrayInputStream bais = new ByteArrayInputStream(bytes.toByteArray());
        Function<String, BiFunction<String,String,String>> remapper =
            append ? (x) -> ((o, n) -> n == null ? o : n)
                   : (x) -> ((o, n) -> n);
        LogManager.getLogManager().updateConfiguration(bais, remapper);
     } catch (IOException ex) {
         throw new RuntimeException(ex);
     }
}

Banket