[v18.x backport] test_runner: avoid swallowing of asynchronously thrown errors

doc/api/test.md

@@ -272,8 +272,8 @@ top level of the file's TAP output.
 
 The second `setImmediate()` creates an `uncaughtException` event.
 `uncaughtException` and `unhandledRejection` events originating from a completed
-test are handled by the `test` module and reported as diagnostic warnings in
-the top level of the file's TAP output.
+test are marked as failed by the `test` module and reported as diagnostic
+warnings in the top level of the file's TAP output.
 
 ```js
 test('a test that creates asynchronous activity', (t) => {

lib/internal/perf/event_loop_utilization.js

@@ -1,13 +1,26 @@
 'use strict';
 
-const nodeTiming = require('internal/perf/nodetiming');
-
-const { now } = require('internal/perf/utils');
+const {
+  constants: {
+    NODE_PERFORMANCE_MILESTONE_LOOP_START,
+  },
+  loopIdleTime,
+  milestones,
+} = internalBinding('performance');
 
 function eventLoopUtilization(util1, util2) {
-  const ls = nodeTiming.loopStart;
+  // Get the original milestone timestamps that calculated from the beginning
+  // of the process.
+  return internalEventLoopUtilization(
+    milestones[NODE_PERFORMANCE_MILESTONE_LOOP_START] / 1e6,
+    loopIdleTime(),
+    util1,
+    util2
+  );
+}
 
-  if (ls <= 0) {
+function internalEventLoopUtilization(loopStart, loopIdleTime, util1, util2) {
+  if (loopStart <= 0) {
     return { idle: 0, active: 0, utilization: 0 };
   }
 
@@ -17,17 +30,31 @@ function eventLoopUtilization(util1, util2) {
     return { idle, active, utilization: active / (idle + active) };
   }
 
-  const idle = nodeTiming.idleTime;
-  const active = now() - ls - idle;
+  // Using process.hrtime() to get the time from the beginning of the process,
+  // and offset it by the loopStart time (which is also calculated from the
+  // beginning of the process).
+  const now = process.hrtime();
+  const active = now[0] * 1e3 + now[1] / 1e6 - loopStart - loopIdleTime;
 
   if (!util1) {
-    return { idle, active, utilization: active / (idle + active) };
+    return {
+      idle: loopIdleTime,
+      active,
+      utilization: active / (loopIdleTime + active),
+    };
   }
 
-  const idle_delta = idle - util1.idle;
-  const active_delta = active - util1.active;
-  const utilization = active_delta / (idle_delta + active_delta);
-  return { idle: idle_delta, active: active_delta, utilization };
+  const idleDelta = loopIdleTime - util1.idle;
+  const activeDelta = active - util1.active;
+  const utilization = activeDelta / (idleDelta + activeDelta);
+  return {
+    idle: idleDelta,
+    active: activeDelta,
+    utilization,
+  };
 }
 
-module.exports = eventLoopUtilization;
+module.exports = {
+  internalEventLoopUtilization,
+  eventLoopUtilization,
+};

lib/internal/perf/performance.js

@@ -35,7 +35,7 @@ const {
   setDispatchBufferFull,
 } = require('internal/perf/observe');
 
-const eventLoopUtilization = require('internal/perf/event_loop_utilization');
+const { eventLoopUtilization } = require('internal/perf/event_loop_utilization');
 const nodeTiming = require('internal/perf/nodetiming');
 const timerify = require('internal/perf/timerify');
 const { customInspectSymbol: kInspect } = require('internal/util');

lib/internal/test_runner/harness.js

@@ -44,6 +44,7 @@ function createProcessEventHandler(eventName, rootTest) {
         `triggered an ${eventName} event.`;
 
       rootTest.diagnostic(msg);
+      process.exitCode = 1;
       return;
     }
 

lib/internal/worker.js

@@ -27,7 +27,9 @@ const {
 const EventEmitter = require('events');
 const assert = require('internal/assert');
 const path = require('path');
-const { now } = require('internal/perf/utils');
+const {
+  internalEventLoopUtilization
+} = require('internal/perf/event_loop_utilization');
 
 const errorCodes = require('internal/errors').codes;
 const {
@@ -472,28 +474,12 @@ function eventLoopUtilization(util1, util2) {
       return { idle: 0, active: 0, utilization: 0 };
   }
 
-  if (util2) {
-    const idle = util1.idle - util2.idle;
-    const active = util1.active - util2.active;
-    return { idle, active, utilization: active / (idle + active) };
-  }
-
-  const idle = this[kHandle].loopIdleTime();
-
-  // Using performance.now() here is fine since it's always the time from
-  // the beginning of the process, and is why it needs to be offset by the
-  // loopStart time (which is also calculated from the beginning of the
-  // process).
-  const active = now() - this[kLoopStartTime] - idle;
-
-  if (!util1) {
-    return { idle, active, utilization: active / (idle + active) };
-  }
-
-  const idle_delta = idle - util1.idle;
-  const active_delta = active - util1.active;
-  const utilization = active_delta / (idle_delta + active_delta);
-  return { idle: idle_delta, active: active_delta, utilization };
+  return internalEventLoopUtilization(
+    this[kLoopStartTime],
+    this[kHandle].loopIdleTime(),
+    util1,
+    util2
+  );
 }
 
 module.exports = {

src/env.cc

@@ -662,7 +662,8 @@ Environment::Environment(IsolateData* isolate_data,
       stream_base_state_(isolate_,
                          StreamBase::kNumStreamBaseStateFields,
                          MAYBE_FIELD_PTR(env_info, stream_base_state)),
-      environment_start_time_(PERFORMANCE_NOW()),
+      time_origin_(PERFORMANCE_NOW()),
+      time_origin_timestamp_(GetCurrentTimeInMicroseconds()),
       flags_(flags),
       thread_id_(thread_id.id == static_cast<uint64_t>(-1)
                      ? AllocateEnvironmentThreadId().id
@@ -767,7 +768,7 @@ void Environment::InitializeMainContext(Local<Context> context,
   set_exiting(false);
 
   performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT,
-                           environment_start_time_);
+                           time_origin_);
   performance_state_->Mark(performance::NODE_PERFORMANCE_MILESTONE_NODE_START,
                            per_process::node_start_time);
 

src/env.h

@@ -855,6 +855,13 @@ class Environment : public MemoryRetainer {
   inline HandleWrapQueue* handle_wrap_queue() { return &handle_wrap_queue_; }
   inline ReqWrapQueue* req_wrap_queue() { return &req_wrap_queue_; }
 
+  inline uint64_t time_origin() {
+    return time_origin_;
+  }
+  inline double time_origin_timestamp() {
+    return time_origin_timestamp_;
+  }
+
   inline bool EmitProcessEnvWarning() {
     bool current_value = emit_env_nonstring_warning_;
     emit_env_nonstring_warning_ = false;
@@ -1045,7 +1052,10 @@ class Environment : public MemoryRetainer {
 
   AliasedInt32Array stream_base_state_;
 
-  uint64_t environment_start_time_;
+  // https://w3c.github.io/hr-time/#dfn-time-origin
+  uint64_t time_origin_;
+  // https://w3c.github.io/hr-time/#dfn-get-time-origin-timestamp
+  double time_origin_timestamp_;
   std::unique_ptr<performance::PerformanceState> performance_state_;
 
   bool has_serialized_options_ = false;

src/node_http2.cc

@@ -644,7 +644,7 @@ void Http2Stream::EmitStatistics() {
   std::unique_ptr<Http2StreamPerformanceEntry> entry =
       std::make_unique<Http2StreamPerformanceEntry>(
           "Http2Stream",
-          start - (node::performance::timeOrigin / 1e6),
+          start - (env()->time_origin() / 1e6),
           duration,
           statistics_);
 
@@ -664,7 +664,7 @@ void Http2Session::EmitStatistics() {
   std::unique_ptr<Http2SessionPerformanceEntry> entry =
       std::make_unique<Http2SessionPerformanceEntry>(
           "Http2Session",
-          start - (node::performance::timeOrigin / 1e6),
+          start - (env()->time_origin() / 1e6),
           duration,
           statistics_);
 

src/node_perf.cc

@@ -35,11 +35,9 @@ using v8::Value;
 
 // Microseconds in a millisecond, as a float.
 #define MICROS_PER_MILLIS 1e3
+// Nanoseconds in a millisecond, as a float.
+#define NANOS_PER_MILLIS 1e6
 
-// https://w3c.github.io/hr-time/#dfn-time-origin
-const uint64_t timeOrigin = PERFORMANCE_NOW();
-// https://w3c.github.io/hr-time/#dfn-time-origin-timestamp
-const double timeOriginTimestamp = GetCurrentTimeInMicroseconds();
 uint64_t performance_v8_start;
 
 PerformanceState::PerformanceState(Isolate* isolate,
@@ -170,9 +168,10 @@ void MarkGarbageCollectionEnd(
     return;
 
   double start_time =
-      (state->performance_last_gc_start_mark - timeOrigin) / 1e6;
-  double duration =
-      (PERFORMANCE_NOW() / 1e6) - (state->performance_last_gc_start_mark / 1e6);
+      (state->performance_last_gc_start_mark - env->time_origin()) /
+      NANOS_PER_MILLIS;
+  double duration = (PERFORMANCE_NOW() / NANOS_PER_MILLIS) -
+                    (state->performance_last_gc_start_mark / NANOS_PER_MILLIS);
 
   std::unique_ptr<GCPerformanceEntry> entry =
       std::make_unique<GCPerformanceEntry>(
@@ -270,12 +269,15 @@ void CreateELDHistogram(const FunctionCallbackInfo<Value>& args) {
 }
 
 void GetTimeOrigin(const FunctionCallbackInfo<Value>& args) {
-  args.GetReturnValue().Set(Number::New(args.GetIsolate(), timeOrigin / 1e6));
+  Environment* env = Environment::GetCurrent(args);
+  args.GetReturnValue().Set(
+      Number::New(args.GetIsolate(), env->time_origin() / 1e6));
 }
 
 void GetTimeOriginTimeStamp(const FunctionCallbackInfo<Value>& args) {
-  args.GetReturnValue().Set(
-      Number::New(args.GetIsolate(), timeOriginTimestamp / MICROS_PER_MILLIS));
+  Environment* env = Environment::GetCurrent(args);
+  args.GetReturnValue().Set(Number::New(
+      args.GetIsolate(), env->time_origin_timestamp() / MICROS_PER_MILLIS));
 }
 
 void MarkBootstrapComplete(const FunctionCallbackInfo<Value>& args) {

src/node_perf.h

@@ -21,8 +21,6 @@ class ExternalReferenceRegistry;
 
 namespace performance {
 
-extern const uint64_t timeOrigin;
-
 inline const char* GetPerformanceMilestoneName(
     PerformanceMilestone milestone) {
   switch (milestone) {

src/node_worker.cc

@@ -845,8 +845,7 @@ void Worker::LoopStartTime(const FunctionCallbackInfo<Value>& args) {
   double loop_start_time = w->env_->performance_state()->milestones[
       node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_START];
   CHECK_GE(loop_start_time, 0);
-  args.GetReturnValue().Set(
-      (loop_start_time - node::performance::timeOrigin) / 1e6);
+  args.GetReturnValue().Set(loop_start_time / 1e6);
 }
 
 namespace {

test/es-module/test-esm-repl-imports.js

@@ -9,7 +9,7 @@ const { describe, it } = require('node:test');
 
 
 describe('ESM: REPL runs', { concurrency: true }, () => {
-  it((context, done) => {
+  it((done) => {
     const child = spawn(execPath, [
       '--interactive',
     ], {

test/fixtures/test-runner/extraneous_set_immediate_async.mjs

@@ -0,0 +1,5 @@
+import test from 'node:test';
+
+test('extraneous async activity test', () => {
+  setImmediate(() => { throw new Error(); });
+});

test/fixtures/test-runner/extraneous_set_timeout_async.mjs

@@ -0,0 +1,5 @@
+import test from 'node:test';
+
+test('extraneous async activity test', () => {
+  setTimeout(() => { throw new Error(); }, 100);
+});

test/parallel/test-perf-hooks-worker-timeorigin.js

@@ -0,0 +1,20 @@
+'use strict';
+
+const common = require('../common');
+const assert = require('assert');
+const { Worker } = require('worker_threads');
+
+const w = new Worker(`
+require('worker_threads').parentPort.postMessage(performance.timeOrigin);
+`, { eval: true });
+
+w.on('message', common.mustCall((timeOrigin) => {
+  // Worker is created after this main context, it's
+  // `performance.timeOrigin` must be greater than this
+  // main context's.
+  assert.ok(timeOrigin > performance.timeOrigin);
+}));
+
+w.on('exit', common.mustCall((code) => {
+  assert.strictEqual(code, 0);
+}));

test/parallel/test-runner-extraneous-async-activity.js

@@ -0,0 +1,31 @@
+'use strict';
+require('../common');
+const fixtures = require('../common/fixtures');
+const assert = require('assert');
+const { spawnSync } = require('child_process');
+
+{
+  const child = spawnSync(process.execPath, [
+    '--test',
+    fixtures.path('test-runner', 'extraneous_set_immediate_async.mjs'),
+  ]);
+  const stdout = child.stdout.toString();
+  assert.match(stdout, /^# pass 0$/m);
+  assert.match(stdout, /^# fail 1$/m);
+  assert.match(stdout, /^# cancelled 0$/m);
+  assert.strictEqual(child.status, 1);
+  assert.strictEqual(child.signal, null);
+}
+
+{
+  const child = spawnSync(process.execPath, [
+    '--test',
+    fixtures.path('test-runner', 'extraneous_set_timeout_async.mjs'),
+  ]);
+  const stdout = child.stdout.toString();
+  assert.match(stdout, /^# pass 0$/m);
+  assert.match(stdout, /^# fail 1$/m);
+  assert.match(stdout, /^# cancelled 0$/m);
+  assert.strictEqual(child.status, 1);
+  assert.strictEqual(child.signal, null);
+}

test/pummel/test-heapdump-env.js

@@ -38,4 +38,10 @@ validateSnapshotNodes('Node / Realm', [{
   ]
 }]);
 
+validateSnapshotNodes('Node / Realm', [{
+  children: [
+    { node_name: 'process', edge_name: 'process_object' },
+  ]
+}]);
+
 console.log(context);  // Make sure it's not GC'ed