From c5b6a2dea8a27d6608f3f4782d0832566397b1f4 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 15:46:50 +0100 Subject: [PATCH 1/6] events: show throw stack trace for uncaught exception MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Show the stack trace for the `eventemitter.emit('error')` call in the case of an uncaught exception. Previously, there would be no clue in Node’s output about where the actual `throw` comes from. --- lib/events.js | 62 ++++++++++++++++++++- lib/internal/bootstrap_node.js | 5 ++ test/message/test-unhandled-error-stack.js | 20 +++++++ test/message/test-unhandled-error-stack.out | 23 ++++++++ 4 files changed, 109 insertions(+), 1 deletion(-) create mode 100644 test/message/test-unhandled-error-stack.js create mode 100644 test/message/test-unhandled-error-stack.out diff --git a/lib/events.js b/lib/events.js index 1c697943371ace..5c6508c6d8e855 100644 --- a/lib/events.js +++ b/lib/events.js @@ -98,6 +98,58 @@ EventEmitter.prototype.getMaxListeners = function getMaxListeners() { return $getMaxListeners(this); }; +// Returns the longest sequence of a that fully appears in b, of length >= 3. +// This is a lazy approach but should work well enough, given that stack +// frames are usually unequal if they don't appear in a group and that +// we only run this code in case of an unhandled exception. +function longestSeqContainedIn(a, b) { + for (var len = a.length; len >= 3; --len) { + for (var i = 0; i < a.length - len; ++i) { + // Attempt to find a[i:i+len] in b + for (var j = 0; j < b.length - len; ++j) { + let matches = true; + for (var k = 0; k < len; ++k) { + if (a[i + k] !== b[j + k]) { + matches = false; + break; + } + } + if (matches) + return [ len, i, j ]; + } + } + } + + return [ 0, 0, 0 ]; +} + +function longestCommonSubsequence(a, b) { + const [ l1, i1, j1 ] = longestSeqContainedIn(a, b); + const [ l2, i2, j2 ] = longestSeqContainedIn(b, a); + if (l1 > l2) + return [ l1, j1, i1 ]; + else + return [ l2, i2, j2 ]; +} + +function enhanceStackTrace(err, own) { + const sep = '\nEmitted \'error\' event at at:\n'; + + const errStack = err.stack.split('\n').slice(1); + const ownStack = own.stack.split('\n').slice(1); + + const [ len, off ] = longestCommonSubsequence(errStack, ownStack); + if (len > 0) { + ownStack.splice(off + 1, len - 1, + ' [... lines matching original stack trace ...]'); + // Do this last, because it is the only operation with side effects. + err.stack = err.stack + sep + ownStack.join('\n'); + } +} + +const kExpandStack = Symbol('kExpandStack'); +Object.defineProperty(EventEmitter, 'kExpandStack', { value: kExpandStack }); + EventEmitter.prototype.emit = function emit(type, ...args) { let doError = (type === 'error'); @@ -113,13 +165,21 @@ EventEmitter.prototype.emit = function emit(type, ...args) { if (args.length > 0) er = args[0]; if (er instanceof Error) { + try { + const capture = {}; + Error.captureStackTrace(capture, EventEmitter.prototype.emit); + er[kExpandStack] = enhanceStackTrace.bind(null, er, capture); + } catch (e) {} + + // Note: The comments on the `throw` lines are intentional, they show + // up in Node's output if this results in an unhandled exception. throw er; // Unhandled 'error' event } // At least give some kind of context to the user const errors = lazyErrors(); const err = new errors.Error('ERR_UNHANDLED_ERROR', er); err.context = er; - throw err; + throw err; // Unhandled 'error' event } const handler = events[type]; diff --git a/lib/internal/bootstrap_node.js b/lib/internal/bootstrap_node.js index f85e557d5efdf8..da3d5d6a5c2d7b 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -458,6 +458,11 @@ } catch (er) { // nothing to be done about it at this point. } + try { + const { kExpandStack } = NativeModule.require('events'); + if (typeof er[kExpandStack] === 'function') + er[kExpandStack](); + } catch (er) {} return false; } diff --git a/test/message/test-unhandled-error-stack.js b/test/message/test-unhandled-error-stack.js new file mode 100644 index 00000000000000..e6c168fc06eb33 --- /dev/null +++ b/test/message/test-unhandled-error-stack.js @@ -0,0 +1,20 @@ +'use strict'; +require('../common'); +const EventEmitter = require('events'); + +function foo() { + function bar() { + return new Error('foo:bar'); + } + + return bar(); +} + +const ee = new EventEmitter(); +const err = foo(); + +function quux() { + ee.emit('error', err); +} + +quux(); diff --git a/test/message/test-unhandled-error-stack.out b/test/message/test-unhandled-error-stack.out new file mode 100644 index 00000000000000..e4ea1b49721830 --- /dev/null +++ b/test/message/test-unhandled-error-stack.out @@ -0,0 +1,23 @@ +events.js:* + throw er; // Unhandled 'error' event + ^ + +Error: foo:bar + at bar (*test-unhandled-error-stack.js:*:*) + at foo (*test-unhandled-error-stack.js:*:*) + at Object. (*test-unhandled-error-stack.js:*:*) + at Module._compile (module.js:*:*) + at Object.Module._extensions..js (module.js:*:*) + at Module.load (module.js:*:*) + at tryModuleLoad (module.js:*:*) + at Function.Module._load (module.js:*:*) + at Function.Module.runMain (module.js:*:*) + at startup (bootstrap_node.js:*:*) +Emitted 'error' event at at: + at quux (*test-unhandled-error-stack.js:*:*) + at Object. (*test-unhandled-error-stack.js:*:*) + at Module._compile (module.js:*:*) + [... lines matching original stack trace ...] + at startup (bootstrap_node.js:*:*) + at bootstrap_node.js:*:* + From 3017598724895fafd2b1eda64ff7bc14a3687039 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 16:01:48 +0100 Subject: [PATCH 2/6] [squash] better comment text --- lib/events.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/events.js b/lib/events.js index 5c6508c6d8e855..9f562724be18ea 100644 --- a/lib/events.js +++ b/lib/events.js @@ -98,9 +98,10 @@ EventEmitter.prototype.getMaxListeners = function getMaxListeners() { return $getMaxListeners(this); }; -// Returns the longest sequence of a that fully appears in b, of length >= 3. +// Returns the longest sequence of `a` that fully appears in `b`, +// of length at least 3. // This is a lazy approach but should work well enough, given that stack -// frames are usually unequal if they don't appear in a group and that +// frames are usually unequal or otherwise appear in groups, and that // we only run this code in case of an unhandled exception. function longestSeqContainedIn(a, b) { for (var len = a.length; len >= 3; --len) { From 3c3fa83a743d57da9c3dd40264776f56597a4fb7 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 17:53:47 +0100 Subject: [PATCH 3/6] [squash] more tests --- lib/events.js | 4 ++-- ...=> events_unhandled_error_common_trace.js} | 0 ...> events_unhandled_error_common_trace.out} | 10 ++++----- .../events_unhandled_error_nexttick.js | 7 +++++++ .../events_unhandled_error_nexttick.out | 21 +++++++++++++++++++ .../events_unhandled_error_sameline.js | 4 ++++ .../events_unhandled_error_sameline.out | 19 +++++++++++++++++ 7 files changed, 58 insertions(+), 7 deletions(-) rename test/message/{test-unhandled-error-stack.js => events_unhandled_error_common_trace.js} (100%) rename test/message/{test-unhandled-error-stack.out => events_unhandled_error_common_trace.out} (63%) create mode 100644 test/message/events_unhandled_error_nexttick.js create mode 100644 test/message/events_unhandled_error_nexttick.out create mode 100644 test/message/events_unhandled_error_sameline.js create mode 100644 test/message/events_unhandled_error_sameline.out diff --git a/lib/events.js b/lib/events.js index 9f562724be18ea..a03c248bf7b7b4 100644 --- a/lib/events.js +++ b/lib/events.js @@ -143,9 +143,9 @@ function enhanceStackTrace(err, own) { if (len > 0) { ownStack.splice(off + 1, len - 1, ' [... lines matching original stack trace ...]'); - // Do this last, because it is the only operation with side effects. - err.stack = err.stack + sep + ownStack.join('\n'); } + // Do this last, because it is the only operation with side effects. + err.stack = err.stack + sep + ownStack.join('\n'); } const kExpandStack = Symbol('kExpandStack'); diff --git a/test/message/test-unhandled-error-stack.js b/test/message/events_unhandled_error_common_trace.js similarity index 100% rename from test/message/test-unhandled-error-stack.js rename to test/message/events_unhandled_error_common_trace.js diff --git a/test/message/test-unhandled-error-stack.out b/test/message/events_unhandled_error_common_trace.out similarity index 63% rename from test/message/test-unhandled-error-stack.out rename to test/message/events_unhandled_error_common_trace.out index e4ea1b49721830..272d7be1729ebb 100644 --- a/test/message/test-unhandled-error-stack.out +++ b/test/message/events_unhandled_error_common_trace.out @@ -3,9 +3,9 @@ events.js:* ^ Error: foo:bar - at bar (*test-unhandled-error-stack.js:*:*) - at foo (*test-unhandled-error-stack.js:*:*) - at Object. (*test-unhandled-error-stack.js:*:*) + at bar (*events_unhandled_error_common_trace.js:*:*) + at foo (*events_unhandled_error_common_trace.js:*:*) + at Object. (*events_unhandled_error_common_trace.js:*:*) at Module._compile (module.js:*:*) at Object.Module._extensions..js (module.js:*:*) at Module.load (module.js:*:*) @@ -14,8 +14,8 @@ Error: foo:bar at Function.Module.runMain (module.js:*:*) at startup (bootstrap_node.js:*:*) Emitted 'error' event at at: - at quux (*test-unhandled-error-stack.js:*:*) - at Object. (*test-unhandled-error-stack.js:*:*) + at quux (*events_unhandled_error_common_trace.js:*:*) + at Object. (*events_unhandled_error_common_trace.js:*:*) at Module._compile (module.js:*:*) [... lines matching original stack trace ...] at startup (bootstrap_node.js:*:*) diff --git a/test/message/events_unhandled_error_nexttick.js b/test/message/events_unhandled_error_nexttick.js new file mode 100644 index 00000000000000..713031eeefa042 --- /dev/null +++ b/test/message/events_unhandled_error_nexttick.js @@ -0,0 +1,7 @@ +'use strict'; +require('../common'); +const EventEmitter = require('events'); +const er = new Error(); +process.nextTick(() => { + new EventEmitter().emit('error', er); +}); diff --git a/test/message/events_unhandled_error_nexttick.out b/test/message/events_unhandled_error_nexttick.out new file mode 100644 index 00000000000000..551693781afa0b --- /dev/null +++ b/test/message/events_unhandled_error_nexttick.out @@ -0,0 +1,21 @@ +events.js:* + throw er; // Unhandled 'error' event + ^ + +Error + at Object. (*events_unhandled_error_nexttick.js:*:*) + at Module._compile (module.js:*:*) + at Object.Module._extensions..js (module.js:*:*) + at Module.load (module.js:*:*) + at tryModuleLoad (module.js:*:*) + at Function.Module._load (module.js:*:*) + at Function.Module.runMain (module.js:*:*) + at startup (bootstrap_node.js:*:*) + at bootstrap_node.js:*:* +Emitted 'error' event at at: + at process.nextTick (*events_unhandled_error_nexttick.js:*:*) + at process._tickCallback (internal/process/next_tick.js:*:*) + at Function.Module.runMain (module.js:*:*) + at startup (bootstrap_node.js:*:*) + at bootstrap_node.js:*:* + diff --git a/test/message/events_unhandled_error_sameline.js b/test/message/events_unhandled_error_sameline.js new file mode 100644 index 00000000000000..1e5e77d08c9919 --- /dev/null +++ b/test/message/events_unhandled_error_sameline.js @@ -0,0 +1,4 @@ +'use strict'; +require('../common'); +const EventEmitter = require('events'); +new EventEmitter().emit('error', new Error()); diff --git a/test/message/events_unhandled_error_sameline.out b/test/message/events_unhandled_error_sameline.out new file mode 100644 index 00000000000000..65ab590a3ea464 --- /dev/null +++ b/test/message/events_unhandled_error_sameline.out @@ -0,0 +1,19 @@ +events.js:* + throw er; // Unhandled 'error' event + ^ + +Error + at Object. (*events_unhandled_error_sameline.js:*:*) + at Module._compile (module.js:*:*) + at Object.Module._extensions..js (module.js:*:*) + at Module.load (module.js:*:*) + at tryModuleLoad (module.js:*:*) + at Function.Module._load (module.js:*:*) + at Function.Module.runMain (module.js:*:*) + at startup (bootstrap_node.js:*:*) + at bootstrap_node.js:*:* +Emitted 'error' event at at: + at Object. (*events_unhandled_error_sameline.js:*:*) + at Module._compile (module.js:*:*) + [... lines matching original stack trace ...] + at bootstrap_node.js:*:* From 70457e0c77c126e0760f42017a2856faf7670f6b Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 22:06:21 +0100 Subject: [PATCH 4/6] [squash] remove at at --- lib/events.js | 2 +- test/message/events_unhandled_error_common_trace.out | 2 +- test/message/events_unhandled_error_nexttick.out | 2 +- test/message/events_unhandled_error_sameline.out | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/events.js b/lib/events.js index a03c248bf7b7b4..b97f44dec37832 100644 --- a/lib/events.js +++ b/lib/events.js @@ -134,7 +134,7 @@ function longestCommonSubsequence(a, b) { } function enhanceStackTrace(err, own) { - const sep = '\nEmitted \'error\' event at at:\n'; + const sep = '\nEmitted \'error\' event at:\n'; const errStack = err.stack.split('\n').slice(1); const ownStack = own.stack.split('\n').slice(1); diff --git a/test/message/events_unhandled_error_common_trace.out b/test/message/events_unhandled_error_common_trace.out index 272d7be1729ebb..e3ff6089699304 100644 --- a/test/message/events_unhandled_error_common_trace.out +++ b/test/message/events_unhandled_error_common_trace.out @@ -13,7 +13,7 @@ Error: foo:bar at Function.Module._load (module.js:*:*) at Function.Module.runMain (module.js:*:*) at startup (bootstrap_node.js:*:*) -Emitted 'error' event at at: +Emitted 'error' event at: at quux (*events_unhandled_error_common_trace.js:*:*) at Object. (*events_unhandled_error_common_trace.js:*:*) at Module._compile (module.js:*:*) diff --git a/test/message/events_unhandled_error_nexttick.out b/test/message/events_unhandled_error_nexttick.out index 551693781afa0b..33c9a9ef571706 100644 --- a/test/message/events_unhandled_error_nexttick.out +++ b/test/message/events_unhandled_error_nexttick.out @@ -12,7 +12,7 @@ Error at Function.Module.runMain (module.js:*:*) at startup (bootstrap_node.js:*:*) at bootstrap_node.js:*:* -Emitted 'error' event at at: +Emitted 'error' event at: at process.nextTick (*events_unhandled_error_nexttick.js:*:*) at process._tickCallback (internal/process/next_tick.js:*:*) at Function.Module.runMain (module.js:*:*) diff --git a/test/message/events_unhandled_error_sameline.out b/test/message/events_unhandled_error_sameline.out index 65ab590a3ea464..100c294276d04b 100644 --- a/test/message/events_unhandled_error_sameline.out +++ b/test/message/events_unhandled_error_sameline.out @@ -12,7 +12,7 @@ Error at Function.Module.runMain (module.js:*:*) at startup (bootstrap_node.js:*:*) at bootstrap_node.js:*:* -Emitted 'error' event at at: +Emitted 'error' event at: at Object. (*events_unhandled_error_sameline.js:*:*) at Module._compile (module.js:*:*) [... lines matching original stack trace ...] From 9cb8461f87135550aed69271faa8d93406f5a02c Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 22:35:13 +0100 Subject: [PATCH 5/6] [squash] hide internals better --- lib/events.js | 9 +++++---- lib/internal/bootstrap_node.js | 6 +++--- lib/internal/util.js | 3 ++- 3 files changed, 10 insertions(+), 8 deletions(-) diff --git a/lib/events.js b/lib/events.js index b97f44dec37832..cfceb5b040a486 100644 --- a/lib/events.js +++ b/lib/events.js @@ -148,9 +148,6 @@ function enhanceStackTrace(err, own) { err.stack = err.stack + sep + ownStack.join('\n'); } -const kExpandStack = Symbol('kExpandStack'); -Object.defineProperty(EventEmitter, 'kExpandStack', { value: kExpandStack }); - EventEmitter.prototype.emit = function emit(type, ...args) { let doError = (type === 'error'); @@ -167,9 +164,13 @@ EventEmitter.prototype.emit = function emit(type, ...args) { er = args[0]; if (er instanceof Error) { try { + const { kExpandStackSymbol } = require('internal/util'); const capture = {}; Error.captureStackTrace(capture, EventEmitter.prototype.emit); - er[kExpandStack] = enhanceStackTrace.bind(null, er, capture); + Object.defineProperty(er, kExpandStackSymbol, { + value: enhanceStackTrace.bind(null, er, capture), + configurable: true + }); } catch (e) {} // Note: The comments on the `throw` lines are intentional, they show diff --git a/lib/internal/bootstrap_node.js b/lib/internal/bootstrap_node.js index da3d5d6a5c2d7b..a0d508c5b135a3 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -459,9 +459,9 @@ // nothing to be done about it at this point. } try { - const { kExpandStack } = NativeModule.require('events'); - if (typeof er[kExpandStack] === 'function') - er[kExpandStack](); + const { kExpandStackSymbol } = NativeModule.require('internal/util'); + if (typeof er[kExpandStackSymbol] === 'function') + er[kExpandStackSymbol](); } catch (er) {} return false; } diff --git a/lib/internal/util.js b/lib/internal/util.js index 5cec64ca18bfba..815dcc871eea3a 100644 --- a/lib/internal/util.js +++ b/lib/internal/util.js @@ -371,5 +371,6 @@ module.exports = { // Used by the buffer module to capture an internal reference to the // default isEncoding implementation, just in case userland overrides it. - kIsEncodingSymbol: Symbol('node.isEncoding') + kIsEncodingSymbol: Symbol('kIsEncodingSymbol'), + kExpandStackSymbol: Symbol('kExpandStackSymbol') }; From 92b6be15e78f8c6779ec95c500cb916c0f45b7d5 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Thu, 1 Mar 2018 22:47:05 +0000 Subject: [PATCH 6/6] [squash] bridgear comments --- lib/events.js | 11 +---------- .../test-events-uncaught-exception-stack.js | 16 ++++++++++++++++ 2 files changed, 17 insertions(+), 10 deletions(-) create mode 100644 test/parallel/test-events-uncaught-exception-stack.js diff --git a/lib/events.js b/lib/events.js index cfceb5b040a486..0a220b5d821e7f 100644 --- a/lib/events.js +++ b/lib/events.js @@ -124,22 +124,13 @@ function longestSeqContainedIn(a, b) { return [ 0, 0, 0 ]; } -function longestCommonSubsequence(a, b) { - const [ l1, i1, j1 ] = longestSeqContainedIn(a, b); - const [ l2, i2, j2 ] = longestSeqContainedIn(b, a); - if (l1 > l2) - return [ l1, j1, i1 ]; - else - return [ l2, i2, j2 ]; -} - function enhanceStackTrace(err, own) { const sep = '\nEmitted \'error\' event at:\n'; const errStack = err.stack.split('\n').slice(1); const ownStack = own.stack.split('\n').slice(1); - const [ len, off ] = longestCommonSubsequence(errStack, ownStack); + const [ len, off ] = longestSeqContainedIn(ownStack, errStack); if (len > 0) { ownStack.splice(off + 1, len - 1, ' [... lines matching original stack trace ...]'); diff --git a/test/parallel/test-events-uncaught-exception-stack.js b/test/parallel/test-events-uncaught-exception-stack.js new file mode 100644 index 00000000000000..c55322a5aa56c4 --- /dev/null +++ b/test/parallel/test-events-uncaught-exception-stack.js @@ -0,0 +1,16 @@ +'use strict'; +const common = require('../common'); +const assert = require('assert'); +const EventEmitter = require('events'); + +// Tests that the error stack where the exception was thrown is *not* appended. + +process.on('uncaughtException', common.mustCall((err) => { + const lines = err.stack.split('\n'); + assert.strictEqual(lines[0], 'Error'); + lines.slice(1).forEach((line) => { + assert(/^ at/.test(line), `${line} has an unexpected format`); + }); +})); + +new EventEmitter().emit('error', new Error());