From 5b8c97f6bcaef5afaaa2e6de399228ff61a90c94 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 26 Feb 2018 15:46:50 +0100 Subject: [PATCH] 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. PR-URL: https://github.com/nodejs/node/pull/19003 Reviewed-By: Benjamin Gruenbaum Reviewed-By: James M Snell --- lib/events.js | 55 ++++++++++++++++++- lib/internal/bootstrap_node.js | 5 ++ lib/internal/util.js | 3 +- .../events_unhandled_error_common_trace.js | 20 +++++++ .../events_unhandled_error_common_trace.out | 22 ++++++++ .../events_unhandled_error_nexttick.js | 7 +++ .../events_unhandled_error_nexttick.out | 20 +++++++ .../events_unhandled_error_sameline.js | 4 ++ .../events_unhandled_error_sameline.out | 19 +++++++ .../test-events-uncaught-exception-stack.js | 16 ++++++ 10 files changed, 169 insertions(+), 2 deletions(-) create mode 100644 test/message/events_unhandled_error_common_trace.js create mode 100644 test/message/events_unhandled_error_common_trace.out 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 create mode 100644 test/parallel/test-events-uncaught-exception-stack.js diff --git a/lib/events.js b/lib/events.js index 07fa6484363116..799f8b4309d4c3 100644 --- a/lib/events.js +++ b/lib/events.js @@ -94,6 +94,47 @@ EventEmitter.prototype.getMaxListeners = function getMaxListeners() { return $getMaxListeners(this); }; +// 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 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) { + 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 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 ] = longestSeqContainedIn(ownStack, errStack); + 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'); +} + EventEmitter.prototype.emit = function emit(type, ...args) { let doError = (type === 'error'); @@ -109,13 +150,25 @@ EventEmitter.prototype.emit = function emit(type, ...args) { if (args.length > 0) er = args[0]; if (er instanceof Error) { + try { + const { kExpandStackSymbol } = require('internal/util'); + const capture = {}; + Error.captureStackTrace(capture, EventEmitter.prototype.emit); + 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 + // 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 06bed3faaa4870..b31e06cba6bafc 100644 --- a/lib/internal/bootstrap_node.js +++ b/lib/internal/bootstrap_node.js @@ -438,6 +438,11 @@ } catch (er) { // nothing to be done about it at this point. } + try { + 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 fd481450bc246d..0241573fa818c8 100644 --- a/lib/internal/util.js +++ b/lib/internal/util.js @@ -320,5 +320,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') }; diff --git a/test/message/events_unhandled_error_common_trace.js b/test/message/events_unhandled_error_common_trace.js new file mode 100644 index 00000000000000..e6c168fc06eb33 --- /dev/null +++ b/test/message/events_unhandled_error_common_trace.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/events_unhandled_error_common_trace.out b/test/message/events_unhandled_error_common_trace.out new file mode 100644 index 00000000000000..d39a95cb77f068 --- /dev/null +++ b/test/message/events_unhandled_error_common_trace.out @@ -0,0 +1,22 @@ +events.js:* + throw er; // Unhandled 'error' event + ^ + +Error: foo:bar + 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:*:*) + 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 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:*:*) + at 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..f0591610ffdb31 --- /dev/null +++ b/test/message/events_unhandled_error_nexttick.out @@ -0,0 +1,20 @@ +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 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..100c294276d04b --- /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 Object. (*events_unhandled_error_sameline.js:*:*) + at Module._compile (module.js:*:*) + [... lines matching original stack trace ...] + at bootstrap_node.js:*:* 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());