java - Why does output appear in wrong order?

Question

I'm trying to write a Groovy script that wraps another command and am having trouble with the stdout/stderr order. My script is below:

#!/usr/bin/env groovy
synchronized def output = ""
def process = "qrsh ${args.join(' ')}".execute()

def outTh = Thread.start {
  process.in.eachLine {
    output += it
    System.out.println "out: $it"
  }
}

def errTh = Thread.start {
  process.err.eachLine {
    output += it
    System.err.println "err: $it"
  } 
} 

outTh.join()
errTh.join()
process.waitFor()
System.exit(process.exitValue())

My problem is that the output doesn't appear on the terminal in the correct order. Below is the wrapper's output.

[<cwd>] wrap.groovy -cwd -V -now n -b y -verbose ant target
waiting for interactive job to be scheduled ...
Your interactive job 2831303 has been successfully scheduled.
Establishing builtin session to host <host> ...
Buildfile: build.xml

BUILD FAILED
Target "target" does not exist in the project "null". 

Total time: 0 seconds
Your job 2831303 ("wrap.groovy") has been submitted

Below is the unwrapped command output.

[<cwd>] qrsh -cwd -V -now n -b y -verbose ant target
Your job 2831304 ("ant") has been submitted
waiting for interactive job to be scheduled ...
Your interactive job 2831303 has been successfully scheduled.
Establishing builtin session to host host ...
Buildfile: build.xml

BUILD FAILED
Target "target" does not exist in the project "null". 

Total time: 0 seconds

Why does the "Your job has been submitted" message appear as the first line in one cast and the last line in another? I'm guessing it's related to Java libraries, not Groovy.

Answer 1

This is because of buffering. The threads which read stdout and stderr will not process the output the moment it is written by the child process. Instead, both streams are buffered, so your process won't see anything unless the child flushes the streams).

When the data is on the way, which thread gets the CPU first? There is no way to tell. Even if the data for stderr arrives a few milliseconds before stdout, if the stdout thread has the CPU right now, it will get its data first.

What you could do is use Java NIO (channels) and a single thread and first process all output from stderr but that still wouldn't guarantee that the order is preserved. Because of the buffering between child and parent process, you could get 4KB of text from one stream before you see a single byte of the other.

Unfortunately, there is no cross-platform solution because Java doesn't have an API to merge the two streams into one. On Unix, you could run the command with sh -c cmd 2>&1. That would redirect stderr to stdout. In the parent process, you could then just read stdout and ignore stderr.

The same works for OS X (since it's Unix based). On Windows, you could install Perl or a similar tool to run the process; that allows you to mess with the file descriptors.

PS: Pray that args never contains spaces. String.execute() is a really bad way to run a process; use java.lang.ProcessBuilder instead.