JDK-6947908 : JAVA Logging interface is not threadsafe since 1.6.0_18
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.logging
  • Affected Version: 6u20
  • Priority: P3
  • Status: Closed
  • Resolution: Duplicate
  • OS: solaris_2.5.1
  • CPU: x86
  • Submitted: 2010-04-28
  • Updated: 2011-02-16
  • Resolved: 2010-10-05
Related Reports
Duplicate :  
Relates :  
Description
FULL PRODUCT VERSION :
java version "1.6.0_18"
Java(TM) SE Runtime Environment (build 1.6.0_18-b07)
Java HotSpot(TM) Server VM (build 16.0-b13, mixed mode)


ADDITIONAL OS VERSION INFORMATION :
Linux hostname 2.6.9-42.EL.vision.1smp #1 SMP Tue Feb 3 09:56:18 EST 2009 i686 i686 i386 GNU/Linux
and
Linux hostname 2.6.18-164.el5PAE #1 SMP Tue Aug 18 15:59:11 EDT 2009 i686 i686 i386 GNU/Linux

EXTRA RELEVANT SYSTEM CONFIGURATION :
Both machines have more than one core.

A DESCRIPTION OF THE PROBLEM :
When multiple threads are logging at the same time, the getLogger() function eventually returns a different logger than the one initialized when it was called the first time. All the configuration done on the first logger is then lost.

The problem started appearing in 1.6.0_18. I validated that it still exists in 1.6.0_20 and that it wasn't in 1.6.0_17.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
I did this test class to reproduce the problem.
It should exit when the reference to the initial logger is lost.
I noticed that it crashes much quickly when the function initRootLogger() is called. It usually takes 1 to 2 seconds to exit with an error. When initRootLogger() isn't called, it can take a couple of seconds to a couple of minutes.

package loggertester;

import java.util.logging.*;

public class LoggerTester {

    public static String LOGGER = "tester";

     public void initRootLogger() {
        Logger.getLogger("").getHandlers();
        Logger rootLogger = Logger.getLogger("");
        rootLogger.setLevel(Level.INFO);
        Handler[] handlers = rootLogger.getHandlers();
        for (Handler handler : handlers) {
            handler.setLevel(Level.INFO);
        }
    }

    public void start() {
        String initialLogger = Logger.getLogger(LOGGER).toString();
        while (true) {
            if (!initialLogger.equals(Logger.getLogger(LOGGER).toString())) {
                System.out.println("Logger changed from " + initialLogger + " to " + Logger.getLogger(LOGGER));
                System.exit(-1);
            }
            Logger.getLogger(LOGGER).fine("LoggerTester log");
        }
    }

    public static void main(String[] args) {
        LoggerTester tester = new LoggerTester();
        tester.initRootLogger();
        Thread thread = new Thread() {
            @Override
            public void run() {
                while (true) {
                    Logger.getLogger(LOGGER).fine("Thread log");
                }
            }
        };
        System.out.println("Starting logger loops");
        thread.start();
        tester.start();
    }
}

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
The program should never exit as the logger returned by getLogger() should always be the same.
ACTUAL -
The program returns saying that the logger changed in the course of the execution.

REPRODUCIBILITY :
This bug can be reproduced always.

CUSTOMER SUBMITTED WORKAROUND :
1.6.0_17 works as expected.

Release Regression From : 6u17
The above release value was the last known release where this 
bug was not reproducible. Since then there has been a regression.

Comments
EVALUATION The JavaDoc changes have been made via the following bug: 6949710 3/3 the GC'able nature of Logging objects needs to be made brutally clear I'm closing this bug as a duplicate of 6949710.
05-10-2010

EVALUATION The test for this bug creates the Logger in the start() function: String initialLogger = Logger.getLogger(LOGGER).toString(); The above line causes a Logger named by string LOGGER to be created; the Logger name will be "tester". In this test, subsequent accesses to the Logger are always of the form: Logger.getLogger(LOGGER) which fetches the Logger object *by name*. However, the test does not keep a strong reference to the Logger object anywhere which means that the initial Logger object that was created is GC'able at anytime. This type of programming error is revealed by the fix for the following bug: 6274920 4/2 JDK logger holds strong reference to java.util.logging.Logger instances Prior to the fix for 6274920, Logger objects were never GC'able which was in direct violation of the spec for Logging. In the JavaDoc for Logger.getLogger(): http://java.sun.com/javase/6/docs/api/java/util/logging/Logger.html#getLogger%28java.lang.String%29 it talks about how the Logger is created if it doesn't exist or an existing Logger by the same name is returned. The following sentence in the description is key to this issue: It will be registered in the LogManager global namespace. Jumping into the LogManager JavaDoc, the addLogger() is function is how a Logger is registered: http://java.sun.com/javase/6/docs/api/java/util/logging/LogManager.html#addLogger%28java.util.logging.Logger%29 The following sentences are key: The application should retain its own reference to the Logger object to avoid it being garbage collected. The LogManager may only retain a weak reference.
04-05-2010

EVALUATION I've modified a copy of the test program to illustrate that adding a strong reference to the Logger object fixes the test program: $ diff -c LoggerTester.java.orig LoggerTester.java *** LoggerTester.java.orig Tue May 4 15:07:47 2010 --- LoggerTester.java Tue May 4 15:24:05 2010 *************** *** 5,10 **** --- 5,11 ---- public class LoggerTester { public static String LOGGER = "tester"; + public static Logger MY_LOGGER = null; public void initRootLogger() { Logger.getLogger("").getHandlers(); *************** *** 17,29 **** } public void start() { ! String initialLogger = Logger.getLogger(LOGGER).toString(); while (true) { if (!initialLogger.equals(Logger.getLogger(LOGGER).toString())) { System.out.println("Logger changed from " + initialLogger + " to " + Logger.getLogger(LOGGER)); System.exit(-1); } Logger.getLogger(LOGGER).fine("LoggerTester log"); } } --- 18,40 ---- } public void start() { ! // String initialLogger = Logger.getLogger(LOGGER).toString(); ! MY_LOGGER = Logger.getLogger(LOGGER); ! String initialLogger = MY_LOGGER.toString(); ! int count = 0; while (true) { if (!initialLogger.equals(Logger.getLogger(LOGGER).toString())) { System.out.println("Logger changed from " + initialLogger + " to " + Logger.getLogger(LOGGER)); + System.out.println("count=" + count); System.exit(-1); } Logger.getLogger(LOGGER).fine("LoggerTester log"); + // repros after 11316 iterations on my WinXP VMWare client + count++; + if (count > 500000) { + System.out.println("Logger did not change in 500,000 iterations!"); + System.exit(0); + } } } By saving a strong reference to the application's Logger object (MY_LOGGER), the remaining uses of Logger.getLogger(LOGGER) no longer run the risk of the application's Logger object being GC'ed out from under it.
04-05-2010

EVALUATION Although this issue is caused by an error in the test program, the JavaDoc is a bit obscure about this semantic. It might be a good idea to duplicate the following wording: The application should retain its own reference to the Logger object to avoid it being garbage collected. in the two Logger.getLogger() APIs.
04-05-2010