Use of readConfiguration method in logging activities

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

Solution 2:

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

Use of readConfiguration method in logging activities

Solution 1:

Solution 2:

Related

Recent Posts