Text written to piped stdout/stderr is printed out of order

[andrewbrey]

When using the default stdout/stderr streams for a $ command, text written to the different streams in a particular order can appear out of order when printed.

Example

if I run deno run -A main.ts on the following file:

// main.ts
import $ from "https://deno.land/x/dax@0.10.0/mod.ts";

await $`deno eval 'console.log("1: out"); console.error("2: err"); console.log("3: out"); console.log("4: out"); console.error("5: err");'`

the output printed to the terminal is:

1: out
3: out
2: err
5: err
4: out

By contrast, if I inherit the streams from the parent process as:

// main.ts
import $ from "https://deno.land/x/dax@0.10.0/mod.ts";

await $`deno eval 'console.log("1: out"); console.error("2: err"); console.log("3: out"); console.log("4: out"); console.error("5: err");'`
  .stdout("inherit").stderr("inherit");

then the output to the terminal is:

1: out
2: err
3: out
4: out
5: err

Is this "out of order" output because the streams are buffered when not inherited?

[dsherret]

By default, stdout and error are always captured. What may occur is the sub process writes to stdout, stderr, then stdout, but only then does the process running dax start reading which could read all the data in stdout at once, then after all the data in stderr. I don't think there's any way around this since stdout and stderr are two separate pipes. I think the same issue could occur in zx, but maybe the chances are lower because node uses callbacks? https://github.com/google/zx/blob/700bd4cae2ce564aa477b2501b1916c2a9041a85/src/core.ts#L208-L222

if I inherit the streams from the parent process as...

Yeah, if you inherit then it the subprocess will write directly to the deno process's stdout and err, which won't rely on the javascript code waking up and reading from stdout and stderr, storing it, then outputing. If you want to change the default you can do:

import {
  build$,
  CommandBuilder,
} from "...";

const commandBuilder = new CommandBuilder()
  .stdout("inherit")
  .stderr("inherit");
  
const $ = build$({ commandBuilder });

[andrewbrey]

@dsherret Got it, this makes sense, and I bet you're right in your guess about zx!

Out of curiosity, did you consider making the io streams inherited by default and piped as an option?

Thanks for the info and follow up on this - cheers!

Edit: I just ran a test with zx and it does indeed print in the "correct" order - I bet you're right about it being less likely to happen given how node uses callbacks. I wonder what it would take to make it print out of order....maybe larger chunks of data written at once so it can't flush the whole buffer at once? Anyway, interesting!

[dsherret]

Out of curiosity, did you consider making the io streams inherited by default and piped as an option?

I think that would be better because of the existence of the "helper" functions (like $`some_command`.text()) that could automatically change to piped when necessary. I'll do that right now.

[andrewbrey]

Awesome! Thanks for taking a look at this and as always, thank you very much for your work on this (and the Deno ecosystem) 😄

[dsherret]

You're welcome! This is now released in 0.11.0. I'm not sure if there's anything we can do to mitigate this when capturing the output unfortunately.

[andrewbrey]

Nice! Yea, given my new understanding of how this works, I suspect you're right. I will go ahead and close this issue as "that's just kinda how it works" 😄

Fortunately, the new default provides the behavior I expected intuitively, so that's great! Cheers!

[dsherret]

I believe my change in...

b8402df

...should mitigate this issue. I was using async writers everywhere, but it wasn't necessary.