report: skip unresponsive workers on process timeout

doc/api/cli.md

@@ -2840,6 +2840,10 @@ addition to the summary printed to stderr. Useful to inspect the JavaScript
 and native stacks, the event loop state, and resource consumption to reason
 about why the process did not exit. Requires [`--process-timeout`][].
 
+Worker threads that do not provide their part of the report within two
+seconds, for example because they are blocked in a synchronous operation such
+as [`child_process.execSync()`][], are left out of it.
+
 ### `--report-on-signal`
 
 <!-- YAML

doc/node.1

@@ -1439,6 +1439,9 @@ Enables the report to be generated when \fB--process-timeout\fR expires, in
 addition to the summary printed to stderr. Useful to inspect the JavaScript
 and native stacks, the event loop state, and resource consumption to reason
 about why the process did not exit. Requires \fB--process-timeout\fR.
+Worker threads that do not provide their part of the report within two
+seconds, for example because they are blocked in a synchronous operation such
+as \fBchild_process.execSync()\fR, are left out of it.
 .
 .It Fl -report-on-signal
 Enables report to be generated upon receiving the specified (or predefined)

src/node_mutex.h

@@ -139,6 +139,8 @@ class ConditionVariableBase {
   inline void Broadcast(const ScopedLock&);
   inline void Signal(const ScopedLock&);
   inline void Wait(const ScopedLock& scoped_lock);
+  // Returns 0 if signaled, or UV_ETIMEDOUT once `timeout_ns` has elapsed.
+  inline int TimedWait(const ScopedLock& scoped_lock, uint64_t timeout_ns);
 
   ConditionVariableBase(const ConditionVariableBase&) = delete;
   ConditionVariableBase& operator=(const ConditionVariableBase&) = delete;
@@ -175,6 +177,12 @@ struct LibuvMutexTraits {
     uv_cond_wait(cond, mutex);
   }
 
+  static inline int cond_timedwait(CondT* cond,
+                                   MutexT* mutex,
+                                   uint64_t timeout_ns) {
+    return uv_cond_timedwait(cond, mutex, timeout_ns);
+  }
+
   static inline void mutex_destroy(MutexT* mutex) {
     uv_mutex_destroy(mutex);
   }
@@ -249,6 +257,12 @@ void ConditionVariableBase<Traits>::Wait(const ScopedLock& scoped_lock) {
   Traits::cond_wait(&cond_, &scoped_lock.mutex_.mutex_);
 }
 
+template <typename Traits>
+int ConditionVariableBase<Traits>::TimedWait(const ScopedLock& scoped_lock,
+                                             uint64_t timeout_ns) {
+  return Traits::cond_timedwait(&cond_, &scoped_lock.mutex_.mutex_, timeout_ns);
+}
+
 template <typename Traits>
 MutexBase<Traits>::MutexBase() {
   CHECK_EQ(0, Traits::mutex_init(&mutex_));

src/node_report.cc

@@ -6,6 +6,7 @@
 #include "node_internals.h"
 #include "node_metadata.h"
 #include "node_mutex.h"
+#include "node_watchdog.h"
 #include "node_worker.h"
 #include "permission/permission.h"
 #include "util.h"
@@ -227,29 +228,49 @@ static void WriteNodeReport(Isolate* isolate,
 
   writer.json_arraystart("workers");
   if (env != nullptr) {
-    Mutex workers_mutex;
-    ConditionVariable notify;
-    std::vector<std::string> worker_infos;
+    // Shared with the callbacks, which can outlive this function if a Worker
+    // thread does not respond in time.
+    struct WorkerInfos {
+      Mutex mutex;
+      ConditionVariable notify;
+      std::vector<std::string> infos;
+    };
+    auto shared = std::make_shared<WorkerInfos>();
     size_t expected_results = 0;
 
     env->ForEachWorker([&](Worker* w) {
-      expected_results += w->RequestInterrupt([&, w = w](Environment* env) {
-        std::ostringstream os;
-        std::string name =
-            "Worker thread subreport [" + std::string(w->name()) + "]";
-        GetNodeReport(env, name, trigger, Local<Value>(), os);
-
-        Mutex::ScopedLock lock(workers_mutex);
-        worker_infos.emplace_back(os.str());
-        notify.Signal(lock);
-      });
+      expected_results += w->RequestInterrupt(
+          [shared, w, trigger = std::string(trigger)](Environment* env) {
+            std::ostringstream os;
+            std::string name =
+                "Worker thread subreport [" + std::string(w->name()) + "]";
+            GetNodeReport(env, name, trigger, Local<Value>(), os);
+
+            Mutex::ScopedLock lock(shared->mutex);
+            shared->infos.emplace_back(os.str());
+            shared->notify.Signal(lock);
+          });
     });
 
-    Mutex::ScopedLock lock(workers_mutex);
-    worker_infos.reserve(expected_results);
-    while (worker_infos.size() < expected_results)
-      notify.Wait(lock);
-    for (const std::string& worker_info : worker_infos)
+    // --process-timeout forces the process to exit shortly after it triggers
+    // the report, so do not wait for Worker threads that are blocked, e.g. in
+    // a synchronous native call. They are left out of the report.
+    const bool wait_forever = trigger != kProcessTimeoutReportTrigger;
+    const uint64_t deadline =
+        uv_hrtime() + kProcessTimeoutResponseGraceMs * 1000 * 1000;
+    Mutex::ScopedLock lock(shared->mutex);
+    shared->infos.reserve(expected_results);
+    while (shared->infos.size() < expected_results) {
+      const uint64_t now = uv_hrtime();
+      if (wait_forever) {
+        shared->notify.Wait(lock);
+      } else if (now < deadline) {
+        shared->notify.TimedWait(lock, deadline - now);
+      } else {
+        break;
+      }
+    }
+    for (const std::string& worker_info : shared->infos)
       writer.json_element(JSONWriter::ForeignJSON { worker_info });
   }
   writer.json_arrayend();

src/node_watchdog.cc

@@ -111,9 +111,6 @@ void Watchdog::Timer(uv_timer_t* timer) {
 namespace {
 
 constexpr uint64_t kNanosecondsPerMillisecond = 1000 * 1000;
-// How long the main thread has to respond to the timeout. If it does not, it
-// is most likely blocked in a synchronous native call.
-constexpr uint64_t kProcessTimeoutResponseGraceMs = 2000;
 // How long printing the diagnostics, writing the report and exiting may take.
 constexpr uint64_t kProcessTimeoutExitGraceMs = 5000;
 
@@ -557,7 +554,7 @@ void ProcessTimeoutWatchdog::OnTimeout(Environment* env,
     if (state->report) {
       TriggerNodeReport(env,
                         "Process timed out (--process-timeout)",
-                        "ProcessTimeout",
+                        kProcessTimeoutReportTrigger,
                         "",
                         Local<Value>());
     }

src/node_watchdog.h

@@ -25,6 +25,7 @@
 #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
 
 #include <memory>
+#include <string_view>
 #include <vector>
 #include "handle_wrap.h"
 #include "memory_tracker-inl.h"
@@ -68,6 +69,13 @@ class Watchdog {
   bool* timed_out_;
 };
 
+// How long the main thread has to respond to --process-timeout, and Worker
+// threads to provide their part of the report. A thread that does not respond
+// is most likely blocked in a synchronous native call.
+constexpr uint64_t kProcessTimeoutResponseGraceMs = 2000;
+// The trigger of the report written by --report-on-process-timeout.
+constexpr std::string_view kProcessTimeoutReportTrigger = "ProcessTimeout";
+
 // Implements --process-timeout.
 //
 // A dedicated thread waits until the configured duration has elapsed since the

test/report/test-report-process-timeout.js

@@ -6,6 +6,7 @@ const common = require('../common');
 const assert = require('assert');
 const fs = require('fs');
 const { spawnSync } = require('child_process');
+const fixtures = require('../common/fixtures');
 const helper = require('../common/report');
 const tmpdir = require('../common/tmpdir');
 
@@ -45,3 +46,49 @@ helper.validate(reports[0], [
 
 const report = JSON.parse(fs.readFileSync(reports[0], 'utf8'));
 assert.match(report.javascriptStack.stack[0], /^at spin \(\[eval\]:1:\d+\)$/);
+
+{
+  // A Worker thread that is blocked in a synchronous native call cannot
+  // provide its part of the report. It is left out, so that the report is
+  // completed before the process is forced to exit.
+  // If the Worker thread was not blocked yet when the deadline expired, which
+  // the fixture signals by creating a file, it is included in the report. Run
+  // the fixture again with a longer timeout in that case.
+  let child;
+  let report;
+  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(`blocked-worker.${timeout}.ready`);
+    child = spawnSync(process.execPath, [
+      `--process-timeout=${timeout}ms`,
+      '--report-on-process-timeout',
+      fixtures.path('process-timeout', 'blocked-worker.js'),
+      marker,
+    ], { cwd: tmpdir.path, encoding: 'utf8' });
+
+    const reports = helper.findReports(child.pid, tmpdir.path);
+    assert.strictEqual(reports.length, 1, child.stderr);
+    helper.validate(reports[0], [
+      ['header.event', 'Process timed out (--process-timeout)'],
+      ['header.trigger', 'ProcessTimeout'],
+    ]);
+    report = JSON.parse(fs.readFileSync(reports[0], 'utf8'));
+    if ((fs.existsSync(marker) && report.workers.length === 0) ||
+        timeout >= common.platformTimeout(16000)) {
+      break;
+    }
+  }
+
+  assert.strictEqual(child.signal, null);
+  assert.strictEqual(child.status, 124, child.stderr);
+  assert.match(child.stderr, /^ {4}Worker \(thread 1, name 'blocked'\)$/m);
+  // The report is completed before the process is forced to exit, so the
+  // message about that is printed on its own line.
+  assert.match(child.stderr, new RegExp(
+    '^Writing Node\\.js report to file: report\\.\\S+\\.json\\n' +
+    'Node\\.js report completed\\n' +
+    '\\(node:\\d+\\) The process did not finish exiting within 5000ms after ' +
+    '--process-timeout expired\\. Forcing exit\\.$', 'm'));
+  assert.deepStrictEqual(report.workers, []);
+}