fix: bound network worker termination so shutdown can complete - #9790
Conversation
`terminateWorkerThread` awaited `Thread.terminate(worker)` outside the timeout race. `Thread.terminate` resolves to Node's `Worker.terminate()`, which cannot preempt a worker stuck inside a synchronous native (napi) call, so that await can hang indefinitely — making the intended `retryCount * retryMs` budget and the throw unreachable. Graceful shutdown then hangs (observed ~5 min until SIGKILL) instead of failing bounded. Move the `Thread.terminate()` call inside the `Promise.race` so both the terminate call and the termination-event wait are bounded by the timeout. Add a unit test covering the success path and the stuck-terminate case (throws within retryCount * retryMs instead of hanging forever). 🤖 Generated with AI assistance
…meout Complete the bounded-terminate fix so a stuck network worker yields a clean shutdown, not just a bounded one: - Return `false` instead of throwing when the worker can't be terminated. Throwing aborts the rest of `BeaconNode.close()` (the AbortController that stops the clock/chain timers, `chain.persistToDisk()`, and `db.close()`), leaving the process to exit via unhandledRejection with an unclean DB close. - `unref()` the network worker when it can't be terminated: a still-running worker is ref'd and keeps the main event loop alive, so bounding the terminate alone would still prevent the process from exiting on its own. On nodes hitting the hang every shutdown (glamsterdam-devnet-6) this turns each shutdown from a ~5 min zombie / unclean crash into a clean bounded exit. 🤖 Generated with AI assistance Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Address Gemini review on #9582: the `afterEach(vi.useRealTimers())` cleanup was vestigial (fake timers were never enabled in `beforeEach`). Enable them and drive the per-retry `sleep(retryMs)` timeouts with `vi.advanceTimersByTimeAsync`, so the bounded-shutdown test is deterministic on CI instead of depending on real-time delays and a wall-clock assertion. Kept `resolves.toBe(false)` (the function returns false rather than throwing since 6ec9952). 🤖 Generated with AI assistance Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
`WorkerNetworkCore.close()` awaits `getApi().close()`, an RPC into the network worker, without a bound. `BeaconNode.close()` closes the network before calling `chain.persistToDisk()`, so if the worker is wedged the call never settles and shutdown never reaches the archival step - the finalized state is not written and the next start has to replay from an older state. Race it against a 3s timeout and log instead of throwing, terminating the worker right below tears the core down anyway. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard. |
Performance Report✔️ no performance regression detected Full benchmark results
|
Every other line in `WorkerNetworkCore.close()` is debug, and until the pending `connection.closed()` promises in js-libp2p-quic are fixed this path is hit on every shutdown of a node with live QUIC connections. Warning on each restart is noise for something the operator can not act on: shutdown still completes, state is archived, the db is closed and the unref-ed worker dies with the process. `terminateWorkerThread` returns `false`, so the caller owns how severe a failed termination is rather than the helper hardcoding a level. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2.3s is the normal close time, 3s was cutting it too fine and tripped the timeout on most restarts. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Measured 1.85-4.03s across 17 mainnet shutdowns, including on a build where the worker later wedged, so the call is not the hang risk the comment claimed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Captured gdb stacks from a wedged worker show it spinning in `Environment::CleanupHandles()` on `uv_run(UV_RUN_ONCE)`, state R, because a libuv handle on its loop never closes. It is not blocked in a native call that V8 can not preempt, and unref does not let the process exit, `process.exit()` still joins the thread. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
5 of 17 measured shutdowns were censored at the old 3s bound so the tail is unknown, and the only uncensored observation above it was 4.03s. Cutting the close short leaves libp2p handles open, and an unclosed handle is exactly what makes the worker spin in CleanupHandles, so err on the generous side. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`process.exit()` joins every worker via `stop_sub_worker_contexts()` regardless of refcounting, confirmed by gdb stacks of the main thread, so unref-ing the worker changes nothing on this path. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
e6658a8 to
2438f1e
Compare
The 10s bound made the measurement uncensored: 20 mainnet shutdowns closed the core in 2.0-4.1s and none hit the bound. 5s clears the observed max with margin. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`Worker.terminate()` never resolves when the worker spins in `Environment::CleanupHandles()` waiting on a libuv handle that never closes. Logging `getActiveResourcesInfo()` right after libp2p stops names the handle types still holding that loop, so the next occurrence can be diagnosed from a log line instead of gdb. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
21 measurements not 20, and the leaked handle was never attributed to libp2p, only that an unclosed libuv handle is what keeps the worker spinning. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
nflaig
left a comment
There was a problem hiding this comment.
LGTM, this was mostly done by claude debugging on my mainnet node, I don't like that we have to add mitigations like this but this issue has been causing a lot of user facing problems and also has been a problem on devnets. The changes in this PR ensure that we always archive the state correctly, there are still few edge cases where the process was not closing correctly and the process manager (docker in my case) had to force exit the process, this is not nice but at least we have the state archived and from my testing (rather claude testing) this was really rare.
The worker is not blocked in a native call, it spins in CleanupHandles, and the resources logged on close are candidates for the handle that fails to close rather than the established cause. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
spiral-ladder
left a comment
There was a problem hiding this comment.
LGTM, even if we don't fix the underlying issue bounding worker termination seems sane anyway
Picks up ChainSafe/js-libp2p-quic#66, released as 2.1.3. `Connection::closed()` only resolves once quinn reports the connection closed, so a stalled connection driver leaves it pending forever, and with it the napi deferred and threadsafe function backing that promise. libp2p will eventually drop such a peer on its own and call `abort()`, but before 2.1.3 the promise stayed pending even then, so each affected connection leaked those resources for the lifetime of the process. 2.1.3 settles it on `abort()` as well, which turns a permanent leak into none. To be clear about what it does not do: it does not make libp2p notice a dead peer any sooner. By the time `abort()` is called libp2p has already concluded the connection is gone and called `onTransportClosed()` itself. This is resource hygiene, not a peer state fix. **This is not a fix for the shutdown hang.** I originally wrote that patch believing the pending promises were what kept the network worker from terminating. They are not - gdb stacks from a live wedged worker show it spinning in Node's `Environment::CleanupHandles()` on a libuv handle that never closes, and the wedge rate was identical with and without the patch (4 in 20 shutdowns vs 1 in 5 on 2.1.2). #9790 is the mitigation for that, and the underlying handle is still unidentified. On the timing of `onTransportClosed()`: `abort()` runs on every locally initiated close, not just at shutdown, so it is worth being precise about what changes. libp2p already calls `onTransportClosed()` itself immediately after `sendClose()` (`abstract-multiaddr-connection.js`), and the method guards every state transition, so it is idempotent. The settled promise therefore produces a redundant call at a moment the framework was transitioning anyway, rather than an genuinely earlier notification. A remote initiated close does not call `abort()` at all and is unaffected. The change only has an observable effect in the stalled driver case it was written for. **Testing** 2.1.3 is byte-identical in behaviour to the build I ran on a mainnet node for 20 shutdowns at ~200 peers with 90-160 live inbound QUIC connections, no regression observed. Locally, install resolves cleanly, the native addon loads and exposes the unchanged API surface, and typecheck passes. **AI Assistance Disclosure** Dependency bump and validation with Claude Code. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Graceful shutdown hangs and the process has to be force-killed: ``` Aug-07 20:13:03.049 [] info: Stopping gracefully Aug-07 20:13:05.065 [network] debug: terminating network worker <- last shutdown progress ... chain keeps ticking slots for another 54s dockerd: "Container failed to exit within 1m0s of signal 15 - using the force" ``` `terminateWorkerThread` awaits `Thread.terminate()` outside the timeout race, so the `retryCount * retryMs` budget is unreachable. The budget is 3s, the hang was 56s, and there is no `Worker thread failed to terminate, retrying...` in the logs, i.e. it never returned from the first call. **Why terminate never resolves.** gdb stacks captured from a live wedged process show the worker is not blocked, it is spinning: ``` Thread 73 (LWP 1524870 "WorkerThread"): <- state R, on CPU #2 uv_run (loop=0x7fd473dc6938, mode=UV_RUN_ONCE) deps/uv/src/unix/core.c:434 #3 node::Environment::CleanupHandles() #4 node::Environment::RunCleanup() #5 node::FreeEnvironment(node::Environment*) #6 node::worker::Worker::Run() ``` `CleanupHandles()` ends in `while (handle_cleanup_waiting_ != 0 || request_waiting_ != 0 || !handle_wrap_queue_.IsEmpty()) uv_run(event_loop(), UV_RUN_ONCE);`. A libuv handle on the worker's loop never closes, so the loop never exits and the thread never dies. Which handle is still open is not identified. **What it costs.** `BeaconNode.close()` closes the network before `chain.persistToDisk()`, so the hang means the finalized state is never archived and the db is never closed cleanly. On the affected node `checkpoint_states/` was empty for 5 days and a restart fell back to a db state 319 slots behind the head it had at shutdown. - race `Thread.terminate()` against the timeout so the `retryCount * retryMs` budget is enforced - return a boolean instead of throwing, so a failed termination does not abort the rest of `BeaconNode.close()` - bound `getApi().close()`, an unbounded RPC into the same worker that runs before the archive - log `getActiveResourcesInfo()` when the network core closes, so the next stuck shutdown can be diagnosed from a log line rather than gdb **Scope.** This keeps a stuck worker from costing us the state archive. It does not stop the worker getting stuck, and it does not make the process exit promptly: `process.exit()` joins every worker via `stop_sub_worker_contexts()`, confirmed in the same capture, so a stuck shutdown still runs to the process manager's stop timeout. ``` Thread 1 (LWP 1524136 "MainThread"): #2 uv_thread_join deps/uv/src/unix/thread.c:295 #3 node::worker::Worker::JoinThread() #4 node::Environment::stop_sub_worker_contexts() #5 node::DefaultProcessExitHandlerInternal(...) ``` I tried to fix that here too, by surfacing the failed termination and hard exiting from the CLI. It did not work - on both wedges that occurred during validation the flag read false at the CLI even though the worker had set it, and the process still waited for the docker timeout. That is dropped from this PR rather than shipped unproven, and `unref()` went with it since `process.exit()` joins regardless of refcounting. **Testing.** 101 mainnet shutdowns on this branch, each after soaking at ~200 peers with 90-160 live inbound QUIC connections for at least 5 minutes: - **99/101 archived the finalized state and logged `Beacon node closed`**, including all 7 where the worker failed to terminate - clean shutdowns complete in 5.9-9.1s - the 7 stuck ones still archived and closed internally in ~9s before being force-killed on the docker timeout The build without this change hung at `terminating network worker` and lost the archive on all 4 shutdowns observed. `NETWORK_CORE_CLOSE_TIMEOUT_MS` is 5s. At the original 3s it tripped on 35 of 101 shutdowns, so the measurement was censored. Raising it to 10s temporarily made it uncensored: 21 shutdowns closed the core in 2.0-4.1s and none hit the bound, so 5s clears the observed max with margin while still bounding an `await` that sits in front of the archive. Note the 35 censored runs mean it is not established that this RPC always resolves, which is the argument for bounding it at all. Root cause notes, gdb captures and the handle-walk tooling: https://gist.github.com/nflaig/b266d89c03cdd2c76338823afed5b2c0 **AI Assistance Disclosure** Investigation and patch developed with Claude Code. Cause traced from debug logs and gdb captures of a live wedged process, validated on a mainnet node as above. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: lodekeeper <lodekeeper@users.noreply.github.com> Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
Picks up ChainSafe/js-libp2p-quic#66, released as 2.1.3. `Connection::closed()` only resolves once quinn reports the connection closed, so a stalled connection driver leaves it pending forever, and with it the napi deferred and threadsafe function backing that promise. libp2p will eventually drop such a peer on its own and call `abort()`, but before 2.1.3 the promise stayed pending even then, so each affected connection leaked those resources for the lifetime of the process. 2.1.3 settles it on `abort()` as well, which turns a permanent leak into none. To be clear about what it does not do: it does not make libp2p notice a dead peer any sooner. By the time `abort()` is called libp2p has already concluded the connection is gone and called `onTransportClosed()` itself. This is resource hygiene, not a peer state fix. **This is not a fix for the shutdown hang.** I originally wrote that patch believing the pending promises were what kept the network worker from terminating. They are not - gdb stacks from a live wedged worker show it spinning in Node's `Environment::CleanupHandles()` on a libuv handle that never closes, and the wedge rate was identical with and without the patch (4 in 20 shutdowns vs 1 in 5 on 2.1.2). #9790 is the mitigation for that, and the underlying handle is still unidentified. On the timing of `onTransportClosed()`: `abort()` runs on every locally initiated close, not just at shutdown, so it is worth being precise about what changes. libp2p already calls `onTransportClosed()` itself immediately after `sendClose()` (`abstract-multiaddr-connection.js`), and the method guards every state transition, so it is idempotent. The settled promise therefore produces a redundant call at a moment the framework was transitioning anyway, rather than an genuinely earlier notification. A remote initiated close does not call `abort()` at all and is unaffected. The change only has an observable effect in the stalled driver case it was written for. **Testing** 2.1.3 is byte-identical in behaviour to the build I ran on a mainnet node for 20 shutdowns at ~200 peers with 90-160 live inbound QUIC connections, no regression observed. Locally, install resolves cleanly, the native addon loads and exposes the unchanged API surface, and typecheck passes. **AI Assistance Disclosure** Dependency bump and validation with Claude Code. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
For anyone picking this up later, the investigation behind this change is written up here:
Short version of what this does and does not fix. Validated over 20 mainnet shutdowns on v1.46.0-rc.1: state was archived 20/20, against 4/4 losses on a build without it. 18/20 completed cleanly in 6.1-9.1s. The remaining 2 hit the known gap, the network worker fails to terminate and the process runs to the stop timeout, but those still archived state, which was the point. The underlying cause is unfixed. The worker spins in Eight refuted hypotheses are listed in the close-out so nobody repeats them. |
|
🎉 This PR is included in v1.46.0 🎉 |
Applies libp2p/js-libp2p#3597 as a local `pnpm patch` until it is released. This fixes the network worker shutdown hang, the underlying handle that #9790 mitigated but did not identify. ## Root cause `TCPSocketMultiaddrConnection.sendReset()` calls `socket.resetAndDestroy()` unconditionally. When the writable side has already ended that does not tear the handle down, so the socket stays alive as an active `TCPSocketWrap` while libp2p considers it closed. Nothing else holds a reference, so nothing ever closes it. Node's worker teardown then spins forever, because `Environment::CleanupHandles()` runs until every handle is closed: ```cpp while (handle_cleanup_waiting_ != 0 || request_waiting_ != 0 || !handle_wrap_queue_.IsEmpty()) { uv_run(event_loop(), UV_RUN_ONCE); } ``` The thread never exits, so `Worker.terminate()` never resolves, so the main thread blocks in `uv_thread_join` from `process.exit()` until the process manager kills it. The patch guards the case the reset cannot handle: ```js sendReset (): void { if (this.socket.writableEnded) { this.socket.destroy() return } this.socket.resetAndDestroy() } ``` ## Why the exact-version pin `@libp2p/tcp` is declared as `^11.0.13` and `patchedDependencies` keys are version exact, so an 11.0.14 release would resolve past the patch and silently drop the fix. The `overrides` pin prevents that, same as the existing `sigstore` patch. It does mean no `@libp2p/tcp` bump until the patch is dropped. ## Testing Validated on a mainnet node against a baseline hang rate of 4 in 36 shutdowns (11.1%). 70 consecutive shutdowns, synced with >=200 peers and a 5 minute soak each: | criterion | result | | --- | --- | | hangs | 0 / 70 | | `TCPSocketWrap` present after `libp2p.stop()` | 0 / 70 | | worker terminate | 0.027-0.072s, hang signature is 3.000s | | exit code | 0 on all 70, never SIGKILLed | | shutdown duration | mean 7.20s, max 9.8s | | state archived | 70 / 70 | Plus one shutdown at 9.07h uptime, since orphaned socket counts grew with uptime: terminate 0.180s, no `TCPSocketWrap`, exit 0. Counted independently from the raw node logs as well as from the test harness. The last unpatched shutdown on the same machine, three minutes before deploying the patched build, hung at 3.001s with `activeResources=MessagePort=1,TCPSocketWrap=6,Timeout=1`. Observing 70 consecutive clean shutdowns if the bug were still present has probability 0.00026. Fisher exact against the measured baseline gives p = 0.012. The `activeResources` logging added by #9790 is what made this diagnosable, the presence of `TCPSocketWrap` separated 5 hangs from 32 clean shutdowns perfectly (Fisher p = 0.0000023). Longest uptime tested was 9.07h. The worst case observed, 28 orphaned sockets, took ~38h to accumulate, so this validates the mechanism rather than proving an upper bound. Full write-up: https://gist.github.com/nflaig/5f41cfc50f38baf5046a034162943dc3 ## When to remove Drop the patch and the `overrides` pin together once js-libp2p#3597 is released and `@libp2p/tcp` is bumped to a version containing it. ## AI Assistance Disclosure Investigation, patch and validation with Claude Code. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Graceful shutdown hangs and the process has to be force-killed:
terminateWorkerThreadawaitsThread.terminate()outside the timeout race, so theretryCount * retryMsbudget is unreachable. The budget is 3s, the hang was 56s, and there is noWorker thread failed to terminate, retrying...in the logs, i.e. it never returned from the first call.Why terminate never resolves. gdb stacks captured from a live wedged process show the worker is not blocked, it is spinning:
CleanupHandles()ends inwhile (handle_cleanup_waiting_ != 0 || request_waiting_ != 0 || !handle_wrap_queue_.IsEmpty()) uv_run(event_loop(), UV_RUN_ONCE);. A libuv handle on the worker's loop never closes, so the loop never exits and the thread never dies. Which handle is still open is not identified.What it costs.
BeaconNode.close()closes the network beforechain.persistToDisk(), so the hang means the finalized state is never archived and the db is never closed cleanly. On the affected nodecheckpoint_states/was empty for 5 days and a restart fell back to a db state 319 slots behind the head it had at shutdown.Thread.terminate()against the timeout so theretryCount * retryMsbudget is enforcedBeaconNode.close()getApi().close(), an unbounded RPC into the same worker that runs before the archivegetActiveResourcesInfo()when the network core closes, so the next stuck shutdown can be diagnosed from a log line rather than gdbScope. This keeps a stuck worker from costing us the state archive. It does not stop the worker getting stuck, and it does not make the process exit promptly:
process.exit()joins every worker viastop_sub_worker_contexts(), confirmed in the same capture, so a stuck shutdown still runs to the process manager's stop timeout.I tried to fix that here too, by surfacing the failed termination and hard exiting from the CLI. It did not work - on both wedges that occurred during validation the flag read false at the CLI even though the worker had set it, and the process still waited for the docker timeout. That is dropped from this PR rather than shipped unproven, and
unref()went with it sinceprocess.exit()joins regardless of refcounting.Testing. 101 mainnet shutdowns on this branch, each after soaking at ~200 peers with 90-160 live inbound QUIC connections for at least 5 minutes:
Beacon node closed, including all 7 where the worker failed to terminateThe build without this change hung at
terminating network workerand lost the archive on all 4 shutdowns observed.NETWORK_CORE_CLOSE_TIMEOUT_MSis 5s. At the original 3s it tripped on 35 of 101 shutdowns, so the measurement was censored. Raising it to 10s temporarily made it uncensored: 21 shutdowns closed the core in 2.0-4.1s and none hit the bound, so 5s clears the observed max with margin while still bounding anawaitthat sits in front of the archive. Note the 35 censored runs mean it is not established that this RPC always resolves, which is the argument for bounding it at all.Root cause notes, gdb captures and the handle-walk tooling: https://gist.github.com/nflaig/b266d89c03cdd2c76338823afed5b2c0
AI Assistance Disclosure
Investigation and patch developed with Claude Code. Cause traced from debug logs and gdb captures of a live wedged process, validated on a mainnet node as above.
🤖 Generated with Claude Code