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.

Aaron Digulla · Answer 1 · 2011-02-10T16:23:18.987

6

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.

edited Feb 10 '11 at 16:23

answered Feb 10 '11 at 16:18

Aaron Digulla

321,842
108
597
820

I understand the problem with relative ordering between streams but should the order be correct within each stream? I didn't show the lines annotated by source but the stdout order is incorrect. I wrote a Perl wrapper as well and it has the same problem. Is it possible that the line that's moving is being written directly to the terminal? It seems that it still makes it to stdout though.. – dromodel Feb 10 '11 at 16:27
I tried redirecting using a shell but that has its own problems. First, it's hard to escape the arguments correctly. Second, I would like to keep stderr since this program is just a wrapper. Last, on Solaris I get a "bad file number" error when redirecting within a shell – dromodel Feb 10 '11 at 16:28
The relative order within a stream can't change. If you see a line that appears at different places in the output, then someone else writes that to the terminal. My guess is that the wrapped script starts another process; I'm not sure how it can write to the console when you redirect the stdio of the wrapper, though. – Aaron Digulla Feb 11 '11 at 11:09
Try to add something like "OUT" and "ERR" when you print the streams from Java. That should help to identify what is what. – Aaron Digulla Feb 11 '11 at 11:10

score 1 · Answer 2 · answered Feb 10 '11 at 16:18

1

Try putting System.out.flush after you do your println. If I am right, the messages are appearing in different orders because the System.out is being buffered.

answered Feb 10 '11 at 16:18

Tim

1,276
11
23

Why does output appear in wrong order?

2 Answers2

Linked

Related