A test's Catch(...).Repeat() was a 54 kHz busy-wait that killed the whole test host (#2341) by rbuergi · Pull Request #2390 · Systemorph/MeshWeaver

rbuergi · 2026-08-26T13:54:44Z

Closes #2341.

MeshWeaver.Threading.Test died with exit=124 TIMEOUT (8m wall-clock cap hit) and no .trx — 12 times in ~15 h across five branches AND main (first 2026-08-25T23:24Z, latest 2026-08-26T12:35Z; 400 runs scanned back to 2026-08-22, none before). It reddened shards on PRs whose diffs never touched the threading library.

The issue's hypothesis is disproved, with evidence

#2341 named the two static ManualResetEventSlim signals in that assembly, on the theory that a signal set by one test makes a later test's guard vacuous. That cannot happen: ParkingChatClient.Entered and ParkedDelegationFactory.DelegationEntered are each referenced only from inside their own single-[Fact] class, so each is Set() and Wait()ed exactly once per process, by the same test; both waits are bounded (Wait(30 s/60 s, ct)); and in every wedged run's phase trace those two drain tests complete in 0.7–2 s. They are still wrong per AGENTS.md's no-static-state rule — but they are not this defect, and this PR leaves them alone.

What it actually is

The failing shards' own artifact carries the answer. In collected-logs/_meshweaver-test-trace.log the wedged host logs 112 INIT_DONE and 111 DISPOSE_DONE — exactly one test method entered and never returned — and in all three failing runs whose artifacts survive it is the same one: SubThreadHangRepro. Everything else finishes ~36 s in; the process then looks idle for 7.5 min until CI kills it.

Reproduced locally 2 attempts out of 2 by running six hosts of the assembly at once under DOTNET_PROCESSOR_COUNT=4 (12 sequential single-host runs on the same box were all green — the repro needs CPU contention). Both local wedges show the same trace imbalance, the same class, and one thread at 100 % CPU whose managed stack names the defect:

SubThreadHangRepro.<HungSubThread_WithoutUserCancel_StaysExecuting>d__4.MoveNext()
  ObservableAssertions.Emit -> WaitForFirst -> ToTask(...)          <- SYNCHRONOUS subscribe
    Timeout.Relative.Run -> ToList.Run -> Take.Count.Run
      ObservableAssertions.SubscribeHereOffSyncContext.b__0
        Do.OnNext.Run -> Concat.Run -> TailRecursiveSink.Drain()    <- Repeat()'s engine, spinning
          Producer.SubscribeRaw (Catch) -> Producer.SubscribeRaw (Defer) -> Defer.Run()
            SubThreadHangRepro+<>c__DisplayClass4_0.b__6()          <- the Defer lambda
              AutofacServiceProvider.GetService -> ResolveOperation.ExecuteOperation

The site:

Observable.Defer(() => workspace.GetMeshNodeStream(subThreadPath) ... .Take(1))
    .Catch<MeshThread?, Exception>(_ => Observable.Empty<MeshThread?>().Delay(200.Milliseconds()))
    .Repeat()

Catch intercepts OnError only. A point read of the not-yet-created sub-thread node completes without emitting, so the 200 ms backoff never runs and Repeat re-subscribes immediately. Measured with a temporary probe on the real repro: 460 000 re-subscribes in 8.45 s (~54 kHz) and ZERO OnError — the delay everyone believed was there had never executed once, on any run.

Two things turn that from wasteful into fatal:

Rx subscribes synchronously, so the loop runs inside the assertion's own .ToTask() call and the await is never reached. That puts it out of reach of every timeout the harness has: .Within(15 s), [Fact(Timeout)], methodTimeout, and MonolithMeshTestBase's hard-deadline watchdog all need the method to return or park at an await. Nothing can fail this test.
It starves what it waits for. The spin pins a core and hammers Autofac + the node-stream cache; on a 4-vCPU runner that is a quarter of the machine plus lock traffic against the very hub that must create the sub-thread node. The condition stops arriving, so the loop that prevents it cannot end. On an idle 18-core box the node lands after ~170 ms and it exits — which is why this stayed invisible locally for the seven weeks the construct has existed.

