Skip to content

Commit

Permalink
process: reduce the number of internal frames in async stack trace
Browse files Browse the repository at this point in the history
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.

PR-URL: #27392
Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
Reviewed-By: Gus Caplan <me@gus.host>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
  • Loading branch information
joyeecheung committed Apr 28, 2019
1 parent c5817ab commit 757f3f8
Show file tree
Hide file tree
Showing 22 changed files with 233 additions and 23 deletions.
4 changes: 0 additions & 4 deletions lib/internal/modules/cjs/loader.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) => {
Expand Down
4 changes: 0 additions & 4 deletions lib/internal/process/execution.js
Original file line number Diff line number Diff line change
Expand Up @@ -48,8 +48,6 @@ function evalModule(source, printResult) {
print(kStderr, e);
process.exit(1);
});
// Handle any nextTicks added in the first tick of the program.
process._tickCallback();
}

function evalScript(name, body, breakFirstLine, printResult) {
Expand Down Expand Up @@ -81,8 +79,6 @@ function evalScript(name, body, breakFirstLine, printResult) {
const { kStdout, print } = require('internal/util/print');
print(kStdout, result);
}
// Handle any nextTicks added in the first tick of the program.
process._tickCallback();
}

const exceptionHandlerState = { captureFn: null };
Expand Down
1 change: 1 addition & 0 deletions lib/internal/process/task_queues.js
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
10 changes: 7 additions & 3 deletions src/node.cc
Original file line number Diff line number Diff line change
Expand Up @@ -379,9 +379,13 @@ MaybeLocal<Value> StartExecution(Environment* env, const char* main_script_id) {
->GetFunction(env->context())
.ToLocalChecked()};

MaybeLocal<Value> result =
ExecuteBootstrapper(env, main_script_id, &parameters, &arguments);
return scope.EscapeMaybe(result);
Local<Value> result;
if (!ExecuteBootstrapper(env, main_script_id, &parameters, &arguments)
.ToLocal(&result) ||
!task_queue::RunNextTicksNative(env)) {
return MaybeLocal<Value>();
}
return scope.Escape(result);
}

MaybeLocal<Value> StartMainThreadExecution(Environment* env) {
Expand Down
10 changes: 10 additions & 0 deletions src/node_process.h
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,16 @@ v8::MaybeLocal<v8::Object> CreateProcessObject(
const std::vector<std::string>& args,
const std::vector<std::string>& exec_args);
void PatchProcessObject(const v8::FunctionCallbackInfo<v8::Value>& 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_
15 changes: 15 additions & 0 deletions src/node_task_queue.cc
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
#include "node.h"
#include "node_errors.h"
#include "node_internals.h"
#include "node_process.h"
#include "v8.h"

#include <atomic>
Expand Down Expand Up @@ -38,6 +39,20 @@ static void EnqueueMicrotask(const FunctionCallbackInfo<Value>& args) {
isolate->EnqueueMicrotask(args[0].As<Function>());
}

// 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<Function> callback = env->tick_callback_function();
CHECK(!callback.IsEmpty());
return !callback->Call(env->context(), env->process_object(), 0, nullptr)
.IsEmpty();
}

static void RunMicrotasks(const FunctionCallbackInfo<Value>& args) {
args.GetIsolate()->RunMicrotasks();
}
Expand Down
27 changes: 27 additions & 0 deletions test/fixtures/async-error.js
Original file line number Diff line number Diff line change
@@ -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;
39 changes: 39 additions & 0 deletions test/message/async_error_eval_cjs.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,39 @@
'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 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());
}
6 changes: 6 additions & 0 deletions test/message/async_error_eval_cjs.out
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
Error: test
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)
42 changes: 42 additions & 0 deletions test/message/async_error_eval_esm.js
Original file line number Diff line number Diff line change
@@ -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());
}
7 changes: 7 additions & 0 deletions test/message/async_error_eval_esm.out
Original file line number Diff line number Diff line change
@@ -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)
13 changes: 13 additions & 0 deletions test/message/async_error_microtask_main.js
Original file line number Diff line number Diff line change
@@ -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);
6 changes: 6 additions & 0 deletions test/message/async_error_microtask_main.out
Original file line number Diff line number Diff line change
@@ -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)
13 changes: 13 additions & 0 deletions test/message/async_error_nexttick_main.js
Original file line number Diff line number Diff line change
@@ -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);
7 changes: 7 additions & 0 deletions test/message/async_error_nexttick_main.out
Original file line number Diff line number Diff line change
@@ -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)
14 changes: 14 additions & 0 deletions test/message/async_error_sync_esm.mjs
Original file line number Diff line number Diff line change
@@ -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();
7 changes: 7 additions & 0 deletions test/message/async_error_sync_esm.out
Original file line number Diff line number Diff line change
@@ -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)
13 changes: 13 additions & 0 deletions test/message/async_error_sync_main.js
Original file line number Diff line number Diff line change
@@ -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();
6 changes: 6 additions & 0 deletions test/message/async_error_sync_main.out
Original file line number Diff line number Diff line change
@@ -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)
3 changes: 0 additions & 3 deletions test/message/events_unhandled_error_nexttick.out
Original file line number Diff line number Diff line change
Expand Up @@ -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:*:*
3 changes: 0 additions & 3 deletions test/message/nexttick_throw.out
Original file line number Diff line number Diff line change
Expand Up @@ -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:*:*
6 changes: 0 additions & 6 deletions test/message/unhandled_promise_trace_warnings.out
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,6 @@
at *
at *
at *
at *
at *
at *
(node:*) Error: This was rejected
at * (*test*message*unhandled_promise_trace_warnings.js:*)
at *
Expand All @@ -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:*)
Expand Down

0 comments on commit 757f3f8

Please sign in to comment.