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.

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>

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) => {

lib/internal/process/execution.js

@@ -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) {
@@ -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 };

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();

src/node.cc

@@ -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) {

src/node_process.h

@@ -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_

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 <atomic>
@@ -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();
 }

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;

test/message/async_error_eval_cjs.js

@@ -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());
+}

test/message/async_error_eval_cjs.out

@@ -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)

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());
+}

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)

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);

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)

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);

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)

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();

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)

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();

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)

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:*:*

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:*:*

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:*)