nodejs / node-report

Delivers a human-readable diagnostic summary, written to file.
https://www.npmjs.com/package/node-report
Other
326 stars 45 forks source link

node-report reports error thrown via napi as uncaught when in fact the JS caller catches it #131

Closed ghost closed 3 years ago

ghost commented 5 years ago

node-report incorrectly reports an uncaught exception for an error that is in fact caught if the error is thrown in native code using napi_throw.

I am filing this issue here since I know that node-report is being pulled into node. I don't know if the issue exists in node v12. I have not tried it.

Here is how to reproduce the problem in v10 using the node-report npm module:

const nodereport = require("node-report/api");
nodereport.setEvents("exception+fatalerror+apicall");
nodereport.setDirectory("d:\\crash");
nodereport.setVerbose("yes");
try {
    nativeFunctionThatThrows();
} catch (err) {
    console.log("got here");
}

The function nativeFunctionThatThrows is implemented in my node addon. It calls napi_throw.

The output is:

Writing Node.js report to file: node-report.20190621.145907.22080.001.txt
Node.js report completed
got here

A portion of the generated node-report is:

Event: exception, location: "OnUncaughtException".
[snip]
==== Native Stack Trace ========================================================

 0: [pc=0x00007FF8E6961FE0] nodereport::TriggerNodeReport [+0] in d:\imjs\imodeljs\common\temp\node_modules\.registry.npmjs.org\node-report\2.2.7\node_modules\node-report\src\node_report.cc: line: 196
 1: [pc=0x00007FF8E6969AB0] nodereport::OnUncaughtException [+0] in d:\imjs\imodeljs\common\temp\node_modules\.registry.npmjs.org\node-report\2.2.7\node_modules\node-report\src\module.cc: line: 184
 2: [pc=0x00007FF7E97F3E10] v8::internal::Isolate::PrintStack [+5398]
 3: [pc=0x00007FF7E9328200] v8::Isolate::ThrowException [+62]
 4: [pc=0x00007FF7E90718F0] napi_throw [+187]
 5: [pc=0x00007FF8E82FBB19]

The node uncaughtException event has no such problem. When I change the example above to this:

process.on("uncaughtException", (err, origin) => {
    console.error(err);
    console.log(origin);
});
try {
    nativeFunctionThatThrows();
} catch (err) {
    console.log("got here");
}

The output is simply got here.

prettydiff commented 5 years ago

This project exists for users to ask Node related questions that can be answered, such as seeking guidance or suggestions. On the contrary it appears you are reporting a defect. I would report this as an issue in the node-report project: https://github.com/nodejs/node-report/issues

richardlau commented 5 years ago

nodereport.setEvents("exception") sets the V8 --abort_on_uncaught_exception option. Can you try your examples with --abort_on_uncaught_exception to see if it reproduces without node-report? Otherwise if you could try to replicate on Node.js 12 with the experimental --experimental-report there are more people likely to be able to help than with the standalone module.

ghost commented 5 years ago

I get something like that behavior when I specify --abort_on_uncaught_exception. That is, when I set that in NODE_OPTIONS and rerun my test without node-report:

That is, despite the fact that my Javascript program has wrapped the call to the addon in try/catch, my program does not catch the error when --abort_on_uncaught_exception is specified and the error is thrown in native code.

In the scenario where I do not specify this command-line option and do enable node-report, I get a report of an uncaught exception and my Javascript program does catch the error.

richardlau commented 5 years ago

cc @nodejs/v8 is this expected behaviour for --abort_on_uncaught_exception?

richardlau commented 5 years ago

There was https://github.com/nodejs/node/issues/13258 that was kind of similar for things executed in vm. Perhaps n-api has a similar v8::TryCatch (https://github.com/nodejs/node/issues/13258#issuecomment-304501990)?

cc @nodejs/n-api

mhdawson commented 5 years ago

@sam-wilson-bentley-com I think the next step is to open an issue in the node/nodejs repo reporting what looks like a bug along with the coded needed to recreate without using node-report.

mmarchini commented 5 years ago

I would need to look into it further, but I guess this is related to how V8 handles the --abort-on-uncaught-exception using catch prediction. Basically when V8 can't say for sure that an exception will be handled, it calls the handler for this flag which will crash the process if the flag is set. This happens because sometimes V8 needs to continue the execution until the end to determine if an exception was catch or not. Since --abort-on-uncaught-exception should crash at the moment the exception was thrown, V8 takes the conservative approach and crashes if it might be an unhandled exception.

