Weird JUnit logging behavior

Question

I'm noticing some weird behavior using standard logging during JUnit tests. Does JUnit redirect standard output to a different stream? How can I get access to that?

Here's a simple JUnit test that demonstrates the behavior I'm describing.

@Test
public void logMessage() {
    // set up new logger with output directed to standard out
    Logger logger = Logger.getLogger("my.test.logger");
    logger.addHandler(new StreamHandler(System.out, new SimpleFormatter()));

    // log a warning message
    logger.warning("logger message"); // message 1

    // turn off parent handlers
    logger.setUseParentHandlers(false);

    // log a second warning message
    logger.warning("second logger message"); // message 2

    // print somehting to standard output
    System.out.println("standard output message");  //message 3
}

Notice that I've created a new logger that simply sends its log messages to standard output (System.out).

Here's the Junit output

Testsuite: com.my.FormatterTest
Feb 19, 2009 12:02:33 PM com.my.FormatterTest logMessage
WARNING: logger message
standard output message
Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.079 sec

------------- Standard Output ---------------
standard output message
------------- ---------------- ---------------
------------- Standard Error -----------------
Feb 19, 2009 12:02:33 PM com.my.FormatterTest logMessage
WARNING: logger message
------------- ---------------- ---------------
Feb 19, 2009 12:02:33 PM com.my.FormatterTest logMessage
WARNING: logger message
Feb 19, 2009 12:02:33 PM com.my.FormatterTest logMessage
WARNING: second logger message
test:
BUILD SUCCESSFUL (total time: 2 seconds)

Why don't message 1 or message 2 show up in the Standard Output portion of the JUnit output?

Thanks!

Answer 1

As you indirectly suggest, the junit testrunners redirect stdout and stderr to a separate stream while the test is running. Your logger is normally initialized before this redirection occurs, which means it uses the regular System.out/System.err for logging to console.

This can be fairly easily seen by looking at the source for the JunitTestRunner class.

Edit: I have looked at some of the source code because your question made me curious. I do not know which TestRunner you are using, and the answer may lay there; the stream redirections etc are not a part of the junit framework but are implemented by ant/eclipse/maven/idea. It looks like you addHandler has no effect whatsovever , so I suspect something is intercepting it (your output would be logical if all the logging was done by a parent logger).

Answer 2

krosenvold's comments led me to the right answer (thanks!).

It appears as if stdout is in fact redirected to another (JUnit) stream. The real problem however, was that the the StreamHandler's buffer was not flushed until after stdout was reset to it's original output stream (resulting in the log messages not appearing in JUnit's output for stdout). Changing the code to the following gives the right behavior.

@Test
public void logMessage() {
    // set up new logger with output directed to standard out
    Logger logger = Logger.getLogger("my.test.logger");
    StreamHandler sh = new StreamHandler(System.out, new SimpleFormatter());
    logger.addHandler(sh);

    // log a warning message
    logger.warning("logger message"); // message 1

    // turn off parent handlers
    logger.setUseParentHandlers(false);

    // log a second warning message
    logger.warning("second logger message"); // message 2

    // print somehting to standard output
    System.out.println("standard output message");  //message 3

    // FLUSH THE STREAM HANDLER !!!
    sh.flush();
}

yeilds

Testsuite: com.my.FormatterTest
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: logger message
standard output message
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: logger message
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: second logger message
Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.078 sec

------------- Standard Output ---------------
standard output message
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: logger message
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: second logger message
------------- ---------------- ---------------
------------- Standard Error -----------------
Feb 20, 2009 12:58:17 PM com.my.FormatterTest logMessage
WARNING: logger message
------------- ---------------- ---------------
test:
BUILD SUCCESSFUL (total time: 2 seconds)
time: 2 seconds)