Skip to content

Commit 75e4bbe

Browse files
authored
report: skip unresponsive workers on process timeout
When --process-timeout expires, --report-on-process-timeout asked every Worker for a subreport and waited without a time limit. A Worker blocked in a synchronous native call never answers, so the watchdog force-exited the process before the report was written. That left a truncated, invalid JSON file, and the forced-exit message was glued onto the "Writing Node.js report to file" line. For reports triggered by --process-timeout, wait at most two seconds for Worker subreports and leave out Worker threads that have not responded by then. The subreport state is now shared with the interrupt callbacks, so a Worker that answers late does not touch freed memory. Other report triggers are unchanged. Signed-off-by: Trivikram Kamat <16024985+trivikr@users.noreply.github.com> Assisted-by: claude:opus-5.5 PR-URL: #66304 Fixes: #66303 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Filip Skokan <panva.ip@gmail.com>
1 parent df775ec commit 75e4bbe

7 files changed

Lines changed: 116 additions & 22 deletions

File tree

‎doc/api/cli.md‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2891,6 +2891,10 @@ addition to the summary printed to stderr. Useful to inspect the JavaScript
28912891
and native stacks, the event loop state, and resource consumption to reason
28922892
about why the process did not exit. Requires [`--process-timeout`][].
28932893

2894+
Worker threads that do not provide their part of the report within two
2895+
seconds, for example because they are blocked in a synchronous operation such
2896+
as [`child_process.execSync()`][], are left out of it.
2897+
28942898
### `--report-on-signal`
28952899

28962900
<!-- YAML

‎doc/node.1‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1481,6 +1481,9 @@ Enables the report to be generated when \fB--process-timeout\fR expires, in
14811481
addition to the summary printed to stderr. Useful to inspect the JavaScript
14821482
and native stacks, the event loop state, and resource consumption to reason
14831483
about why the process did not exit. Requires \fB--process-timeout\fR.
1484+
Worker threads that do not provide their part of the report within two
1485+
seconds, for example because they are blocked in a synchronous operation such
1486+
as \fBchild_process.execSync()\fR, are left out of it.
14841487
.
14851488
.It Fl -report-on-signal
14861489
Enables report to be generated upon receiving the specified (or predefined)

