Doesn't Always Display the Whole Output

[vlad-shatskyi]

On Linux, running a command with node-pty sometimes truncates the end of the output. Steps to reproduce:

• docker run -it node bash

Then inside docker:

• npm install node-pty
• curl https://gist.githubusercontent.com/vlad-shatskyi/d3820878733294d8e12571eab207885b/raw/e644351d9a8bc81ea97e8797e696a7cc5a757f24/output > output
• node -e "require('node-pty').spawn('cat', ['output']).on('data', data => console.log(data))"

I obfuscated the output, but note that sometimes the lines with dashes aren't printed.

It seems that onread isn't called the last time. https://github.com/nodejs/node/blob/master/lib/net.js#L568 A possibly related issue: https://github.com/nodejs/node-v0.x-archive/issues/6595

This issue is also present in pty.js.

If you run the command with NODE_DEBUG=NET, it shows that the last chunk of data has a negative nread value:

NET 435: _read
NET 435: onread -4095
NET 435: EOF

[vlad-shatskyi]

Were you able to reproduce it, @Tyriar?

[Tyriar]

@vlad-shatskyi no, I don't have time to look into it at the moment. If it happens in pty.js it's a bug that carried over then. If there's an issue over there was would probably help diagnose https://github.com/chjj/pty.js

[vlad-shatskyi]

@Tyriar I'm not sure I understood the last sentence. Do you propose to open an issue in the pty.js repository? If so, I don't think it'd be very useful since the author doesn't seem to be active for at least half a year.

[jerch]

I think this is the same bug I stumbled over here https://github.com/Tyriar/node-pty/issues/72#issuecomment-291813706 The pty pipe gets closed and invalidated as soon as the pty slave process terminates discarding any leftover data in the pipe. Thats the default behavior of a pipe under POSIX. To fix it, the native module would have to hold a second slave file descriptor until the pipe got emptied by net.Socket.

[twifty]

Are there any updates on this? I noticed @jerch was working on the low level stuff, but nothing has been posted in quite some time.

[jerch]

Sadly the problem is caused by a false assumption in libuv's polling mechanism (node's underlying event library). The fix I came up with involves to many changes of the low level code base, therefore I stopped development. Feel free to grab it and develop it further (see https://github.com/jerch/node-newpty).

[twifty]

Well, I guess I'll continue using my 'patch' bash script. I just feel uneasy about including bash within a nodejs package.

[starpit]

btw, we are seeing this with cat bigfile.json on linux. no remote networks involved, just a local filesystem read. we get an EXIT event prior to all of the output appearing on DATA events. inserting a setTimeout in unixTerminal.ts's call to emit('exit') doesn't seem to help, which indicates that the issue resides in pty.cc or some lower level?

[jerch]

@starpit The problem is within libuv, that drives nodejs' event system and IO stuff. It cannot handle a POLLHUP and keep reading until all data is drained (Thats a special condition on pty pipes). You can try with this package https://github.com/jerch/node-newpty and check if the issue goes away.

[jerch]

@starpit Some addtional notes - since the process already exited a setTimeout does not help here. Reason - the exit of the process also closes the slave end of the pty - POLLHUP is signalled and the connection hold in libuv (as Socket object) gets destroyed. The data in the pty OS buffer is lost. Imho this only happens in Linux as all BSDs hold back the POLLHUP until all data got drained (found it out the hard way here).

Only ugly hack I see for now is to spawn a shell and place a sentinel and a sleep behind the call, e.g.:

bash -c "your_cmd && echo '##sentinel##' && sleep 1"

The sleep will hold the slave side open (hopefully long enough) to read all data. With the sentinel you can decide whether you have seen all data.

@Tyriar I think we have to address this again. The bug makes node-pty pretty unusable for any directly spawned command that generates more than one page of pty buffer output (for some reason the first page always gets through in time). Rough idea - maybe we can fetch the pending data in the exit thread and deliver it with on('exit').

[Tyriar]

I think vscode works around this by "queueing" process exit to make sure all data is flushed before disposing of everything:

https://github.com/microsoft/vscode/blob/3ccdd1e63d4819349903e17019264b954e56db44/src/vs/workbench/contrib/terminal/node/terminalProcess.ts#L135-L140

[jerch]

@Tyriar Imho that is not related to the problem I see with this snippet:

var ptyProcess = pty.spawn('python', ['-c', 'for i in range(50000):\n  print i;'], {
    name: 'xterm-color',
    cols: 10,
    rows: 5,
    cwd: process.env.HOME,
    env: process.env
});
ptyProcess.on('exit', (...args) => console.log(...args));
ptyProcess.on('data', data => console.log(data));

There is no explicit kill involved, it is just the slave side hanging up that triggers an early end of the socket object and leads to missing the last bytes. Possibly related is the weird workaround to get net.Socket working at all here: https://github.com/microsoft/node-pty/blob/04445ed76f90b4f56a190982ea2d4fcdd22a0ee7/src/unixTerminal.ts#L282-L290

[jerch]

Hmm the more I test this the more I have the feeling it is not working correctly at all. Taken the snippet from above and remove all exit/data handlers:

var ptyProcess = pty.spawn('python', ['-c', 'for i in range(50000):\n  print i;'], {
    name: 'xterm-color',
    cols: 10,
    rows: 5,
    cwd: process.env.HOME,
    env: process.env
});

Isnt this meant to block forever? But it doesnt, the node process exits as soon as python closes. Also the python process should be paused by backpressure from the pty buffer. But it finished? To me this pretty much looks like a serious bug. Imagine the script takes really long to attach the data handler. What happens to data that was produced before that? Extend the snippet to this:

var ptyProcess = pty.spawn('python', ['-c', 'for i in range(500000):\n  print i;'], {
    name: 'xterm-color',
    cols: 10,
    rows: 5,
    cwd: process.env.HOME,
    env: process.env
});

// something takes really long to setup a read handler
setTimeout(() => {
  ptyProcess.on('data', data => {
    console.log(data.slice(0, 20));
    process.exit();
  });
}, 100);

Et voila, now early bytes are missing too. We have a serious issue with blocking vs. non blocking. Try the same snippet above with child_process - it just works expected.

@Tyriar Any thoughts on this? Not sure how this went unnoticed for so long, I guess no one ever tested this explicitly. Only tested on Linux for now, not sure if other systems are affected as well.

[shizhx]

we encounter same problem, when cat a big file(large than 4096 maybe), node-pty cannot get all ouput

[Tyriar]

duplicate of https://github.com/microsoft/node-pty/issues/72