src: fix --process-timeout message when exit waits

src/node_watchdog.cc

@@ -113,6 +113,10 @@ namespace {
 constexpr uint64_t kNanosecondsPerMillisecond = 1000 * 1000;
 // How long printing the diagnostics, writing the report and exiting may take.
 constexpr uint64_t kProcessTimeoutExitGraceMs = 5000;
+// Printed when the process is still exiting, e.g. joining Worker threads, once
+// --process-timeout has expired.
+constexpr char kProcessNotFinishedExitingMessage[] =
+    "The process did not finish exiting after the event loop had stopped.\n";
 
 std::string FormatProcessTimeoutHeader(const std::string& duration) {
   return SPrintF("(node:%d) Process timed out after %s (--process-timeout). "
@@ -460,6 +464,15 @@ void ProcessTimeoutWatchdog::Run(void* arg) {
   uv_mutex_lock(&state->mutex);
   state->WaitWhile(Phase::kArmed, state->deadline);
 
+  // Environment::Exit(), e.g. from process.exit() or for an uncaught
+  // exception, exits without returning to NodeMainInstance::Run(), so
+  // OnEnvironmentStopping() is not called while it joins Worker threads. The
+  // Environment is only freed after OnEnvironmentStopping(), so it is safe to
+  // read while the phase is still kArmed.
+  if (state->phase == Phase::kArmed && self->env_->is_stopping()) {
+    state->phase = Phase::kStopping;
+  }
+
   if (state->phase == Phase::kArmed) {
     // Barring the race described below, the process exits once the timeout
     // has fired, either through ForceProcessTimeoutExit() on this thread or
@@ -479,13 +492,18 @@ void ProcessTimeoutWatchdog::Run(void* arg) {
                      uv_hrtime() + kProcessTimeoutResponseGraceMs *
                                        kNanosecondsPerMillisecond);
     if (state->phase == Phase::kFired) {
+      // If Environment::Exit() started before the interrupt could run, the
+      // main thread is not blocked by the application but by exiting.
       ForceProcessTimeoutExit(
           FormatProcessTimeoutHeader(state->duration) +
-          SPrintF("The main thread did not respond within %dms. It is likely "
-                  "blocked in a synchronous native operation, e.g. "
-                  "child_process.execSync() or a native addon, so no "
-                  "JavaScript stack or resource information is available.\n",
-                  kProcessTimeoutResponseGraceMs));
+          (self->env_->is_stopping()
+               ? std::string(kProcessNotFinishedExitingMessage)
+               : SPrintF("The main thread did not respond within %dms. It is "
+                         "likely blocked in a synchronous native operation, "
+                         "e.g. child_process.execSync() or a native addon, so "
+                         "no JavaScript stack or resource information is "
+                         "available.\n",
+                         kProcessTimeoutResponseGraceMs)));
     }
 
     if (state->phase == Phase::kHandling) {
@@ -507,8 +525,8 @@ void ProcessTimeoutWatchdog::Run(void* arg) {
     // The event loop has stopped, but tearing down the Environment, e.g.
     // joining Worker threads, can still take arbitrarily long. If the deadline
     // has already passed, give the process a moment to finish exiting. That
-    // only happens if the event loop stopped right as the deadline was reached,
-    // a race that tests cannot reproduce reliably.
+    // happens if Environment::Exit() was still in progress at the deadline, or
+    // if the event loop stopped right as the deadline was reached.
     const uint64_t now = uv_hrtime();
     // LCOV_EXCL_START
     const uint64_t until =
@@ -520,8 +538,7 @@ void ProcessTimeoutWatchdog::Run(void* arg) {
     if (state->phase == Phase::kStopping) {
       // LCOV_EXCL_START
       ForceProcessTimeoutExit(FormatProcessTimeoutHeader(state->duration) +
-                              "The process did not finish exiting after the "
-                              "event loop had stopped.\n");
+                              kProcessNotFinishedExitingMessage);
       // LCOV_EXCL_STOP
     }
   }

test/fixtures/process-timeout/blocked-worker-at-process-exit.js

@@ -0,0 +1,31 @@
+'use strict';
+// Exits the process while a Worker is blocked in a synchronous native call, so
+// that exiting the process waits for the Worker. The first argument is a path
+// at which a file is created once the process is exiting. The second argument
+// is how the process exits: 'exit' calls process.exit(), 'throw' throws an
+// uncaught exception, and 'reject' leaves a promise rejection unhandled.
+const fs = require('fs');
+const path = require('path');
+const { Worker } = require('worker_threads');
+
+const [, , marker, mode] = process.argv;
+const childMarker = `${marker}.child`;
+const script = path.join(__dirname, 'wait-for-parent.js');
+const args = [script, String(process.pid), childMarker];
+new Worker(`
+  require('child_process').execFileSync(process.execPath, ${JSON.stringify(args)}, {
+    stdio: 'ignore',
+  });
+`, { eval: true });
+
+// Once the child process has created its file, the Worker is blocked in
+// execFileSync() and can no longer be terminated.
+const interval = setInterval(() => {
+  if (!fs.existsSync(childMarker)) return;
+  clearInterval(interval);
+  if (mode === 'throw') throw new Error('boom');
+  if (mode === 'reject') return Promise.reject(new Error('boom'));
+  process.exit(0);
+}, 10);
+
+process.on('exit', () => fs.writeFileSync(marker, ''));

test/parallel/test-process-timeout-blocked.js

@@ -16,16 +16,17 @@ tmpdir.refresh();
 // it can expire before the fixture has reached the state under test, which the
 // fixture signals by creating a file. If it did not get that far and did not
 // print the expected message, run it again with a longer timeout.
-function runUntilReady(fixture, expected) {
+function runUntilReady(fixture, expected, args = []) {
   for (let timeout = common.platformTimeout(1000); ; timeout *= 2) {
     // Child processes of a previous attempt may still be running, so use a
     // different file for each attempt.
-    const marker = tmpdir.resolve(`${fixture}.${timeout}.ready`);
+    const marker = tmpdir.resolve([fixture, ...args, timeout, 'ready'].join('.'));
     const start = process.hrtime.bigint();
     const child = spawnSync(process.execPath, [
       `--process-timeout=${timeout}ms`,
       fixtures.path('process-timeout', fixture),
       marker,
+      ...args,
     ], { encoding: 'utf8' });
     const elapsed = Number(process.hrtime.bigint() - start) / 1e6;
 
@@ -69,3 +70,14 @@ function runUntilReady(fixture, expected) {
     'blocked-worker-at-exit.js',
     /^The process did not finish exiting after the event loop had stopped\.$/m);
 }
+
+for (const mode of ['exit', 'throw', 'reject']) {
+  // process.exit(), an uncaught exception, or an unhandled rejection waits for
+  // a Worker thread that is blocked in a synchronous native call. The main thread is exiting, so it
+  // must not be reported as blocked by the application.
+  const stderr = runUntilReady(
+    'blocked-worker-at-process-exit.js',
+    /^The process did not finish exiting after the event loop had stopped\.$/m,
+    [mode]);
+  assert.doesNotMatch(stderr, /The main thread did not respond/);
+}