New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Missing or truncated error message #6867

Closed
ChALkeR opened this Issue May 18, 2016 · 12 comments

Comments

Projects
None yet
6 participants
@ChALkeR
Member

ChALkeR commented May 18, 2016

This looks close to #6456, and I thought it was just another case of that issue, but @indutny mentioned that the errors are printed from c++, so #6456 alone shouldn't have caused this, this is why I'm opening a separate issue.

A harder to reproduce example where the error is missing (it reproduces with about 10% chance for me):

for (var i = 0; i < 10000; i++) {
  console.log('HelloHelloHelloHelloHelloHelelloHelloHelloHelloHelloHelloHello ' + i);
}
a();

A simplier to reproduce example (the error gets truncated here most of the times, and sometimes is missing as in the previous example):

for (var i = 0; i < 10000; i++) {
  console.log('HelloHelloHelloHelloHelloHelelloHelloHelloHelloHelloHelloHello ' + i);
}
throw new Error(Array(100000 + 1).join('x') + '!');
@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 18, 2016

So you're experiencing a dropped data to console with normal exiting JS? i.e., without calling process.exit()? If so, that's a different issue to #6456.

On which platform are you experiencing this issue?

kzc commented May 18, 2016

So you're experiencing a dropped data to console with normal exiting JS? i.e., without calling process.exit()? If so, that's a different issue to #6456.

On which platform are you experiencing this issue?

@indutny

This comment has been minimized.

Show comment
Hide comment
@indutny

indutny May 18, 2016

Member

That happens because of libc buffer size limit. In fact vfprintf returns -1.

Member

indutny commented May 18, 2016

That happens because of libc buffer size limit. In fact vfprintf returns -1.

@Fishrock123 Fishrock123 added the process label May 18, 2016

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 18, 2016

src/node.cc:

    vfprintf(stderr, format, ap);

That's technically not correct without flushing libuv and node write queues to process.stderr first - and having stderr fd block.

kzc commented May 18, 2016

src/node.cc:

    vfprintf(stderr, format, ap);

That's technically not correct without flushing libuv and node write queues to process.stderr first - and having stderr fd block.

@indutny

This comment has been minimized.

Show comment
Hide comment
@indutny

indutny May 18, 2016

Member

@kzc this is a separate issue, IMO

Member

indutny commented May 18, 2016

@kzc this is a separate issue, IMO

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 18, 2016

It's a different take on the same issue actually.

$ node -v
v6.0.0

$ node -e 'for(var i=0;i<9999;++i){process.stderr.write(i + ": The quick brown fox jumps.\n")}throw new Error("Fin.");'
0: The quick brown fox jumps.
1: The quick brown fox jumps.
2: The quick brown fox jumps.
3: The quick brown fox jumps.
...
1595: The quick brown fox jumps.
1596: The quick brown fox jumps.
1597: The quick brown fox jumps.
1598[eval]:1
for(var i=0;i<9999;++i){process.stderr.write(i + ": The quick brown fox jumps.\n")}throw new Error("Fin.");
                                                                                   ^
Error: Fin.
    at [eval]:1:90
    at Object.exports.runInThisContext (vm.js:54:17)
    at Object.<anonymous> ([eval]-wrapper:6:22)
    at Module._compile (module.js:541:32)
    at node.js:328:29
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)

vfprintf(stderr) and libuv/node writes shouldn't be mixed.

Edit: the test run above was with node 6.0.0 on Mac. Issue was reproduced with node 5.10.1 on Linux - it outputs between 2400 and 2900 rows before showing the exception on my machine.

kzc commented May 18, 2016

It's a different take on the same issue actually.

$ node -v
v6.0.0

$ node -e 'for(var i=0;i<9999;++i){process.stderr.write(i + ": The quick brown fox jumps.\n")}throw new Error("Fin.");'
0: The quick brown fox jumps.
1: The quick brown fox jumps.
2: The quick brown fox jumps.
3: The quick brown fox jumps.
...
1595: The quick brown fox jumps.
1596: The quick brown fox jumps.
1597: The quick brown fox jumps.
1598[eval]:1
for(var i=0;i<9999;++i){process.stderr.write(i + ": The quick brown fox jumps.\n")}throw new Error("Fin.");
                                                                                   ^
Error: Fin.
    at [eval]:1:90
    at Object.exports.runInThisContext (vm.js:54:17)
    at Object.<anonymous> ([eval]-wrapper:6:22)
    at Module._compile (module.js:541:32)
    at node.js:328:29
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)

vfprintf(stderr) and libuv/node writes shouldn't be mixed.

Edit: the test run above was with node 6.0.0 on Mac. Issue was reproduced with node 5.10.1 on Linux - it outputs between 2400 and 2900 rows before showing the exception on my machine.

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 18, 2016

Using a locally patched version of node with a flushSync method on stream it produces the expected result - outputting all rows prior to the exception.

for (var i = 0; i <= 9999; ++i) {
    process.stdout.write(i + ": stdout - The quick brown fox jumps.\n");
    process.stderr.write(i + ": stderr - The quick brown fox jumps.\n");
}
process.stdout.flushSync && process.stdout.flushSync();
process.stderr.flushSync && process.stderr.flushSync();
throw new Error("Fin.");

Edit: code sample was edited to work with the patched version of node as well as unmodified node releases. Note: this is a different patch than seen in PR #6773 which does not have flushSync method on stream (Writable actually). This patch is for demonstrative purposes only.

kzc commented May 18, 2016

Using a locally patched version of node with a flushSync method on stream it produces the expected result - outputting all rows prior to the exception.

