Cause runtime exceptions to be properly ordered wi

Question

A common problem with VM Java console output is that System.out and System.err are not usually synchronized properly, possibly because they are on different threads. This results in mixed up output such as the following:

debugging output mixed up with runtime exception stack trace

[8, 1, 3, 5, 9, 13, 15, 17, 19]
Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: 9
scanning xAnswer: 1 xValue: 1 total: 1 [1, 1, 0, 0, 0, 0, 0, 0, 0]
    at cra.common.Group_jsc.listSubsetSum(Group_jsc.java:29)
scanning xAnswer: 2 xValue: 2 total: 4 [2, 1, 2, 0, 0, 0, 0, 0, 0]
    at cra.common.Group_jsc.main(Group_jsc.java:12)
scanning xAnswer: 3 xValue: 3 total: 9 [3, 1, 2, 3, 0, 0, 0, 0, 0]
scanning xAnswer: 4 xValue: 4 total: 18 [4, 1, 2, 3, 4, 0, 0, 0, 0]
scanning xAnswer: 5 xValue: 5 total: 31 [5, 1, 2, 3, 4, 5, 0, 0, 0]
  reset to xAnswer: 4 xValue: 5 total: 26 [4, 1, 2, 3, 5, 5, 0, 0, 0]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
scanning xAnswer: 5 xValue: 6 total: 41 [5, 1, 2, 3, 5, 6, 0, 0, 0]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
  reset to xAnswer: 4 xValue: 6 total: 35 [4, 1, 2, 3, 6, 6, 0, 0, 0]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:601)
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)
scanning xAnswer: 5 xValue: 7 total: 52 [5, 1, 2, 3, 6, 7, 0, 0, 0]
  reset to xAnswer: 4 xValue: 7 total: 45 [4, 1, 2, 3, 7, 7, 0, 0, 0]
scanning xAnswer: 5 xValue: 8 total: 64 [5, 1, 2, 3, 7, 8, 0, 0, 0]
  reset to xAnswer: 4 xValue: 8 total: 56 [4, 1, 2, 3, 8, 8, 0, 0, 0]

Process finished with exit code 1

Since the exception occurred at the end of the process I would expect the print out of the exception to occur AFTER all the println's in the program. Why is this happening and what can be done to correct the problem?

(note that this particular example is from IntelliJ's IDEA console, but the same thing happens in Eclipse and other Java IDEs)

Answer 1

PyCharm also has this problem, which I believe uses the same IDE engine. There's a fix if you add the following line to your idea.properties file:

output.reader.blocking.mode=true

Get to idea.properties via Help | Edit Custom Properties.

Answer 2

A common problem with VM Java console output is that System.out and System.err are not usually synchronized properly,

No, they are synchronized perfectly. The problem is that the lines are intermixed because they are printed as separate calls to println(...). This is the code from Exception.printStackTrace():

        StackTraceElement[] trace = getOurStackTrace();
        for (int i=0; i < trace.length; i++)
            s.println("\tat " + trace[i]);

Loggers (like log4j) get the full stack trace and turn multiple lines into a single log output call which is then persisted atomically.

Why is this happening and what can be done to correct the problem?

Typically with Unix programs, standard-out is buffered while standard-error is not. I didn't think that this was true with Java but maybe it is. To read the javadocs of System.out:

The "standard" output stream. This stream is already open and ready to accept output data. Typically this stream corresponds to display output or another output destination specified by the host environment or user.

Versus for System.err:

By convention, this output stream is used to display error messages or other information that should come to the immediate attention of a user even if the principal output stream, the value of the variable out, has been redirected to a file or other destination that is typically not continuously monitored.

See this answer for more details: Why do System.err statements get printed first sometimes?

If this running the from the command line, you should redirect the out and err output to different files. Here's how to do that using ~unix:

How to redirect stderr and stdout to different files in the same line of bash?

In Java you can use System.setOut(...) and System.setErr(...) to send the different output to different PrintStreams so the lines don't interleave.

---

You edited the question to note that this is happening from inside an IDE. If you need to use System.out and err then you can redirect them using Java code above.

However, it is typical to use logging code instead. Common logging packages are log4j or logback which writes a single multi-line log message atomically to the output file so they don't get interleaved. As @fge mentions, there is also java.util.logging built into the JVM although the other packages provide more features.

Answer 3

Why is this happening and what can be done to correct the problem?

Because syserr and sysout are separate data streams but the system (IDE) console is trying to display both simultaneously. This can be fixed by using a Logger which will typically correctly order entries in the log.

Another possibility is to invoke System.setErr and assign it to a PrintStream for an error log file. This would be the Java equivalent solution to redirecting the error stream.