Cause runtime exceptions to be properly ordered with println in console output

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)

Thumbsdown

I've added some details and links to logging packages in my answer @Tyler. As @fge mentions, there is also java.util.logging built into the JVM. – Magus

Can you show some of the code @Tyler? Are you sure the exception happens after the scanner stuff runs? It's not in another thread? – Magus

@Magus This is not some obscure problem. This affects anybody who has done any work with Java. If you want to demonstrate the effect for yourself, just make a loop that spits out a lot of stuff to stdout and then crashes. – Thumbsdown

Uh. I've done a crap ton of Java work and have never seen this. Can you please show some code? This works for me for example: pastebin.com/HbeRZXdC – Magus

Have you tried putting a System.out.flush() before the exception? – Magus

Answer 1

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.

Magus

This answer does not explain the underlying cause. Since the error occurs after the calls to System.out.println, none of the lines to System.err should have been printed before those, yet they did. The first part of my question is to explain why this is occurring. – Thumbsdown

And you thought my answer was not useful @TylerDurden. Huh. – Magus

Answer 2

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.

Undercool

I would like to use the existing console. What do you mean by a "Logger"? Can this be installed seamlessly or will it require an extra nuisance to use? – Thumbsdown

@TylerDurden there is java.util.logging in the JDK – Chatter

Right, this is my point: the console is trying to DISPLAY THEM BOTH SIMULTANEOUSLY to use your exact words. However, in the case above the exception occurs AFTER the output to system.out has been printed, so therefore, all of the error should have been printed after the system.out was printed, since chronologically the error occurred after the system.out.print call. This is the problem I am trying to understand and solve. I consider manually buffering the streams to be a workaround, not a solution. – Thumbsdown

Answer 3

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.

Cakewalk