for (var i = 0; i <= 9999; ++i) {
    process.stdout.write(i + ": stdout - The quick brown fox jumps.\n");
    process.stderr.write(i + ": stderr - The quick brown fox jumps.\n");
}
process.stdout.flushSync && process.stdout.flushSync();
process.stderr.flushSync && process.stderr.flushSync();
throw new Error("Fin.");

Edit: code sample was edited to work with the patched version of node as well as unmodified node releases. Note: this is a different patch than seen in PR #6773 which does not have flushSync method on stream (Writable actually). This patch is for demonstrative purposes only.

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 19, 2016

As noted above this issue is present in node 5.x on Linux (and presumably on node 4.x) so it's not a recent regression.

Not sure what's the best way to fix this mixing of different stdio mechanisms. PR #6773 will not fix it alone. It's only similar to that issue in that the event loop has ceased and stdio is unflushed.

In light of this exception/stdio issue, the documentation to process.exit is not correct:

If it is necessary to terminate the Node.js process due to an error condition, throwing an uncaught error and allowing the process to terminate accordingly is safer than calling process.exit().
https://github.com/nodejs/node/blob/master/doc/api/process.md#processexitcode

Instead of calling vfprintf(stderr,...) could v8 be re-entered at this point so that process.stderr.write() be called with the exception error string and process.exit() called to initiate the stdio flush as in #6773?

/cc @jasnell

kzc commented May 19, 2016

As noted above this issue is present in node 5.x on Linux (and presumably on node 4.x) so it's not a recent regression.

Not sure what's the best way to fix this mixing of different stdio mechanisms. PR #6773 will not fix it alone. It's only similar to that issue in that the event loop has ceased and stdio is unflushed.

In light of this exception/stdio issue, the documentation to process.exit is not correct:

If it is necessary to terminate the Node.js process due to an error condition, throwing an uncaught error and allowing the process to terminate accordingly is safer than calling process.exit().
https://github.com/nodejs/node/blob/master/doc/api/process.md#processexitcode

Instead of calling vfprintf(stderr,...) could v8 be re-entered at this point so that process.stderr.write() be called with the exception error string and process.exit() called to initiate the stdio flush as in #6773?

/cc @jasnell

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc May 19, 2016

Another way: invoke uv_flush_sync() on stdout and stderr uv streams, re-enter v8 just to obtain the outstanding buffered write data for stdout and stderr node streams, return to C++ and flush this data, and then call vfprintf(stderr,...).

kzc commented May 19, 2016

Another way: invoke uv_flush_sync() on stdout and stderr uv streams, re-enter v8 just to obtain the outstanding buffered write data for stdout and stderr node streams, return to C++ and flush this data, and then call vfprintf(stderr,...).

@kzc kzc referenced this issue Jun 1, 2016

Closed

doc: expand documentation for process.exit() #6410

2 of 2 tasks complete
@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc Jun 4, 2016

Reproduced bug with node 4.x on Linux:

$ node -v
v4.4.5

$ node -p process.platform
linux

$ node -e 'for(var i=0;i<9999;++i){process.stderr.write(i+": The quick brown fox jumps.\n")}throw new Error("Fin.");'
0: The quick brown fox jumps.
1: The quick brown fox jumps.
2: The quick brown fox jumps.
...
2399: The quick brown fox jumps.
2400: The quick brown fox jumps.
2401: The quick brown fox jumps.$ 

Number of lines outputted is variable on repeated runs - 2281 to 2407. Sometimes the uncaught exception is printed, and sometimes it is not (as seen above).

kzc commented Jun 4, 2016

Reproduced bug with node 4.x on Linux:

$ node -v
v4.4.5

$ node -p process.platform
linux

$ node -e 'for(var i=0;i<9999;++i){process.stderr.write(i+": The quick brown fox jumps.\n")}throw new Error("Fin.");'
0: The quick brown fox jumps.
1: The quick brown fox jumps.
2: The quick brown fox jumps.
...
2399: The quick brown fox jumps.
2400: The quick brown fox jumps.
2401: The quick brown fox jumps.$ 

Number of lines outputted is variable on repeated runs - 2281 to 2407. Sometimes the uncaught exception is printed, and sometimes it is not (as seen above).

@kzc

This comment has been minimized.

Show comment
Hide comment
@kzc

kzc Jun 22, 2016

Could someone please add a confirmed-bug tag to this issue to raise the profile of this bug?

kzc commented Jun 22, 2016

Could someone please add a confirmed-bug tag to this issue to raise the profile of this bug?

@xhallix

This comment has been minimized.

Show comment
Hide comment
@xhallix

xhallix Oct 17, 2016

On v7.0.0-pre everything seems to work here, I'm just having this on my LTS version

xhallix commented Oct 17, 2016

On v7.0.0-pre everything seems to work here, I'm just having this on my LTS version

@ChALkeR

This comment has been minimized.

Show comment
Hide comment
@ChALkeR

ChALkeR Mar 3, 2017

Member

Works for me on v7.7.1 on 6.10.0.

Not sure which specific commit fixed that, but both 7.x and 6.x currently work fine.
Note: I could reproduce the issue on old Node.js versions on the same hardware and testcase.

For 6.x, 6.3.1 is the last version where the issue is reproducable, 6.4.0 is the first version that looks fixed.

Member

ChALkeR commented Mar 3, 2017

Works for me on v7.7.1 on 6.10.0.

Not sure which specific commit fixed that, but both 7.x and 6.x currently work fine.
Note: I could reproduce the issue on old Node.js versions on the same hardware and testcase.

For 6.x, 6.3.1 is the last version where the issue is reproducable, 6.4.0 is the first version that looks fixed.

@ChALkeR ChALkeR closed this Mar 3, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment