stdio buffered writes (chunked) issues & process.exit() truncation #6456

eljefedelrodeodeljefe · 2016-04-28T22:47:27Z

If this is currently breaking your program, please use this temporary fix:

[process.stdout, process.stderr].forEach((s) => {
  s && s.isTTY && s._handle && s._handle.setBlocking &&
    s._handle.setBlocking(true)
})

Version: v6, (likely all and backportable)
Platform: all
Subsystem: process

As noted in #6297 async stdio will not be flushed upon immediate process.exit(). This may lay open general deficiencies around C exit() from C++ functions not being properly unwound and is probably not just introduced by latest libuv updates. It should be considered to add flushing, providing graceful exit and/or improving unwinding C++ stacks.

cc @jasnell, @kzc, @Qix-, @bnoordhuis

Issues

Discussion has been already taking place at several places, e.g. #6297, #6456, #6379

Summaries of Proposals

proposals are not exclusive and could lead to semantically unrelated contributions.

aid with process.stdout.flush()
process.setBlocking(true)
node --blocking-stdio
longjmp() towards main at exit in C++
move parts of process.exit() / process.reallyExit() to new method os.exit()
golang panic()- or c++ throw-like stack unwinding

Discussions by Author (with content)

@ChALkeR
I tried to discuss this some time ago at IRC, but postponed it for quite a long time. Also I started the discussion of this in #1741, but I would like to extract the more specific discussion to a separate issue.

I could miss some details, but will try to give a quick overview here.

Several issues here:

Many calls to console.log (e.g. calling it in a loop) could chew up all the memory and die — Why does node/io.js hang when printing to the console inside a loop? #1741, Silly program or memory leak? #2970, Strange memory leaks #3171.
console.log has different behavior while printing to a terminal and being redirected to a file. — Why does node/io.js hang when printing to the console inside a loop? #1741 (comment).
Output is sometimes truncated — A libuv upgrade in Node v6 breaks the popular david package #6297, there were other ones as far as I remember.
The behaviour seems to differ across platforms.

As I understand it — the output has an implicit write buffer (as it's non-blocking) of unlimited size.

One approach to fixing this would be to:

Introduce an explicit cyclic write buffer.
Make writes to that cyclic buffer blocking.
Make writes from the buffer to the actual output non blocking.
When the cyclic buffer reaches it's maximum size (e.g. 10 MiB) — block further writes to the buffer until a corresponding part of it is freed.
On (normal) exit, make sure the buffer is flushed.

For almost all cases, except for the ones that are currently broken, this would behave as a non-blocking buffer (because writes to the buffer are considerably faster than writes from the buffer to file/terminal).

For cases when the data is being piped to the output too quickly and when the output file/terminal does not manage to output it at the same rate — the write would turn into a blocking operation. It would also be blocking at the exit until all the data is written.

Another approach would be to monitor (and limit) the size of data that is contained in the implicit buffer coming from the async queue, and make the operations block when that limit is reached.

The text was updated successfully, but these errors were encountered:

Qix- · 2016-04-28T22:50:25Z

Perhaps a list of issues this would address and/or close would be helpful to include since this seems to be a sprawling issue with a lot of fragmented discussion.

eljefedelrodeodeljefe · 2016-04-28T22:52:36Z

Yes, just a little late in Europe :( keep 'em coming and I add them above.

vsemozhetbyt · 2016-04-28T22:55:05Z

Also see #6410

vsemozhetbyt · 2016-04-28T23:11:07Z

Considering all the clarification in the #6410, is there also a theoretical possibility that not only several I/O calls to stdout could not make it, but even one simple console.log() before process.exit() could be truncated or discarded?

Qix- · 2016-04-28T23:13:23Z

@vsemozhetbyt that is especially correct if I'm understanding your question correctly.

addaleax · 2016-04-28T23:14:34Z

@vsemozhetbyt If it’s big enough, definitely. See e.g. test/known_issues/test-stdout-buffer-flush-on-exit.js.

eljefedelrodeodeljefe · 2016-04-28T23:18:20Z

To reproduce you can do

require('crypto').randomBytes(100000000, function(err, buffer) {
  var token = buffer.toString('hex');
  console.log(token);
  process.exit(0)
});

Edit: @addaleax's hint: test does a similar thing. Sorry @addaleax

kzc · 2016-04-28T23:24:01Z

@vsemozhetbyt This output is truncated with node 6.0.0 on Mac after approx 40 lines:

node -e 'console.log("The quick brown fox jumps.\n".repeat(40000)); process.exit(7);'

node 5.x and earlier output all 40000 lines on Mac.

vsemozhetbyt · 2016-04-28T23:44:18Z

So now if user does not want to reflow the code all one has is to write something like

const err = {name: 'Error', message: 'something wrong'};
throw err;

instead of

console.log('Error: something wrong');
process.exit(1);

and to deal with all the uncontrolled clutter of debug output?

kzc · 2016-04-28T23:49:28Z

throw err;
and to deal with all the uncontrolled clutter of debug output?

For dev code, sure, but uncaught exceptions in production code is not very elegant or professional.

kzc · 2016-04-29T00:07:08Z

Related: #6379

Also discusses process.stdio.setBlocking(Boolean)

eljefedelrodeodeljefe · 2016-04-29T07:47:55Z

added @chalkers thread and updated this issue with some summaries and stuff.

Qix- · 2016-04-29T08:09:35Z

@kzc

node 5.x and earlier output all 40000 lines on Mac.

Not sure what you're talking about.

#!/usr/bin/env bash
. ~/.nvm/nvm.sh

uname -a
echo

function do_buffer_test {
    node <<< 'console.log((new Array(40000)).join("Hello! this is a test!\n"));' | wc -l
    node <<< 'console.log((new Array(40000)).join("Hello! this is a test!\n")); process.exit(1)' | wc -l
    node <<< 'console.log((new Array(40000)).join("Hello! this is a test!\n")); process.reallyExit(1)' | wc -l
    node <<< 'console.log((new Array(40000)).join("Hello! this is a test!\n")); process.abort()' | wc -l
    node <<< 'for (var i = 0; i < 40000; i++) console.log("Hello! this is a test!");' | wc -l
    node <<< 'for (var i = 0; i < 40000; i++) console.log("Hello! this is a test!"); process.exit(1)' | wc -l
    node <<< 'for (var i = 0; i < 40000; i++) console.log("Hello! this is a test!"); process.reallyExit(1)' | wc -l
    node <<< 'for (var i = 0; i < 40000; i++) console.log("Hello! this is a test!"); process.abort()' | wc -l
}

nvm install 0.10
do_buffer_test

nvm install 0.12
do_buffer_test

nvm install 1
do_buffer_test

nvm install 2
do_buffer_test

nvm install 3
do_buffer_test

nvm install 4
do_buffer_test

nvm install 5
do_buffer_test

nvm install 6
do_buffer_test

$ ./test-buffers.sh
Darwin JunonBox.local 15.4.0 Darwin Kernel Version 15.4.0: Fri Feb 26 22:08:05 PST 2016; root:xnu-3248.40.184~3/RELEASE_X86_64 x86_64

v0.10.44 is already installed.
Now using node v0.10.44 (npm v2.15.0)
   40000
   40000
   40000
   40000
   40000
   40000
   40000
   40000
v0.12.13 is already installed.
Now using node v0.12.13 (npm v2.15.0)
   40000
   40000
   40000
   40000
   40000
   40000
   40000
   40000
iojs-v1.8.4 is already installed.
Now using io.js v1.8.4 (npm v2.9.0)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000
iojs-v2.5.0 is already installed.
Now using io.js v2.5.0 (npm v2.13.2)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000
iojs-v3.3.1 is already installed.
Now using io.js v3.3.1 (npm v2.14.3)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000
v4.4.3 is already installed.
Now using node v4.4.3 (npm v2.15.1)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000
v5.11.0 is already installed.
Now using node v5.11.0 (npm v3.8.6)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000
v6.0.0 is already installed.
Now using node v6.0.0 (npm v3.8.6)
   40000
    2849
    2849
    2849
   40000
   40000
   40000
   40000

$ ./test-buffers.sh
Linux -snip- 3.18.27 #1 SMP Wed Feb 17 01:14:23 UTC 2016 x86_64 GNU/Linux

######################################################################## 100.0%
Now using node v0.10.44 (npm v2.15.0)
Creating default alias: default -> 0.10 (-> v0.10.44)
40000
40000
40000
40000
40000
40000
40000
40000
######################################################################## 100.0%
Now using node v0.12.13 (npm v2.15.0)
40000
40000
40000
40000
40000
40000
40000
40000
Downloading https://iojs.org/dist/v1.8.4/iojs-v1.8.4-linux-x64.tar.gz...
######################################################################## 100.0%
Now using io.js v1.8.4 (npm v2.9.0)
40000
2849
2849
2849
40000
40000
40000
40000
Downloading https://iojs.org/dist/v2.5.0/iojs-v2.5.0-linux-x64.tar.xz...
######################################################################## 100.0%
Now using io.js v2.5.0 (npm v2.13.2)
40000
2849
2849
2849
40000
40000
40000
40000
Downloading https://iojs.org/dist/v3.3.1/iojs-v3.3.1-linux-x64.tar.xz...
######################################################################## 100.0%
Now using io.js v3.3.1 (npm v2.14.3)
40000
2849
2849
2849
40000
40000
40000
40000
Downloading https://nodejs.org/dist/v4.4.3/node-v4.4.3-linux-x64.tar.xz...
######################################################################## 100.0%
Now using node v4.4.3 (npm v2.15.1)
40000
2849
2849
2849
40000
40000
40000
40000
Downloading https://nodejs.org/dist/v5.11.0/node-v5.11.0-linux-x64.tar.xz...
######################################################################## 100.0%
Now using node v5.11.0 (npm v3.8.6)
40000
2849
2849
2849
40000
40000
40000
40000
Downloading https://nodejs.org/dist/v6.0.0/node-v6.0.0-linux-x64.tar.xz...
######################################################################## 100.0%
Now using node v6.0.0 (npm v3.8.6)
40000
2849
2849
2849
40000
40000
40000
40000

Looks to me whenever io.js forked is when this started happening. Perhaps @indutny can shed some light on the subject.

eljefedelrodeodeljefe · 2016-04-29T10:15:25Z

Adding two other possibilities.

move parts of process.exit() / process.reallyExit() to new method os.exit(), which may fit what actually is happening better
golang panic()- or c++ throw-like stack unwinding.

kzc · 2016-04-29T11:56:25Z

@Qix- @eljefedelrodeodeljefe Please understand that when you pipe the results you are changing the test. It follows a different code path in node and libuv. You have to observe it on the terminal. So in that regard, the test is more difficult to automate.

I am observing this behavior of Mac OS X 10.9.5. The behavior is different on Mac and Linux. Mac stdout appears to have had blocking writes to the tty historically. See #6297 (comment)

kzc · 2016-04-29T12:03:57Z

+1 for new function os.exit(Boolean) that drains stdout/stderr upon exit and leave process.exit() as is.

Actually may have to leave process.exit as is because of the prevalence of workarounds to the stdout flushing problem such as node-exit which might break if the behavior of process.exit changes.

saghul · 2016-04-29T14:06:02Z

If memory serves right, and by looking at the results posted by @Qix- I think this is where things started to change: libuv/libuv@b197515 Because we started to open writable TTYs in non-blocking mode. Follow the commit trail for reasonin, reverting is not an option.

kzc · 2016-04-29T14:15:25Z

reverting is not an option.

Yes, and that particular commit also introduced the tty redirection bug in src/unix/tty.c that was fixed in libuv 1.9.0.

saghul · 2016-04-29T14:26:35Z

@kzc your point being?

kzc · 2016-04-29T14:31:40Z

Just adding weight to reverting is not an option.

kzc · 2016-04-29T14:36:28Z

@saghul I will add that prior to the tty redirection fix, Mac stdout appeared to be blocking based on my observations with process.exit tests never truncating tty output on Mac. As of that tty redirect fix it is now non-blocking to make it on par with Linux behavior.

bnoordhuis · 2016-04-29T16:00:34Z

Can I suggest closing out all other issues with a "discussion continues in #6456" comment?

jasnell · 2016-04-29T16:03:47Z

+1 ... we don't need multiple issues covering the same thing.

When set, an internal timer will be set that will exit the process at the given timeout. In the meantime, the registered listeners for process.on('exitingSoon') will be invoked and passed a callback to be called when the handler is ready for the process to exit. The process will exit either when the internal timer fires or all the callbacks are called, whichever comes first. This is an attempt to deal more intelligently with resource cleanup and async op completion on exit (see nodejs#6456).

jasnell · 2016-04-29T17:57:03Z

See: #6477

dead-claudia · 2018-03-04T06:55:40Z

@Trott Based on some of these recent issues/commits linking to here, I suspect it still is an issue. (I've long had to move on to fix async writes, since it was causing tests to fail.)

silverwind · 2018-07-16T16:23:02Z

Is this still an issue?

Yes, I can confirm 10.6.0 still shows this issue. Simple repro:

$ node -p 'process.stdout.write("x".repeat(5e6)); process.exit()' | wc -c
65536

1. Compute deathSignal correctly 2. Redirect output to tmp file. Very long piped strings sometimes get mishandled.

…ng process.stdout to blocking. See nodejs/node#6456 for a discussion of the issue and a version of the fix used here. Signed-off-by: mrickard <[email protected]>

Trott · 2021-03-16T01:58:07Z

It seems to me that the most viable path forward is the one outlined by @gireeshpunathil in this comment in an earlier issue. I propose closing this issue in favor of that one (so we at least can keep conversation all in one place) and add a help wanted label to that issue, as the implementation will not be trivial.

`process.exit()` may not flush stdio, which in turn can lead to the loss of output. See nodejs/node#6456. This issue manifests with `max-failures should work` test being flaky, where we examine large output and it is sometimes truncated.

jasnell · 2021-04-30T21:08:12Z

Closing in favor of the conversation happen in #6379

`process.exit()` may not flush stdio, which in turn can lead to the loss of output. See nodejs/node#6456. This issue manifests with `max-failures should work` test being flaky, where we examine large output and it is sometimes truncated.

eljefedelrodeodeljefe mentioned this issue Apr 28, 2016

A libuv upgrade in Node v6 breaks the popular david package #6297

Closed

addaleax added the process Issues and PRs related to the process subsystem. label Apr 28, 2016

eljefedelrodeodeljefe mentioned this issue Apr 29, 2016

stdout/stderr buffering considerations #6379

Closed

jasnell mentioned this issue Apr 29, 2016

process: add process.exitSoon() #6477

Closed

4 tasks

mhdawson mentioned this issue Apr 29, 2016

Intermittent failures in test-process-exec-argv #6480

Closed

Trott added the help wanted Issues that need assistance from volunteers or PRs that need help to proceed. label Mar 4, 2018

gireeshpunathil mentioned this issue Apr 13, 2018

Flexible stdios for IPC #20000

Open

This was referenced Apr 16, 2018

🐛 Flush stdout before exiting process after running tests ampproject/amphtml#14653

Merged

🐛 Don't call process.exit() in Karma during normal pass / fail flow ampproject/amphtml#14669

Merged

xzyfer added a commit to sass/node-sass that referenced this issue Jul 19, 2018

Try patch for nodejs/node#6456

13ec2d3

ronag mentioned this issue Jul 24, 2018

flush & flushSync stdout on Node core streams pinojs/pino#458

Closed

mohd-akram mentioned this issue Jul 26, 2018

Fix exception not printed when debugging evanw/node-source-map-support#219

Merged

swgillespie mentioned this issue Nov 19, 2018

Flush stdout and stderr on abnormal lang shutdown pulumi/pulumi#2226

Merged

gireeshpunathil mentioned this issue Nov 29, 2018

fs.createWriteStream is creating file but not writing to it nodejs/help#1641

Closed

gireeshpunathil mentioned this issue Jan 22, 2019

console: use synchronous write when the process is piped #25638

Closed

3 tasks

jamesdonoh referenced this issue in davisjam/vuln-regex-detector Feb 13, 2019

validate-vuln: bugfixing

f15e61e

1. Compute deathSignal correctly 2. Redirect output to tmp file. Very long piped strings sometimes get mishandled.

silverwind mentioned this issue Jun 20, 2019

util: change inspect's default depth to 4 #28269

Closed

3 tasks

RichardBronosky mentioned this issue Jul 12, 2019

Option to output as json palashkulsh/jira-cmd#56

Closed

AndrewFinlay mentioned this issue Jan 19, 2020

Flaky output from --help yargs/yargs#1519

Open

harrysarson mentioned this issue May 22, 2020

JUnit output incomplete, truncated at ^2kB boundary elm-explorations/test#138

Open

pbelbin mentioned this issue Jun 2, 2020

error() should flush stdout before emitting message sparksuite/waterfall-cli#258

Closed

Arkham mentioned this issue Oct 15, 2020

Make report async jfmengels/node-elm-review#23

Merged

alexlamsl mentioned this issue Dec 27, 2020

ufuzz failure mishoo/UglifyJS#4466

Closed

therealgilles mentioned this issue Jan 23, 2021

Miscellaneous issues with razzle jaredpalmer/razzle#1510

Closed

dgozman mentioned this issue Apr 23, 2021

fix(stdio): drain stdio before process.exit microsoft/folio#244

Merged

jasnell closed this as completed Apr 30, 2021

jamesdbrock mentioned this issue May 24, 2022

Stream Promises API? purescript-node/purescript-node-streams#44

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

stdio buffered writes (chunked) issues & process.exit() truncation #6456

stdio buffered writes (chunked) issues & process.exit() truncation #6456

eljefedelrodeodeljefe commented Apr 28, 2016 •

edited by Trott

Loading

Qix- commented Apr 28, 2016 •

edited

Loading

eljefedelrodeodeljefe commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016 •

edited

Loading

Qix- commented Apr 28, 2016

addaleax commented Apr 28, 2016

eljefedelrodeodeljefe commented Apr 28, 2016 •

edited

Loading

kzc commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016 •

edited

Loading

kzc commented Apr 28, 2016

kzc commented Apr 29, 2016

eljefedelrodeodeljefe commented Apr 29, 2016

Qix- commented Apr 29, 2016 •

edited

Loading

eljefedelrodeodeljefe commented Apr 29, 2016

kzc commented Apr 29, 2016 •

edited

Loading

kzc commented Apr 29, 2016 •

edited

Loading

saghul commented Apr 29, 2016

kzc commented Apr 29, 2016

saghul commented Apr 29, 2016

kzc commented Apr 29, 2016

kzc commented Apr 29, 2016 •

edited

Loading

bnoordhuis commented Apr 29, 2016

jasnell commented Apr 29, 2016

jasnell commented Apr 29, 2016

dead-claudia commented Mar 4, 2018

silverwind commented Jul 16, 2018

Trott commented Mar 16, 2021

jasnell commented Apr 30, 2021

stdio buffered writes (chunked) issues & process.exit() truncation #6456

stdio buffered writes (chunked) issues & process.exit() truncation #6456

Comments

eljefedelrodeodeljefe commented Apr 28, 2016 • edited by Trott Loading

Issues

Summaries of Proposals

Discussions by Author (with content)

Qix- commented Apr 28, 2016 • edited Loading

eljefedelrodeodeljefe commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016 • edited Loading

Qix- commented Apr 28, 2016

addaleax commented Apr 28, 2016

eljefedelrodeodeljefe commented Apr 28, 2016 • edited Loading

kzc commented Apr 28, 2016

vsemozhetbyt commented Apr 28, 2016 • edited Loading

kzc commented Apr 28, 2016

kzc commented Apr 29, 2016

eljefedelrodeodeljefe commented Apr 29, 2016

Qix- commented Apr 29, 2016 • edited Loading

eljefedelrodeodeljefe commented Apr 29, 2016

kzc commented Apr 29, 2016 • edited Loading

kzc commented Apr 29, 2016 • edited Loading

saghul commented Apr 29, 2016

kzc commented Apr 29, 2016

saghul commented Apr 29, 2016

kzc commented Apr 29, 2016

kzc commented Apr 29, 2016 • edited Loading

bnoordhuis commented Apr 29, 2016

jasnell commented Apr 29, 2016

jasnell commented Apr 29, 2016

dead-claudia commented Mar 4, 2018

silverwind commented Jul 16, 2018

Trott commented Mar 16, 2021

jasnell commented Apr 30, 2021

eljefedelrodeodeljefe commented Apr 28, 2016 •

edited by Trott

Loading

Qix- commented Apr 28, 2016 •

edited

Loading

vsemozhetbyt commented Apr 28, 2016 •

edited

Loading

eljefedelrodeodeljefe commented Apr 28, 2016 •

edited

Loading

vsemozhetbyt commented Apr 28, 2016 •

edited

Loading

Qix- commented Apr 29, 2016 •

edited

Loading

kzc commented Apr 29, 2016 •

edited

Loading

kzc commented Apr 29, 2016 •

edited

Loading

kzc commented Apr 29, 2016 •

edited

Loading