events: show throw stack trace for uncaught exception

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: nodejs#19003
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: James M Snell <[email protected]>

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];

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;
       }
 

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')
 };

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();

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.<anonymous> (*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.<anonymous> (*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:*:*

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);
+});

test/message/events_unhandled_error_nexttick.out

@@ -0,0 +1,20 @@
+events.js:*
+      throw er; // Unhandled 'error' event
+      ^
+
+Error
+    at Object.<anonymous> (*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:*:*

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());

test/message/events_unhandled_error_sameline.out

@@ -0,0 +1,19 @@
+events.js:*
+      throw er; // Unhandled 'error' event
+      ^
+
+Error
+    at Object.<anonymous> (*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.<anonymous> (*events_unhandled_error_sameline.js:*:*)
+    at Module._compile (module.js:*:*)
+    [... lines matching original stack trace ...]
+    at bootstrap_node.js:*:*

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());