There's a pure JavaScript example that shows this behavior:

$ # The command below works, as it should
$ node -e "function foo() { try { throw new Error('Foo') } finally {return; } } foo()"

$ # The command below just crashes, even though the error is handled later
$ node --abort-on-uncaught-exception -e "function foo() { try { throw new Error('Foo') } finally {return; } } foo()"
Uncaught Error: Foo

FROM
foo ([eval]:1:24)
[eval]:1:70
Script.runInThisContext (vm.js:119:20)
Object.runInThisContext (vm.js:326:38)
Object.<anonymous> ([eval]-wrapper:6:22)
Module._compile (internal/modules/cjs/loader.js:701:30)
evalScript (internal/bootstrap/node.js:589:27)
startup (internal/bootstrap/node.js:265:9)
bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)
[1]    6415 illegal hardware instruction (core dumped)  node --abort-on-uncaught-exception -e 

My guess is that V8 catch prediction can't tell if an error will be catched when it's thrown from C++ context, so it will take the conservative approach and crash the process. Or maybe the C++ code was written in a way similar to the JavaScript example above.

mmarchini commented 5 years ago

By the way, the node-report we integrated in Node.js v12 should not be affected by this, so we might be able to fix it on the module as well, but it would probably be a breaking change.

mmarchini commented 5 years ago

(I got the wrong example above :(, let me see if I can find the right one)

mmarchini commented 5 years ago

I updated my comment with more information + the correct examples.

@sam-wilson-bentley-com do you have a C++ code you can share where this issue happens (i.e., the code for nativeFunctionThatThrows?

gireeshpunathil commented 5 years ago

I guess it can be as trivial (not tested though) as:

#include <node_api.h>

static napi_value foo(napi_env env, napi_value exports) {
  return napi_throw(env, NULL);
}

NAPI_MODULE(NODE_GYP_MODULE_NAME, foo)
ghost commented 5 years ago

gireeshpunathil's example captures what my addon code is doing.

ghost commented 5 years ago

I tried mmarchini's examples of executing scripts on the command line with and without the --abort-on-uncaught-exception command-line option, and I see the same result that he reports.

However, the outcome is different when I put the script into a .js file and execute it from there. In this case, the --abort-on-uncaught-exception command-line option does not cause node to abort when the error is thrown in Javascript, but it does when the exception is thrown in native code.

Here is the version of foo.js that throws in Javascript:

function foo() {
    try {
        throw new Error("foo");
    }
    catch (err) {
        console.log("I caught this exception: " + err.message);
    }
}

foo();

Whether I run node foo.js or node --abort-on-uncaught-exception foo.js, the program prints I caught this exception: foo.

Then I changed the example to throw in native code:

let native = require("myaddon");

function foo() {
    try {
        native.nativeFunctionThatThrows();
        // throw new Error("foo");
    }
    catch (err) {
        console.log("I caught this exception: " + err.message);
    }
}

foo();

When I run node foo.js, the program prints I caught this exception: MyAddonException. When I run node --abort-on-uncaught-exception foo.js, the program prints the following:

Uncaught TypeError: MyAddonException

FROM
foo (D:\try.js:5:16)
Object.<anonymous> (D:\try.js:13:1)
Module._compile (internal/modules/cjs/loader.js:701:30)
etc.

and then aborts.

mmarchini commented 5 years ago

Here is the version of foo.js that throws in Javascript:

For the script to behave the same as in my example, it must be finally instead of catch and you must return inside the finally. This is a very tricky case but it demonstrates how crash prediction can have a false-positive.

Then I changed the example to throw in native code: When I run node foo.js, the program prints I caught this exception: MyAddonException. When I run node --abort-on-uncaught-exception foo.js, the program prints the following: and then aborts.

This confirms that errors thrown from native code will trigger the abort on uncaught exception event even if it's catched in JS. It might be an implementation detail on N-API, but I think it's more likely a limitation of V8's catch prediction (I think C++ Throw implementation might bypass catch prediction, but someone from @nodejs/v8 would need to confirm that).

node-report can avoid this by generating the report on the same event we use in core instead of the abort event. It should still use the abort event if the --abort-on-uncaught-exception is given though, otherwise we'll have the same problem reported in https://github.com/nodejs/node/issues/28414. This issue should be moved to nodejs/node-report, since it doesn't affect our integrated node-report implementation.

hashseed commented 5 years ago

Can you maybe construct a V8 cctest for this case?