Node: `process.throwDeprecation` hides original error stack

[nylen]

Node v9.3.0 on Linux (I would expect other versions since the introduction of the deprecation warning stuff - and other platforms - to behave the same way)

Current behavior

It doesn't matter whether you use process.throwDeprecation = true or node --throw-deprecation here, the behavior is the same.

async function x() {
    throw new Error( 'aaaa' );
}

process.throwDeprecation = true;

x().then( r => console.log( r ) );

$ node test1.js
internal/process/warning.js:143
        throw warning;
        ^

DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
    at emitWarning (internal/process/promises.js:92:15)
    at emitPendingUnhandledRejections (internal/process/promises.js:109:11)
    at runMicrotasksCallback (internal/process/next_tick.js:118:9)
    at process._tickCallback (internal/process/next_tick.js:150:11)
    at Function.Module.runMain (module.js:703:11)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3

Expected behavior

Note concise output that preserves the original error stack without adding irrelevant stuff.

async function x() {
        throw new Error( 'aaaa' );
}

process.on( 'unhandledRejection', err => {
        console.error( 'Unhandled promise rejection:', err );
        process.exit( 1 );
} );

x().then( r => console.log( r ) );

$ node test2.js 
Unhandled promise rejection: Error: aaaa
    at x (../test2.js:2:8)
    at Object.<anonymous> (.../test2.js:10:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:573:32)
    at tryModuleLoad (module.js:513:12)
    at Function.Module._load (module.js:505:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3

[BridgeAR]

This is normal behavior as the error is thrown async as most errors in Node.js. Tracking errors better can be done with async hooks on your side. Currently there is nothing that can be done to further improve this. Therefore I am closing this issue.

[nylen]

When an error occurs in my code, I expect to see the place in my code where it occurred. I think this is a pretty reasonable expectation and this issue should stay open until it's met for the case I described.

[BridgeAR]

Refs #11865

@nylen there you will find more information about the problem. It has nothing to do with "your code". What is actually happening is something like

function throwing() { throw new Error() }
function notIncludedInStack() { setTimeout(throwing, 1) }
notIncludedInStack()

This will only show "throwing" in the stack trace and not the original function because the error is thrown async.

[nylen]

Thanks for the context.

Of course I'd like to have full async stack traces, but that's not really what this issue is about. In this specific case, I don't want to see any of these stack trace lines, because they're not relevant to the actual problem that occurred:

    at emitWarning (internal/process/promises.js:92:15)
    at emitPendingUnhandledRejections (internal/process/promises.js:109:11)
    at runMicrotasksCallback (internal/process/next_tick.js:118:9)
    at process._tickCallback (internal/process/next_tick.js:150:11)
    at Function.Module.runMain (module.js:703:11)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:618:3

It's a bit frustrating to have this closed as "question" because all of the information needed to print a better stack trace is readily available.

[BridgeAR]

@nylen I will try to explain it with your code

async function x() {
    throw new Error( 'aaaa' );
}

This translates into

function x() {
  return Promise.reject(new Error('aaaa'));
}

As soon as the promise is rejected Node.js tracks if it was caught on the nextTick. This is not the case here and as soon as Node.js realizes this (remember, it is already in the next tick), a new Error is created. This error has a stack trace that has no knowledge about the function x as it only knows things happening sync.

I hope this explains the problem better.

[bnoordhuis]

We could defer the deprecation warning by a tick, that gives the UnhandledPromiseRejectionWarnings time to print. I.e., this diff:

diff --git a/lib/internal/process/promises.js b/lib/internal/process/promises.js
index 82f15f9f9d..8985cd1a63 100644
--- a/lib/internal/process/promises.js
+++ b/lib/internal/process/promises.js
@@ -89,11 +89,18 @@ function setupPromises(scheduleMicrotasks) {
     process.emitWarning(warning);
     if (!deprecationWarned) {
       deprecationWarned = true;
-      process.emitWarning(
-        'Unhandled promise rejections are deprecated. In the future, ' +
-        'promise rejections that are not handled will terminate the ' +
-        'Node.js process with a non-zero exit code.',
-        'DeprecationWarning', 'DEP0018');
+      const warn = () => {
+        process.emitWarning(
+          'Unhandled promise rejections are deprecated. In the future, ' +
+          'promise rejections that are not handled will terminate the ' +
+          'Node.js process with a non-zero exit code.',
+          'DeprecationWarning', 'DEP0018');
+      };
+      if (process.throwDeprecation)
+        process.nextTick(warn);  // Give warnings time to print.
+      else
+        warn();
     }
   }

Produces this output:

(node:77108) UnhandledPromiseRejectionWarning: Error: aaaa
    at x (/home/bnoordhuis/src/bug17871.js:2:11)
    at Object.<anonymous> (/home/bnoordhuis/src/bug17871.js:7:1)
    at Module._compile (module.js:660:30)
    at Object.Module._extensions..js (module.js:671:10)
    at Module.load (module.js:577:32)
    at tryModuleLoad (module.js:517:12)
    at Function.Module._load (module.js:509:3)
    at Function.Module.runMain (module.js:701:10)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:645:3
(node:77108) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
internal/process/warning.js:143
        throw warning;
        ^

DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
    at process.nextTick (internal/process/promises.js:93:17)
    at process._tickCallback (internal/process/next_tick.js:114:11)
    at Function.Module.runMain (module.js:703:11)
    at startup (bootstrap_node.js:194:16)
    at bootstrap_node.js:645:3

OTOH, a one-off hack like that is kind of yuck and it's not as if node isn't doing exactly what it's being told to - throw instead of emit.

@nylen You can try opening a PR and see what others think.

[nylen]

as soon as Node.js realizes this (remember, it is already in the next tick), a new Error is created. This error has a stack trace that has no knowledge about the function x as it only knows things happening sync.

This is the root of the problem, I think. Why does Node have to create a new Error here as opposed to re-using the error from the promise rejection?

[nylen]

OTOH, a one-off hack like that is kind of yuck and it's not as if node isn't doing exactly what it's being told to - throw instead of emit.

I agree with all of this. I think a better fix involves throwing the original error instead of throw warning, but I am not sure the best way to achieve it.

[nylen]

Just wrote this in another script:

// https://github.com/nodejs/node/issues/17871 :(
// process.throwDeprecation = true;
process.on( 'unhandledRejection', err => {
    console.error( 'Unhandled promise rejection:', err );
    process.exit( 1 );
} );

I _want_ to like developing against Node.js with promises and async/await, but stuff like this doesn't make it easy.

[nylen]

This is still broken, and I still don't understand why this issue was closed.

[nylen]

I'm still writing this at the top of almost all my scripts:

// https://github.com/nodejs/node/issues/17871 :(
process.on( 'unhandledRejection', err => {
    console.error( 'Unhandled promise rejection:', err );
    process.exit( 1 );
} );

[BridgeAR]

@nylen I am sorry, I somehow misread your original issue. I just opened a PR to fix the issue. The warning mechanism was a bit off by delaying the actual warnings but not the error.

See https://github.com/nodejs/node/pull/32312