Why it started on 2026-08-25: the construct dates from 2026-07-02 and its comment records the then-true behaviour ("GetMeshNodeStream surfaces missing satellite as OnError almost immediately"). The absent-node answer is now an empty completion, which silently made the Catch guard vacuous and flipped a 200 ms poll into a 54 kHz spin. Nothing in src/ shares the shape — its only two .Repeat() sites are over sources that carry their own cadence.

The fix

Both waits move to the composition AGENTS.md prescribes for a node that may not exist yet: the keyed GetQuery listing for existence (empty-on-absent, live — the index trails the store, so "the index has seen it" implies "the store has it"), then the owner's stream for content. No polling, no retry, no resubscribe; every wait is bounded by the assertion's own timeout again because nothing blocks the subscribe. The n.Content as MeshThread trap-door casts on the touched lines become ContentAs<MeshThread>(...).

SubThreadColdStartRepro and SubThreadStallRepro carried the same construct in two more places (same assembly, same delegation wait) and are fixed identically — otherwise the wedge simply moves.

The control

UnthrottledResubscribeInTestRatchetGuard refuses an argument-less .Repeat() / .Retry() anywhere under test/. Its allow file is deliberately empty: the three sites that existed are the three fixed here. .Repeat(count) / .Retry(count) / .RetryWhen(handler) are not matched — a bounded count terminates, and RetryWhen is the sanctioned replacement (OnError only, its own timer, bounded).

