From ef8b2284cf41d420d436b11a720332510e34f09f Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Thu, 25 Apr 2019 03:03:48 +0800 Subject: [PATCH 1/3] process: reduce the number of internal frames in async stack trace Previously, we call the JS land `runNextTicks` implementation immediately from JS land after evaluating the main module or the input, so these synchronous JS call frames would show up in the stack trace of the async errors, which can be confusing. This patch moves those calls into C++ so that more of these internal scheduler implementation details can be hidden and the users can see a cleaner a cleaner async JS stack trace. --- lib/internal/modules/cjs/loader.js | 4 -- lib/internal/process/execution.js | 4 -- lib/internal/process/task_queues.js | 1 + src/node.cc | 10 +++-- src/node_process.h | 10 +++++ src/node_task_queue.cc | 15 +++++++ test/fixtures/async-error.js | 27 ++++++++++++ test/message/async_error_eval_cjs.js | 36 ++++++++++++++++ test/message/async_error_eval_cjs.out | 6 +++ test/message/async_error_eval_esm.js | 42 +++++++++++++++++++ test/message/async_error_eval_esm.out | 7 ++++ test/message/async_error_microtask_main.js | 13 ++++++ test/message/async_error_microtask_main.out | 6 +++ test/message/async_error_nexttick_main.js | 13 ++++++ test/message/async_error_nexttick_main.out | 7 ++++ test/message/async_error_sync_esm.mjs | 14 +++++++ test/message/async_error_sync_esm.out | 7 ++++ test/message/async_error_sync_main.js | 13 ++++++ test/message/async_error_sync_main.out | 6 +++ .../events_unhandled_error_nexttick.out | 3 -- test/message/nexttick_throw.out | 3 -- .../unhandled_promise_trace_warnings.out | 6 --- 22 files changed, 230 insertions(+), 23 deletions(-) create mode 100644 test/fixtures/async-error.js create mode 100644 test/message/async_error_eval_cjs.js create mode 100644 test/message/async_error_eval_cjs.out create mode 100644 test/message/async_error_eval_esm.js create mode 100644 test/message/async_error_eval_esm.out create mode 100644 test/message/async_error_microtask_main.js create mode 100644 test/message/async_error_microtask_main.out create mode 100644 test/message/async_error_nexttick_main.js create mode 100644 test/message/async_error_nexttick_main.out create mode 100644 test/message/async_error_sync_esm.mjs create mode 100644 test/message/async_error_sync_esm.out create mode 100644 test/message/async_error_sync_main.js create mode 100644 test/message/async_error_sync_main.out diff --git a/lib/internal/modules/cjs/loader.js b/lib/internal/modules/cjs/loader.js index a1e5046d406a1a..96b5e8b7b881b6 100644 --- a/lib/internal/modules/cjs/loader.js +++ b/lib/internal/modules/cjs/loader.js @@ -819,13 +819,9 @@ Module.runMain = function() { true /* fromPromise */ ); }); - // Handle any nextTicks added in the first tick of the program - process._tickCallback(); return; } Module._load(process.argv[1], null, true); - // Handle any nextTicks added in the first tick of the program - process._tickCallback(); }; Module.createRequireFromPath = (filename) => { diff --git a/lib/internal/process/execution.js b/lib/internal/process/execution.js index addd450ed3551c..19866d17226982 100644 --- a/lib/internal/process/execution.js +++ b/lib/internal/process/execution.js @@ -50,8 +50,6 @@ function evalModule(source, print) { error(e); process.exit(1); }); - // Handle any nextTicks added in the first tick of the program. - process._tickCallback(); } function evalScript(name, body, breakFirstLine, print) { @@ -83,8 +81,6 @@ function evalScript(name, body, breakFirstLine, print) { const { log } = require('internal/console/global'); log(result); } - // Handle any nextTicks added in the first tick of the program. - process._tickCallback(); } const exceptionHandlerState = { captureFn: null }; diff --git a/lib/internal/process/task_queues.js b/lib/internal/process/task_queues.js index 12e34b7ff79068..309e27e6ecd0fa 100644 --- a/lib/internal/process/task_queues.js +++ b/lib/internal/process/task_queues.js @@ -49,6 +49,7 @@ function setHasTickScheduled(value) { const queue = new FixedQueue(); +// Should be in sync with RunNextTicksNative in node_task_queue.cc function runNextTicks() { if (!hasTickScheduled() && !hasRejectionToWarn()) runMicrotasks(); diff --git a/src/node.cc b/src/node.cc index 10ef0d5bc7c522..636a92eab3f760 100644 --- a/src/node.cc +++ b/src/node.cc @@ -379,9 +379,13 @@ MaybeLocal StartExecution(Environment* env, const char* main_script_id) { ->GetFunction(env->context()) .ToLocalChecked()}; - MaybeLocal result = - ExecuteBootstrapper(env, main_script_id, ¶meters, &arguments); - return scope.EscapeMaybe(result); + Local result; + if (!ExecuteBootstrapper(env, main_script_id, ¶meters, &arguments) + .ToLocal(&result) || + !task_queue::RunNextTicksNative(env)) { + return MaybeLocal(); + } + return scope.Escape(result); } MaybeLocal StartMainThreadExecution(Environment* env) { diff --git a/src/node_process.h b/src/node_process.h index cb6ad85828b608..f01445b3c515d0 100644 --- a/src/node_process.h +++ b/src/node_process.h @@ -36,6 +36,16 @@ v8::MaybeLocal CreateProcessObject( const std::vector& args, const std::vector& exec_args); void PatchProcessObject(const v8::FunctionCallbackInfo& args); + +namespace task_queue { +// Handle any nextTicks added in the first tick of the program. +// We use the native version here for once so that any microtasks +// created by the main module is then handled from C++, and +// the call stack of the main script does not show up in the async error +// stack trace. +bool RunNextTicksNative(Environment* env); +} // namespace task_queue + } // namespace node #endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS #endif // SRC_NODE_PROCESS_H_ diff --git a/src/node_task_queue.cc b/src/node_task_queue.cc index b125f5d01ece66..af1d96fab22810 100644 --- a/src/node_task_queue.cc +++ b/src/node_task_queue.cc @@ -2,6 +2,7 @@ #include "node.h" #include "node_errors.h" #include "node_internals.h" +#include "node_process.h" #include "v8.h" #include @@ -38,6 +39,20 @@ static void EnqueueMicrotask(const FunctionCallbackInfo& args) { isolate->EnqueueMicrotask(args[0].As()); } +// Should be in sync with runNextTicks in internal/process/task_queues.js +bool RunNextTicksNative(Environment* env) { + TickInfo* tick_info = env->tick_info(); + if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn()) + env->isolate()->RunMicrotasks(); + if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn()) + return true; + + Local callback = env->tick_callback_function(); + CHECK(!callback.IsEmpty()); + return !callback->Call(env->context(), env->process_object(), 0, nullptr) + .IsEmpty(); +} + static void RunMicrotasks(const FunctionCallbackInfo& args) { args.GetIsolate()->RunMicrotasks(); } diff --git a/test/fixtures/async-error.js b/test/fixtures/async-error.js new file mode 100644 index 00000000000000..48b19b40d8fb54 --- /dev/null +++ b/test/fixtures/async-error.js @@ -0,0 +1,27 @@ +'use strict'; + +async function one() { + throw new Error('test'); +} + +async function breaker() { + return true; +} + +async function stack() { + await breaker(); +} + +async function two() { + await stack(); + await one(); +} +async function three() { + await two(); +} + +async function four() { + await three(); +} + +module.exports = four; diff --git a/test/message/async_error_eval_cjs.js b/test/message/async_error_eval_cjs.js new file mode 100644 index 00000000000000..4cb15032d98108 --- /dev/null +++ b/test/message/async_error_eval_cjs.js @@ -0,0 +1,36 @@ +'use strict'; + +require('../common'); +const fixtures = require('../common/fixtures'); +const errorModule = fixtures.path('async-error.js'); +const { spawnSync } = require('child_process'); + +const main = `'use strict'; + +const four = require('${errorModule}'); + +async function main() { + try { + await four(); + } catch (e) { + console.log(e); + } +} + +main(); +`; + +// --eval CJS +{ + const child = spawnSync(process.execPath, [ + '-e', + main + ], { + env: { ...process.env } + }); + + if (child.status !== 0) { + console.error(child.stderr.toString()); + } + console.error(child.stdout.toString()); +} diff --git a/test/message/async_error_eval_cjs.out b/test/message/async_error_eval_cjs.out new file mode 100644 index 00000000000000..8b27f345b0a4ff --- /dev/null +++ b/test/message/async_error_eval_cjs.out @@ -0,0 +1,6 @@ +Error: test + at one (*fixtures*async-error.js:4:9) + at two (*fixtures*async-error.js:17:9) + at async three (*fixtures*async-error.js:20:3) + at async four (*fixtures*async-error.js:24:3) + at async main ([eval]:7:5) diff --git a/test/message/async_error_eval_esm.js b/test/message/async_error_eval_esm.js new file mode 100644 index 00000000000000..33675b5a9db286 --- /dev/null +++ b/test/message/async_error_eval_esm.js @@ -0,0 +1,42 @@ +'use strict'; + +require('../common'); +const { spawnSync } = require('child_process'); + +const four = require('../common/fixtures') + .readSync('async-error.js') + .toString() + .split('\n') + .slice(2, -2) + .join('\n'); + +const main = `${four} + +async function main() { + try { + await four(); + } catch (e) { + console.log(e); + } +} + +main(); +`; + +// --eval ESM +{ + const child = spawnSync(process.execPath, [ + '--experimental-modules', + '--input-type', + 'module', + '-e', + main + ], { + env: { ...process.env } + }); + + if (child.status !== 0) { + console.error(child.stderr.toString()); + } + console.error(child.stdout.toString()); +} diff --git a/test/message/async_error_eval_esm.out b/test/message/async_error_eval_esm.out new file mode 100644 index 00000000000000..91ce0ce21cd456 --- /dev/null +++ b/test/message/async_error_eval_esm.out @@ -0,0 +1,7 @@ +Error: test + at one (eval:1:2:9) + at two (eval:1:15:9) + at processTicksAndRejections (internal/process/task_queues.js:*:*) + at async three (eval:1:18:3) + at async four (eval:1:22:3) + at async main (eval:1:28:5) diff --git a/test/message/async_error_microtask_main.js b/test/message/async_error_microtask_main.js new file mode 100644 index 00000000000000..5520c650addeac --- /dev/null +++ b/test/message/async_error_microtask_main.js @@ -0,0 +1,13 @@ +'use strict'; +require('../common'); +const four = require('../fixtures/async-error'); + +async function main() { + try { + await four(); + } catch (e) { + console.error(e); + } +} + +queueMicrotask(main); diff --git a/test/message/async_error_microtask_main.out b/test/message/async_error_microtask_main.out new file mode 100644 index 00000000000000..9512270730a976 --- /dev/null +++ b/test/message/async_error_microtask_main.out @@ -0,0 +1,6 @@ +Error: test + at one (*fixtures*async-error.js:4:9) + at two (*fixtures*async-error.js:17:9) + at async three (*fixtures*async-error.js:20:3) + at async four (*fixtures*async-error.js:24:3) + at async main (*message*async_error_microtask_main.js:7:5) diff --git a/test/message/async_error_nexttick_main.js b/test/message/async_error_nexttick_main.js new file mode 100644 index 00000000000000..ecd0531852da8f --- /dev/null +++ b/test/message/async_error_nexttick_main.js @@ -0,0 +1,13 @@ +'use strict'; +require('../common'); +const four = require('../fixtures/async-error'); + +async function main() { + try { + await four(); + } catch (e) { + console.error(e); + } +} + +process.nextTick(main); diff --git a/test/message/async_error_nexttick_main.out b/test/message/async_error_nexttick_main.out new file mode 100644 index 00000000000000..c6ac1e418086ac --- /dev/null +++ b/test/message/async_error_nexttick_main.out @@ -0,0 +1,7 @@ +Error: test + at one (*fixtures*async-error.js:4:9) + at two (*fixtures*async-error.js:17:9) + at processTicksAndRejections (internal/process/task_queues.js:*:*) + at async three (*fixtures*async-error.js:20:3) + at async four (*fixtures*async-error.js:24:3) + at async main (*message*async_error_nexttick_main.js:7:5) diff --git a/test/message/async_error_sync_esm.mjs b/test/message/async_error_sync_esm.mjs new file mode 100644 index 00000000000000..f437db87b0552c --- /dev/null +++ b/test/message/async_error_sync_esm.mjs @@ -0,0 +1,14 @@ +// Flags: --experimental-modules +/* eslint-disable node-core/required-modules */ +// import '../common/index.mjs'; +import four from '../fixtures/async-error.js'; + +async function main() { + try { + await four(); + } catch (e) { + console.error(e); + } +} + +main(); diff --git a/test/message/async_error_sync_esm.out b/test/message/async_error_sync_esm.out new file mode 100644 index 00000000000000..99ce9ed0b21c2f --- /dev/null +++ b/test/message/async_error_sync_esm.out @@ -0,0 +1,7 @@ +(node:*) ExperimentalWarning: The ESM module loader is experimental. +Error: test + at one (*fixtures*async-error.js:4:9) + at two (*fixtures*async-error.js:17:9) + at async three (*fixtures*async-error.js:20:3) + at async four (*fixtures*async-error.js:24:3) + at async main (*message*async_error_sync_esm.mjs:8:5) diff --git a/test/message/async_error_sync_main.js b/test/message/async_error_sync_main.js new file mode 100644 index 00000000000000..fa33c86d2cf911 --- /dev/null +++ b/test/message/async_error_sync_main.js @@ -0,0 +1,13 @@ +'use strict'; +require('../common'); +const four = require('../fixtures/async-error'); + +async function main() { + try { + await four(); + } catch (e) { + console.error(e); + } +} + +main(); diff --git a/test/message/async_error_sync_main.out b/test/message/async_error_sync_main.out new file mode 100644 index 00000000000000..565affbaf750d9 --- /dev/null +++ b/test/message/async_error_sync_main.out @@ -0,0 +1,6 @@ +Error: test + at one (*fixtures*async-error.js:4:9) + at two (*fixtures*async-error.js:17:9) + at async three (*fixtures*async-error.js:20:3) + at async four (*fixtures*async-error.js:24:3) + at async main (*message*async_error_sync_main.js:7:5) diff --git a/test/message/events_unhandled_error_nexttick.out b/test/message/events_unhandled_error_nexttick.out index ddb13807eea5b5..f592d91b52c099 100644 --- a/test/message/events_unhandled_error_nexttick.out +++ b/test/message/events_unhandled_error_nexttick.out @@ -13,6 +13,3 @@ Error Emitted 'error' event at: at *events_unhandled_error_nexttick.js:*:* at processTicksAndRejections (internal/process/task_queues.js:*:*) - at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*) - at Function.Module.runMain (internal/modules/cjs/loader.js:*:*) - at internal/main/run_main_module.js:*:* diff --git a/test/message/nexttick_throw.out b/test/message/nexttick_throw.out index f180c4ab55a7c0..d0a45b3cec0f2b 100644 --- a/test/message/nexttick_throw.out +++ b/test/message/nexttick_throw.out @@ -5,6 +5,3 @@ ReferenceError: undefined_reference_error_maker is not defined at *test*message*nexttick_throw.js:*:* at processTicksAndRejections (internal/process/task_queues.js:*:*) - at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*) - at Function.Module.runMain (internal/modules/cjs/loader.js:*:*) - at internal/main/run_main_module.js:*:* diff --git a/test/message/unhandled_promise_trace_warnings.out b/test/message/unhandled_promise_trace_warnings.out index 13778fb798aa6c..c9fff40efb72bd 100644 --- a/test/message/unhandled_promise_trace_warnings.out +++ b/test/message/unhandled_promise_trace_warnings.out @@ -9,9 +9,6 @@ at * at * at * - at * - at * - at * (node:*) Error: This was rejected at * (*test*message*unhandled_promise_trace_warnings.js:*) at * @@ -25,9 +22,6 @@ at * at * at * - at * - at * - at * (node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1) at handledRejection (internal/process/promises.js:*) at promiseRejectHandler (internal/process/promises.js:*) From 3def28d083125a007d4201779d5f2983ada5fdc6 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Thu, 25 Apr 2019 03:25:05 +0800 Subject: [PATCH 2/3] fixup! process: reduce the number of internal frames in async stack trace --- test/message/async_error_sync_esm.mjs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/message/async_error_sync_esm.mjs b/test/message/async_error_sync_esm.mjs index f437db87b0552c..86a901a1225572 100644 --- a/test/message/async_error_sync_esm.mjs +++ b/test/message/async_error_sync_esm.mjs @@ -1,6 +1,6 @@ // Flags: --experimental-modules /* eslint-disable node-core/required-modules */ -// import '../common/index.mjs'; +import '../common/index.mjs'; import four from '../fixtures/async-error.js'; async function main() { From c354c2cea5123dfac05c65276f24f9cf17e00167 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Thu, 25 Apr 2019 15:25:37 +0800 Subject: [PATCH 3/3] fixup! fixup! process: reduce the number of internal frames in async stack trace --- test/message/async_error_eval_cjs.js | 11 +++++++---- test/message/async_error_eval_cjs.out | 10 +++++----- 2 files changed, 12 insertions(+), 9 deletions(-) diff --git a/test/message/async_error_eval_cjs.js b/test/message/async_error_eval_cjs.js index 4cb15032d98108..a2caaa0937745e 100644 --- a/test/message/async_error_eval_cjs.js +++ b/test/message/async_error_eval_cjs.js @@ -1,13 +1,16 @@ 'use strict'; require('../common'); -const fixtures = require('../common/fixtures'); -const errorModule = fixtures.path('async-error.js'); const { spawnSync } = require('child_process'); -const main = `'use strict'; +const four = require('../common/fixtures') + .readSync('async-error.js') + .toString() + .split('\n') + .slice(2, -2) + .join('\n'); -const four = require('${errorModule}'); +const main = `${four} async function main() { try { diff --git a/test/message/async_error_eval_cjs.out b/test/message/async_error_eval_cjs.out index 8b27f345b0a4ff..a8d89eebcb6ada 100644 --- a/test/message/async_error_eval_cjs.out +++ b/test/message/async_error_eval_cjs.out @@ -1,6 +1,6 @@ Error: test - at one (*fixtures*async-error.js:4:9) - at two (*fixtures*async-error.js:17:9) - at async three (*fixtures*async-error.js:20:3) - at async four (*fixtures*async-error.js:24:3) - at async main ([eval]:7:5) + at one ([eval]:2:9) + at two ([eval]:15:9) + at async three ([eval]:18:3) + at async four ([eval]:22:3) + at async main ([eval]:28:5) \ No newline at end of file