Skip to content
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

process.throwDeprecation hides original error stack #17871

Closed
nylen opened this issue Dec 26, 2017 · 12 comments
Closed

process.throwDeprecation hides original error stack #17871

nylen opened this issue Dec 26, 2017 · 12 comments
Labels
confirmed-bug Issues with confirmed bugs.

Comments

@nylen
Copy link

nylen commented Dec 26, 2017

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
Copy link
Member

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.

@BridgeAR BridgeAR added the question Issues that look for answers. label Dec 26, 2017
@nylen
Copy link
Author

nylen commented Dec 26, 2017

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
Copy link
Member

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
Copy link
Author

nylen commented Dec 26, 2017

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
Copy link
Member

@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
Copy link
Member

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
Copy link
Author

nylen commented Dec 28, 2017

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
Copy link
Author

nylen commented Dec 28, 2017

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
Copy link
Author

nylen commented Aug 5, 2018

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
Copy link
Author

nylen commented Nov 12, 2018

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

@nylen
Copy link
Author

nylen commented Mar 16, 2020

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 BridgeAR added confirmed-bug Issues with confirmed bugs. and removed question Issues that look for answers. labels Mar 17, 2020
BridgeAR added a commit to BridgeAR/node that referenced this issue Mar 17, 2020
This makes sure all warnings that were triggered before a deprecation
warning during the same tick are properly handled and logged.

It also guarantees that users can not catch the error anymore.

Fixes: nodejs#17871
@BridgeAR
Copy link
Member

@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 #32312

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
confirmed-bug Issues with confirmed bugs.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants