Yarn: process.stderr.write message is not displayed if it does not contain a newline

[kuzyn]

Do you want to request a feature or report a bug?

bug

What is the current behavior?
Both npm start and node index.js display the process.stderr.write message in this handler, but not yarn start

process.on('uncaughtException', err => {
  process.stderr.write(`Caught Exception. Err: ${err}`)
  process.exit(1)
})

For it to display when using yarn start, one needs to add a \n to the template literate

process.on('uncaughtException', err => {
  process.stderr.write(`Caught Exception. Err: ${err}\n`)
  process.exit(1)
})

More precisely, everything up until the newline will be flush to the buffer, so if the \n is in the middle, everything before will be shown

If the current behavior is a bug, please provide the steps to reproduce.

https://github.com/kuzyn/test-yarn

What is the expected behavior?
The process.stderr.write message should be displayed regardless of the presence of a newline character

Please mention your node.js, yarn and operating system version.

• OSX 10.12.6
• node v8.9.1
• yarn 1.3.2
• npm 5.5.1

[rally25rs]

This is probably due to https://github.com/nodejs/node/issues/6456 which seems to have a long-standing history in Node land, ever since they made stdio async (v6).

[rally25rs]

@kuzyn if you are in a position where you can reproduce this consistently, could you try this code and see if it works? (I can't reproduce it on Node v8.5.0 on OSX, even using test examples from the above nodejs issue)

process.on('uncaughtException', err => {
  process.stderr.write(`Caught Exception. Err: ${err}`, () => process.exit(1))
})

The 2nd argument can be a callback that is called after the data is flushed, so we should be able to delay exit until that happens.

This is supported in Node v4 which IIRC is as far back as Yarn supports. Docs reference: https://nodejs.org/dist/latest-v4.x/docs/api/stream.html#stream_writable_write_chunk_encoding_callback

[rally25rs]

NPM seems to work because they log through the npmlog module which according to the README:

We use set-blocking to set stderr and stdout blocking if they are tty's and have the setBlocking call. This is a work around for an issue in early versions of Node.js 6.x, which made stderr and stdout non-blocking on OSX. (They are always blocking Windows and were never blocking on Linux.) npmlog needs them to be blocking so that it can allow output to stdout and stderr to be interlaced.

This blocking stdio approach is not recommended by the Node team (in the comments of the node issue I linked above) _"If possible don't do .handle.setBlocking, since this will affect the whole process"_ however it _is_ listed as the "temporary workaround" at the top if that issue as well.

I guess that gives us a way to fix this if the above "write with callback" doesn't work.

[kuzyn]

Thanks for the info/research! The callback is indeed more elegant anyway. I'll check if I can reproduce with 8.5.0 on OSX

w/r/t the stdout being non-blocking on osx/linux, this make sense as I can reproduce (from my linked test-yarn repo) on arch (4.13.4-1) with node 9.2.0, yarn 1.3.2 and npm 5.5.1. Weird that you can't tho

[kuzyn]

Bizarre: the callback doesn't seem to work on the arch env mentioned above

[kuzyn]

Yep, same problem on OSX w/ node 8.5.0 and the callback

[rally25rs]

Weird. I tried it in zsh on my machine too and it still works fine. 😕

Well since you can reproduce it @kuzyn do you want to make a PR to fix it? I would try adding the recommended fix from the node issue linked above to the entry file of Yarn, which is src/cli/index.js start() function.

This code should work and pass Flow and linting:

async function start(): Promise<void> {
  const rc = getRcConfigForCwd(process.cwd());
  const yarnPath = rc['yarn-path'];

  // Set the stdio streams to be syncronous. This ensures all console output will be written before process exit.
  // This is the recommended fix taken from https://github.com/nodejs/node/issues/6456
  [process.stdout, process.stderr].forEach(s => {
    // $FlowFixMe: flow doesn't know about _handle, but it exists.
    s && s.isTTY && s._handle && s._handle.setBlocking && s._handle.setBlocking(true);
  });

  ...existing code...

Or put that code in a separate function that start() calls.

I appreciate the help!

[kuzyn]

@rally25rs Yeah, looks straightforward enough; I'll have a shot at it :+1:

[kuzyn]

The fix does not seem to work with node 8.5.0 and 8.8.1 😕

And after reading through this joyent repo and issue https://github.com/nodejs/node/issues/6297 and https://github.com/nodejs/node/issues/6379 I am not even sure if this temporary fix should be applied anymore. What do you think @rally25rs ?

[rally25rs]

Lovely 😢

Interestingly, that exeunt code basically does the same thing

function setBlocking() {
    [process.stdout, process.stderr].forEach(function setStreamBlocking(s) {
        if (s && s._handle && s._handle.setBlocking) {
            s._handle.setBlocking(true);
        }
    });
}

function exeunt(code) {
    var exitCode = code || 0;

    // Set stdout and stderr to be blocking *before* we exit...
    setBlocking();
    ...

but I read somewhere that you have to call setBlocking before anything ever writes to stdio or else it has no effect (i.e. you can't wait until right before exiting to call it). But with how much seemingly contradicting info is out there on this issue, who knows what's really "correct" any more.

---

Going back and re-reading this issue from the top, I'm starting to wonder if this is because of yarn start kicking off another process, and that process is what needs the fix... When Yarn runs a script, we basically just pass it to NodeJS's child_process.spawn() which fires up a new shell.

I had been thinking it was Yarn's logging itself that wasn't writing out, but it might just be the stdio from that child process never being flushed... Let me see if I can rig up a way to reproduce that...

[rally25rs]

OK, now I'm even more confused... I _can_ reproduce the issue now 🎉

But looking at the Yarn code, it looks like we set child_process.spawn() to inherit stdio, which I think means that it should be writing directly to the Yarn process' stdio. If back in Yarn after your process ends, I simply console.log('\n') inside Yarn, then I do see the flushed output... which is weird because your output is printed to stderr and console.log should write to stdout, but maybe it just flushes all stdio streams? Who knows...

What's weird though is that when Yarn prints the error itself to stdio "error Command failed with exit code 1." that output is there and should be on the same stream as the rest of the (missing) output. So how did it print some output, then skip some, then output some more, when they are all (i think)
on the same stdio stream??? 😕

I started digging through the NPM code to see what they do differently, and I think they set the .spawn() stdio to [0,1,2] which should be the same as inherit but I tried switching Yarn to the same, and still don't see the output. This is all very confusing...

[rally25rs]

Oh hey! I figured it out! 🎉

After like an hour of tracing back through the code, I found this in console-reporter.js

  error(msg: string) {
    clearLine(this.stderr); // <-- COMMENTING THIS OUT FIXES IT!
    this.stderr.write(`${this.format.red('error')} ${msg}\n`);
  }

It turns out on reporter writes, we clear the current output line! This is why adding a \n was fixing things, we would then clear the empty line instead of the line that the output was on.

It looks like _every_ call to reporter (.info, .log, .warn, .error, .success, etc...) all call clearLine().
I'm wondering why we do that... @kittens it looks like you wrote this about a year ago, so I'm sure it's still fresh in your mind 😆 Do you remember if there was a reason for the clearLine() stuff?

export function clearLine(stdout: Stdout) {
  if (!supportsColor) {
    if (stdout instanceof tty.WriteStream) {
      if (stdout.columns > 0) {
        stdout.write(`\r${' '.repeat(stdout.columns - 1)}`);
      }
      stdout.write(`\r`);
    }
    return;
  }

  readline.clearLine(stdout, CLEAR_WHOLE_LINE);
  readline.cursorTo(stdout, 0);
}

It looks like it deletes any stdio output that was written before the call to reporter that didn't end with a newline, causing output to be lost. My guess is that this was to ensure reporter lines were always on a newline. Maybe there is a way we can instead see if the last character on the stream is a \n and if not, add one? Alternatively, maybe instead of letting lifecycle and run scripts "inherit" Yarn's stdio streams, they should have their own and be written using reporter. (although when I tried changing the stdio type to "pipe" I still got no output from the child process, so this might have issues of its own)

[milesj]

I had a similar issue on a project of mine. The last line in any log was always removed. Adding a termincal cursor (\x1B[?25h) seemed to solve the problem, like so: https://github.com/milesj/boost/commit/358091f78840e4d0695d222ed775d710ba55c255#diff-b4492ec3d7fb1648d41dd3153e630708R95

[LandonSchropp]

@rally25rs @bestander: Not to be pushy, but is a fix for this on the roadmap? I just rediscovered this issue for the second time (via #5030). Thanks!

[rally25rs]

@LandonSchropp sorry for the slow reply. was out at a conference for a week, then had offsite meetings at work the week right after 😑 ... There is a major code update on the way (next major version) that might fix this (I haven't see the new code to know) but otherwise no, I sorta forgot about it since I was hoping for a reply from Kittens.
We could potentially just stop calling clearLine() if someone wants to do some regression testing to see if the output is still correct and submit a PR.

Or maybe @arcanis knows something about the original intent of clearLine or can see if this is fixed in the next major yarn update?