System.setErr() interferes with Logger

Question

In a larger program, I am using a static java.util.logging.Logger instance, but redirecting System.err to several different files in succession. The Logger fails to log the second time I try to redirect System.err.

Here's a test program to show the problem:

import java.io.FileNotFoundException;
import java.io.PrintStream;
import java.util.logging.Logger;

class TestRedirect {
    static final Logger logger = Logger.getLogger("test");

    public static void main(String[] args) throws FileNotFoundException {
        for (int i = 1; i <= 2; i++) {
            TestRedirect ti = new TestRedirect();
            ti.test(i);
        }
    }

    void test(int i) throws FileNotFoundException {
        PrintStream filePrintStream = new PrintStream("test" + i + ".log");
        PrintStream stderr = System.err; // Save stderr stream.
        System.setErr(filePrintStream);  // Redirect stderr to file.
        System.err.println("about to log " + i);
        logger.info("at step " + i);
        System.setErr(stderr);           // Restore stderr stream.
        filePrintStream.close();
    }
}

Here's the output:

test1.log:

about to log 1
Jan 28, 2014 4:34:20 PM TestRedirect test
INFO: at step 1

test2.log:

about to log 2

I thought I would see a Logger-generated message in test2.log as well. Why does the Logger stop working, and what could I do about this?

Answer 1

By default the JRE is configured to load a ConsoleHandler on the root logger. Your log message will travel up to the root logger handlers by default. The root logger handlers are loaded on demand. In your current program, the lazy loading of the root logger ConsoleHandler is capturing your 1st redirected System.err. After that, the root logger handler is never reloaded which is why you'll never see the log message in log 2. Plus the 1st redirected stream is closed so now the root ConsoleHandler is writing to a closed stream.

To prove this point, add the following as the first lines of your test case main method and run the program.

Logger.getLogger("").getHandlers(); //Force load root logger handlers.
Logger.getLogger("").removeHandler((Handler) null);

You'll see that now no logger messages are recorded. If you are curious why this works you can read the java.util.logging.LogManager$RootLogger source code for details.

What you need to do is create a StreamHandler with your redirected System.err stream and then add and remove the StreamHandler from your logger. You can also toggle the use of parent handlers on your logger config to avoid writing to the original System.err.

Another possible solution would be to find all ConsoleHandler instances. Remove and close all of them. Perform the remap System.err. Then create and attach new ConsoleHandlers.

JDK wise, the ConsoleHandler and ErrorManager should have been designed to use the java.io.FileDescriptor which is never redirected.