Proved non-vacuous two ways in the same run: a fixture asserts the scanner counts the shape in code and ignores it in comments and string literals (load-bearing — the guard's own prose quotes .Repeat() repeatedly), and it was mutation-tested by reintroducing one call site, which turns it red with NEW SITE.

Verification

	result
BEFORE — 6 concurrent hosts, `DOTNET_PROCESSOR_COUNT=4`	2 wedges in 2 rounds; stack + full dump captured for both
BEFORE — 12 sequential single-host runs, same box	all green (the repro needs contention)
BEFORE — CI	12 × `exit=124` in the last 400 runs
AFTER — 12 rounds × 6 concurrent hosts = 72 full-assembly runs	0 wedges
`MeshWeaver.Threading.Test`	139/139 green
`MeshWeaver.Documentation.Test`	64/64 green (both ratchets + `DocumentationLinkIntegrityTest`)
`dotnet build -c Release -p:CIRun=true -warnaserror`	clean on both touched test projects

Follow-up worth a separate look (not changed here)

MeshNodeStreamCache's cached entry tracks a terminal OnError (MarkFaulted → re-probe) but not a terminal OnCompleted, and the absent-node read now answers with an empty completion rather than the NotFound error the 2026-07 comment assumed. No other caller depends on that assumption today (checked: the only .Repeat() sites in src/ are cadence-carrying), so this PR does not touch it — but it is the behaviour change that made the guard above vacuous, and worth a decision of its own.

🤖 Generated with Claude Code

…hole test host (#2341) `MeshWeaver.Threading.Test` died with `exit=124 TIMEOUT (8m wall-clock cap hit)` and no `.trx` — 12 times in ~15 h across five branches AND `main` (first 2026-08-25T23:24Z, latest 2026-08-26T12:35Z; 400 runs scanned back to 2026-08-22, none before). It reddened shards on PRs whose diffs never touch the threading library. ## The standing hypothesis is DISPROVED, with evidence #2341 proposed the two static `ManualResetEventSlim` signals in that assembly as the cause, on the theory that a signal set by one test makes a later test's guard vacuous. That cannot happen: `ParkingChatClient.Entered` and `ParkedDelegationFactory.DelegationEntered` are each referenced ONLY from inside their own single-`[Fact]` class, so each is `Set()` and `Wait()`ed exactly once per process by the same test; both waits are bounded (`Wait(30 s/60 s, ct)`); and in every wedged run's phase trace those two drain tests complete in 0.7–2 s. They remain wrong per AGENTS.md's no-static-state rule, but they are not this defect and are left alone here. ## What it actually is The failing shards' own artifact carries the answer. In `_meshweaver-test-trace.log`, the wedged host logs 112 `INIT_DONE` and 111 `DISPOSE_DONE`: exactly ONE test method is entered and never returns, and in all three failing runs whose artifacts survive it is the same one — `SubThreadHangRepro`. Everything else in the assembly finishes ~36 s in; the process then sits idle-looking for 7.5 min until CI's `timeout 8m` kills it. Reproduced locally 2 attempts out of 2 by running six hosts of the assembly concurrently under `DOTNET_PROCESSOR_COUNT=4` (12 sequential single-host runs on the same box were all green — the repro needs CPU contention). Both local wedges show the identical trace imbalance, the identical class, and one thread at 100 % CPU. Its managed stack names the defect outright: SubThreadHangRepro.<HungSubThread_WithoutUserCancel_StaysExecuting>d__4.MoveNext() ObservableAssertions.Emit -> WaitForFirst -> ToTask(...) <- SYNCHRONOUS subscribe Timeout.Relative.Run -> ToList.Run -> Take.Count.Run ObservableAssertions.SubscribeHereOffSyncContext.b__0 Do.OnNext.Run -> Concat.Run -> TailRecursiveSink.Drain() <- Repeat()'s engine, spinning Producer.SubscribeRaw (Catch) -> Producer.SubscribeRaw (Defer) -> Defer.Run() SubThreadHangRepro+<>c__DisplayClass4_0.b__6() <- the Defer lambda AutofacServiceProvider.GetService -> ResolveOperation.ExecuteOperation The site is Observable.Defer(() => workspace.GetMeshNodeStream(subThreadPath) ... .Take(1)) .Catch<MeshThread?, Exception>(_ => Observable.Empty<MeshThread?>().Delay(200.Milliseconds())) .Repeat() `Catch` intercepts **OnError only**. A point read of the not-yet-created sub-thread node COMPLETES without emitting, so the 200 ms backoff never runs and `Repeat` re-subscribes immediately. Measured with a temporary probe on the real repro: **460 000 re-subscribes in 8.45 s (~54 kHz) and ZERO OnError** — the delay everyone believed was there had never executed once, on any run. Two things turn that from "wasteful" into "kills the host": * **Rx subscribes synchronously.** The loop runs inside the assertion's own `.ToTask()` call, so the `await` is never reached — which puts it out of reach of EVERY timeout the harness has: `.Within(15 s)`, `[Fact(Timeout)]`, `methodTimeout`, and `MonolithMeshTestBase`'s hard-deadline watchdog all need the method to return or to park at an await. Nothing can fail this test. * **It starves what it waits for.** The spin pins a core and hammers Autofac + the node-stream cache. On a 4-vCPU runner that is a quarter of the machine plus lock traffic against the very hub that has to create the sub-thread node — so the condition the loop waits for stops arriving, and the loop that prevents it cannot end. On an idle 18-core box the node lands after ~170 ms and it exits, which is why this was invisible locally for the seven weeks the construct has existed. Why it started on 2026-08-25 and not in July: the construct dates from 2026-07-02 and its comment records the then-true behaviour ("GetMeshNodeStream surfaces missing satellite as OnError almost immediately"). The absent-node answer is now an empty COMPLETION, which silently made the `Catch` guard vacuous. Nothing in `src/` shares the shape — the only two `.Repeat()` sites there are over sources that carry their own cadence. ## The fix Both waits move to the composition AGENTS.md prescribes for a node that may not exist yet: the keyed `GetQuery` listing for EXISTENCE (empty-on-absent, live — the index trails the store, so "the index has seen it" implies "the store has it"), then the owner's stream for CONTENT. No polling, no retry, no resubscribe: purely event-driven, and every wait is bounded by the assertion's own timeout again because nothing blocks the subscribe. The `n.Content as MeshThread` trap-door casts on the touched lines become `ContentAs<MeshThread>(...)` at the same time. `SubThreadColdStartRepro` and `SubThreadStallRepro` carried the SAME construct in two more places (same assembly, same delegation wait) and are fixed identically — otherwise the wedge simply moves. ## The control `UnthrottledResubscribeInTestRatchetGuard` refuses an argument-less `.Repeat()` / `.Retry()` in `test/**`. Its allow file is deliberately EMPTY: the three sites that existed are the three fixed here. `.Repeat(count)` / `.Retry(count)` / `.RetryWhen(handler)` are not matched — a bounded count terminates and `RetryWhen` is the sanctioned replacement (OnError only, its own timer). The guard is proved non-vacuous two ways in the same run: a fixture asserts the scanner counts the shape in CODE and ignores it in comments and string literals (load-bearing — the guard's own prose quotes `.Repeat()` repeatedly), and it was mutation-tested by reintroducing one call site, which turns it red with `NEW SITE`. ## Verification * BEFORE: 2 wedges in 2 harness rounds (6 concurrent hosts, `DOTNET_PROCESSOR_COUNT=4`); stack + full dump captured for both; 12 CI occurrences in the last 400 runs. * AFTER: 12 rounds x 6 concurrent hosts = 72 host runs of the full assembly, ZERO wedges. * `MeshWeaver.Threading.Test` 139/139 green; `MeshWeaver.Documentation.Test` 64/64 green (includes both ratchets and `DocumentationLinkIntegrityTest`). * `dotnet build -c Release -p:CIRun=true -warnaserror` clean on both touched test projects. Closes #2341 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot

Pull request overview

This PR addresses CI-host wedges caused by unthrottled Rx resubscribe loops in delegation sub-thread tests, where a missing-node read completed (no OnError) and .Catch(...).Repeat() turned into a tight synchronous busy-wait. It replaces the polling pattern with the repo’s canonical “existence via synced query, then content via owner stream” composition and adds a governance ratchet to prevent reintroducing the defect class.

Changes:

Replace Defer(...).Catch(...).Repeat() delegation sub-thread waits with GetQuery(...select:path) existence gating followed by GetMeshNodeStream(...) content reads.
Switch touched content reads from node.Content as T to ContentAs<T>(...) at the updated wait sites.
Add a new test ratchet (UnthrottledResubscribeInTestRatchetGuard) plus an empty allow-file to block any future argument-less .Repeat() / .Retry() usage under test/.

Reviewed changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated no comments.

Show a summary per file

File	Description
test/UnthrottledResubscribeSites.allow	New (deliberately empty) allow-file for the unthrottled-resubscribe ratchet.
test/MeshWeaver.Threading.Test/SubThreadHangRepro.cs	Replaces the unthrottled resubscribe wait with existence-gated query + owner stream read; switches to `ContentAs`.
test/MeshWeaver.Threading.Test/SubThreadColdStartRepro.cs	Applies the same existence-gated wait pattern and `ContentAs` usage at the affected sites.
test/MeshWeaver.Documentation.Test/UnthrottledResubscribeInTestRatchetGuard.cs	New governance ratchet that scans `test/` for argument-less `.Repeat()` / `.Retry()` in code (masking comments/strings).
src/MeshWeaver.Documentation/Data/WhatsNew/2026-08-26-test-suite-busy-wait.md	“What’s New” entry documenting the fix and the new build guard.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

github-actions · 2026-08-26T14:10:23Z

Test Results (shard 3)

9 files ±0 9 suites ±0 5m 21s ⏱️ -20s
1 960 tests ±0 1 958 ✅ ±0 2 💤 ±0 0 ❌ ±0
2 518 runs +1 2 516 ✅ +1 2 💤 ±0 0 ❌ ±0

Results for commit fd68d8f. ± Comparison against base commit f494f65.