Strange JUnit Log Behavior

Question

I notice some weird behavior using standard logging during JUnit tests. Does JUnit translate standard output to another thread? How can I access this?

Here is a simple JUnit test that demonstrates the behavior that I am 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 } 

Note that I created a new log 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 does message 1 or message 2 not appear in the Standard Output section of JUnit output?

Thanks!

Answer 1

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

It seems that stdout is actually being redirected to another (JUnit) thread. However, the real problem was that the StreamHandler buffer was not flushed until stdout was reset to its original output stream (as a result, the log messages did not appear in the JUnit output for stdout). Changing the code to the following gives the correct 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) 

Answer 2

As you indirectly assume, junit testers redirect stdout and stderr to a separate thread during the test. Your registrar is usually initialized before this redirect, which means that it uses the regular System.out / System.err system to log into the console.

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

Edit: I looked at some source code because your question aroused my curiosity. I don't know which TestRunner you are using, and the answer may be there; thread redirection etc. are not part of the junit framework, but are implemented using ant / eclipse / maven / idea. It sounds like you added that Handler has no effect, so I suspect something is intercepting it (your output would be logical if all the logging was done by the parent registrar).