‎src/node_mutex.h‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -139,6 +139,8 @@ class ConditionVariableBase {
139139
inline void Broadcast(const ScopedLock&);
140140
inline void Signal(const ScopedLock&);
141141
inline void Wait(const ScopedLock& scoped_lock);
142+
// Returns 0 if signaled, or UV_ETIMEDOUT once `timeout_ns` has elapsed.
143+
inline int TimedWait(const ScopedLock& scoped_lock, uint64_t timeout_ns);
142144

143145
ConditionVariableBase(const ConditionVariableBase&) = delete;
144146
ConditionVariableBase& operator=(const ConditionVariableBase&) = delete;
@@ -175,6 +177,12 @@ struct LibuvMutexTraits {
175177
uv_cond_wait(cond, mutex);
176178
}
177179

180+
static inline int cond_timedwait(CondT* cond,
181+
MutexT* mutex,
182+
uint64_t timeout_ns) {
183+
return uv_cond_timedwait(cond, mutex, timeout_ns);
184+
}
185+
178186
static inline void mutex_destroy(MutexT* mutex) {
179187
uv_mutex_destroy(mutex);
180188
}
@@ -249,6 +257,12 @@ void ConditionVariableBase<Traits>::Wait(const ScopedLock& scoped_lock) {
249257
Traits::cond_wait(&cond_, &scoped_lock.mutex_.mutex_);
250258
}
251259

260+
template <typename Traits>
261+
int ConditionVariableBase<Traits>::TimedWait(const ScopedLock& scoped_lock,
262+
uint64_t timeout_ns) {
263+
return Traits::cond_timedwait(&cond_, &scoped_lock.mutex_.mutex_, timeout_ns);
264+
}
265+
252266
template <typename Traits>
253267
MutexBase<Traits>::MutexBase() {
254268
CHECK_EQ(0, Traits::mutex_init(&mutex_));

‎src/node_report.cc‎

Lines changed: 39 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
#include "node_internals.h"
77
#include "node_metadata.h"
88
#include "node_mutex.h"
9+
#include "node_watchdog.h"
910
#include "node_worker.h"
1011
#include "permission/permission.h"
1112
#include "util.h"
@@ -227,29 +228,49 @@ static void WriteNodeReport(Isolate* isolate,
227228

228229
writer.json_arraystart("workers");
229230
if (env != nullptr) {
230-
Mutex workers_mutex;
231-
ConditionVariable notify;
232-
std::vector<std::string> worker_infos;
231+
// Shared with the callbacks, which can outlive this function if a Worker
232+
// thread does not respond in time.
233+
struct WorkerInfos {
234+
Mutex mutex;
235+
ConditionVariable notify;
236+
std::vector<std::string> infos;
237+
};
238+
auto shared = std::make_shared<WorkerInfos>();
233239
size_t expected_results = 0;
234240

235241
env->ForEachWorker([&](Worker* w) {
236-
expected_results += w->RequestInterrupt([&, w = w](Environment* env) {
237-
std::ostringstream os;
238-
std::string name =
239-
"Worker thread subreport [" + std::string(w->name()) + "]";
240-
GetNodeReport(env, name, trigger, Local<Value>(), os);
241-
242-
Mutex::ScopedLock lock(workers_mutex);
243-
worker_infos.emplace_back(os.str());
244-
notify.Signal(lock);
245-
});
242+
expected_results += w->RequestInterrupt(
243+
[shared, w, trigger = std::string(trigger)](Environment* env) {
244+
std::ostringstream os;
245+
std::string name =
246+
"Worker thread subreport [" + std::string(w->name()) + "]";
247+
GetNodeReport(env, name, trigger, Local<Value>(), os);
248+
249+
Mutex::ScopedLock lock(shared->mutex);
250+
shared->infos.emplace_back(os.str());
251+
shared->notify.Signal(lock);
252+
});
246253
});
247254

248-
Mutex::ScopedLock lock(workers_mutex);
249-
worker_infos.reserve(expected_results);
250-
while (worker_infos.size() < expected_results)
251-
notify.Wait(lock);
252-
for (const std::string& worker_info : worker_infos)
255+
// --process-timeout forces the process to exit shortly after it triggers
256+
// the report, so do not wait for Worker threads that are blocked, e.g. in
257+
// a synchronous native call. They are left out of the report.
258+
const bool wait_forever = trigger != kProcessTimeoutReportTrigger;
259+
const uint64_t deadline =
260+
uv_hrtime() + kProcessTimeoutResponseGraceMs * 1000 * 1000;
261+
Mutex::ScopedLock lock(shared->mutex);
262+
shared->infos.reserve(expected_results);
263+
while (shared->infos.size() < expected_results) {
264+
const uint64_t now = uv_hrtime();
265+
if (wait_forever) {
266+
shared->notify.Wait(lock);
267+
} else if (now < deadline) {
268+
shared->notify.TimedWait(lock, deadline - now);
269+
} else {
270+
break;
271+
}
272+
}
273+
for (const std::string& worker_info : shared->infos)
253274
writer.json_element(JSONWriter::ForeignJSON { worker_info });
254275
}
255276
writer.json_arrayend();

‎src/node_watchdog.cc‎

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -111,9 +111,6 @@ void Watchdog::Timer(uv_timer_t* timer) {
111111
namespace {
112112

113113
constexpr uint64_t kNanosecondsPerMillisecond = 1000 * 1000;
114-
// How long the main thread has to respond to the timeout. If it does not, it
115-
// is most likely blocked in a synchronous native call.
116-
constexpr uint64_t kProcessTimeoutResponseGraceMs = 2000;
117114
// How long printing the diagnostics, writing the report and exiting may take.
118115
constexpr uint64_t kProcessTimeoutExitGraceMs = 5000;
119116

@@ -557,7 +554,7 @@ void ProcessTimeoutWatchdog::OnTimeout(Environment* env,
557554
if (state->report) {
558555
TriggerNodeReport(env,
559556
"Process timed out (--process-timeout)",
560-
"ProcessTimeout",
557+
kProcessTimeoutReportTrigger,
561558
"",
562559
Local<Value>());
563560
}

‎src/node_watchdog.h‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
2626

2727
#include <memory>
28+
#include <string_view>
2829
#include <vector>
2930
#include "handle_wrap.h"
3031
#include "memory_tracker-inl.h"
@@ -68,6 +69,13 @@ class Watchdog {
6869
bool* timed_out_;
6970
};
7071

72+
// How long the main thread has to respond to --process-timeout, and Worker
73+
// threads to provide their part of the report. A thread that does not respond
74+
// is most likely blocked in a synchronous native call.
75+
constexpr uint64_t kProcessTimeoutResponseGraceMs = 2000;
76+
// The trigger of the report written by --report-on-process-timeout.
77+
constexpr std::string_view kProcessTimeoutReportTrigger = "ProcessTimeout";
78+
7179
// Implements --process-timeout.
7280
//
7381
// A dedicated thread waits until the configured duration has elapsed since the

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

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ const common = require('../common');
66
const assert = require('assert');
77
const fs = require('fs');
88
const { spawnSync } = require('child_process');
9+
const fixtures = require('../common/fixtures');
910
const helper = require('../common/report');
1011
const tmpdir = require('../common/tmpdir');
1112

@@ -45,3 +46,49 @@ helper.validate(reports[0], [
4546

4647
const report = JSON.parse(fs.readFileSync(reports[0], 'utf8'));
4748
assert.match(report.javascriptStack.stack[0], /^at spin \(\[eval\]:1:\d+\)$/);
49+
50+
{
51+
// A Worker thread that is blocked in a synchronous native call cannot
52+
// provide its part of the report. It is left out, so that the report is
53+
// completed before the process is forced to exit.
54+
// If the Worker thread was not blocked yet when the deadline expired, which
55+
// the fixture signals by creating a file, it is included in the report. Run
56+
// the fixture again with a longer timeout in that case.
57+
let child;
58+
let report;
59+
for (let timeout = common.platformTimeout(1000); ; timeout *= 2) {
60+
// Child processes of a previous attempt may still be running, so use a
61+
// different file for each attempt.
62+
const marker = tmpdir.resolve(`blocked-worker.${timeout}.ready`);
63+
child = spawnSync(process.execPath, [
64+
`--process-timeout=${timeout}ms`,
65+
'--report-on-process-timeout',
66+
fixtures.path('process-timeout', 'blocked-worker.js'),
67+
marker,
68+
], { cwd: tmpdir.path, encoding: 'utf8' });
69+
70+
const reports = helper.findReports(child.pid, tmpdir.path);
71+
assert.strictEqual(reports.length, 1, child.stderr);
72+
helper.validate(reports[0], [
73+
['header.event', 'Process timed out (--process-timeout)'],
74+
['header.trigger', 'ProcessTimeout'],
75+
]);
76+
report = JSON.parse(fs.readFileSync(reports[0], 'utf8'));
77+
if ((fs.existsSync(marker) && report.workers.length === 0) ||
78+
timeout >= common.platformTimeout(16000)) {
79+
break;
80+
}
81+
}
82+
83+
assert.strictEqual(child.signal, null);
84+
assert.strictEqual(child.status, 124, child.stderr);
85+
assert.match(child.stderr, /^ {4}Worker \(thread 1, name 'blocked'\)$/m);
86+
// The report is completed before the process is forced to exit, so the
87+
// message about that is printed on its own line.
88+
assert.match(child.stderr, new RegExp(
89+
'^Writing Node\\.js report to file: report\\.\\S+\\.json\\r?\\n' +
90+
'Node\\.js report completed\\r?\\n' +
91+
'\\(node:\\d+\\) The process did not finish exiting within 5000ms after ' +
92+
'--process-timeout expired\\. Forcing exit\\.$', 'm'));
93+
assert.deepStrictEqual(report.workers, []);
94+
}

0 commit comments

Comments
 (0)