MeshNodeLanguageServiceTest teardown DIRTY — one pooled I/O leaf still ignores cancellation after #2598 (#2665 names the pool on the next occurrence) #2616

Activity

1. rbuergi commented on Aug 29, 2026

   

   rbuergi

   on Aug 29, 2026

   ContributorAuthor

   More actions

   Fresh measurement — only one occurrence so far; too soon to call it either way

   Swept every MeshWeaver Build and Test run on main, 2026-08-26T07:38Z → 2026-08-28T20:46Z (61 h,
   121 non-cancelled attempts, 19 failures, each cross-checked via the shard job's own
   Test failed/crash annotations).

   MeshNodeLanguageServiceTest.ScriptCompletions_FilterByTypedPrefix_NotJustTheAlphabet appears
   exactly once: run 33171489378,
   2026-08-28T12:32:28Z, shard 2 — the same event this issue was filed from. Since then: 18 valid
   main attempts, 0 recurrences (through 2026-08-28T20:46Z; no further main push has run as of
   this comment, 2026-08-29T06:14Z). Since the issue was filed (14:18Z): 11 valid attempts, 0
   recurrences.

   That is well short of a confident window — the rule of thumb here is ~30 clean runs before calling
   something not-reproducing, and no fix has landed since (#2598/102275d1e is still the most recent
   commit touching MeshNodeLanguageService.cs / KernelScriptReferences.cs). One occurrence is not
   enough to confirm the race is real and recurring either, versus a one-off under whatever load shard
   2 was carrying at that moment.

   Leaving open — could not establish a rate in either direction with this little data. Worth
   re-checking once more main runs accumulate.
2. rbuergi commented on Aug 29, 2026

   

   rbuergi

   on Aug 29, 2026

   ContributorAuthor

   More actions

   The premise is refuted: #2598 did not start this, and the test did not fail its assertion

   MEASURED, from the still-live testResults-shard2 artifact of the exact run this issue was filed on (33171489378).

   1. The test PASSED. There was no completion assertion failure.

   collected-logs/_meshweaver-test-trace.log, lines 5921–5936:

   12:53:48.631 [MeshNodeLanguageServiceTest] TEST_START ScriptCompletions_FilterByTypedPrefix_NotJustTheAlphabet
   12:53:49.675 [MeshNodeLanguageServiceTest] TEST_END elapsed=1044ms ... outcome=Passed
   12:53:49.676 DISPOSE_INVOKED
   12:53:49.720 DISPOSE_IOPOOL_DRAIN_START
   12:54:19.721 DISPOSE_IOPOOL_DRAIN_DONE elapsed=30045ms leakedIoLeaves=1
   12:54:19.721 DISPOSE_DONE teardown DIRTY — 1 pooled I/O leaf(s) still running
   

   All four assertions (NotBeEmpty, Count ≤ 15, Contain "Mesh", OnlyContain "Mes") were green in 1.04 s. The reported exception is an InvalidOperationException from MonolithMeshTestBase.DisposeAsync() (MonolithMeshTestBase.cs:1574) — a teardown failure wearing the test's name. Nothing about the reference set was ever observed to be wrong. The "truncated symbol list" hypothesis is refuted at the observation level.

   2. It predates #2598 by ~4 hours — it is a recurrence of #2578

   	run	started	head sha	contains #2598 (cc3c18c3)?
   #2578	33152742916	08-28 07:46Z	842cd523	NO (verified merge-base --is-ancestor)
   #2616	33171489378	08-28 12:32Z	4ad8fb85	YES

   #2598 merged at 11:34Z. #2578 is the observation that motivated #2598 — same test, same exception text, same 30 s, same anonymous 1 pooled I/O leaf(s). So "first seen right after #2598" is inverted: it predates that PR and recurred unchanged after it. This should be treated as a recurrence of #2578.

   3. The Lazy<Task<T>> cancellation hypothesis is refuted at the code level too

   Both memos are exactly the shape worth suspecting — KernelScriptReferences.cs:64 and MeshNodeLanguageService.cs:68 — but the "cancelled task cached forever" classic does not apply: Task.WaitAsync(ct) returns a new task that faults with OCE and never touches the awaited task, and neither memo is started with a caller token (Task.Run(CreateSharedSnapshot) takes none; BuildScriptWorkspaceAsync awaits with explicit CancellationToken.None). A cancelled caller cannot poison either memo.

   🚨 4. Why this has now cost two investigations: #2598's own diagnostic is inert

   #2480 asked for the offending pool to be named. #2598 added it — IoPoolRegistry.cs:149, "IoPoolDrain: pool '{PoolName}' did not finish {Residual} leaf(es)…". On the first recurrence it produced nothing: zero hits in the job log, the trx, and collected-logs/.

   Cause: it goes to ILogger, and DrainAll() runs after Mesh.Dispose(). MEASURED: of 294 Mesh.Dispose() invoking windows in this shard's trx, ZERO contain an ILogger line at any level — while the same trx carries 84 [Warning] [SynchronizationStream] and 76 [Warning] [RoutingServiceBase] records from before dispose. The mesh's log sink stops capturing at dispose, so the one diagnostic written to name the pool is structurally invisible in exactly the window it exists for.

   PR #2665 fixes that: DrainAll returns the per-pool residuals, and both callers route them somewhere that survives dispose (TestPhaseTrace → the file CI keeps, which also survives an exit=124 host kill; TeardownReport.ResidualByPool in production). The trace becomes leakedIoLeaves=1 pools=[Query=1]. That matters because Query=1 and Compile=1 are different bugs, and IoPool.Drain yields a residual from three distinct causes that all currently reduce to the same integer.

   5. What the evidence says the leaf probably is (NOT proven — needs the name)

   • 30045 ms is exactly one DrainTimeout (IoPool.cs:80).
   • The memory watchdog shows RSS flat at ~950 MiB from 12:53:51.372 through 12:54:16.371 — the leaf was parked for ~28 of the 30 s, not computing. That argues against Pooled I/O leaf now observes cancellation: script-completion's first-in-process reference build (#2480, #2578) #2598's premise (an uncancellable metadata build overrunning) and for a leaf blocked on something that never observes its token.
   • Strongest un-eliminated candidate on this exact path: MeshNodeLanguageService.cs:153 calls usageIndex.EnsureFresh(), and CompletionUsageIndex.EnsureFresh() (:79) fires a fire-and-forget, never-disposed, unowned mesh.Query<MeshNode>(...) subscription with .Timeout(QueryTimeout) where QueryTimeout = 30 s (:43), subscribed through the Query pool. A second independent 30 s budget coinciding with the drain's is the expected shape. CompletionMemoryStore has the same unowned .Subscribe(...) at :102, :182, :265.

   If #2665 lands and the next occurrence says pools=[Query=1], that candidate is confirmed and the fix is to give EnsureFresh() an owner (hold the IDisposable, dispose the prior one, dispose on teardown) rather than leaving a 30 s subscription running past the request that started it.

   6. One thing #2598 made worse, worth a look regardless

   Task.Run(CreateSharedSnapshot) and the CancellationToken.None continuation now run on bare ThreadPool items that no IIoPool tracks and DrainAll() cannot see or join, while capturing hub.ServiceProvider. The PR moved the largest Roslyn workload in the process out of the drain's sight rather than making it drainable. Evidence it runs past TEST_END: DISPOSE_MEM rss Δ+161 MiB on this 1-second test, versus Δ+9 / Δ+27 MiB on the same class's other instances.

   ---

   Recommendation: retitle/close this as a duplicate of #2578, land #2665 so the third occurrence names its pool, and do not re-run, widen DrainTimeout (the guard's own message forbids it), or skip-list the test — the test is passing; teardown is not.
3. rbuergi

   added a commit that references this issue on Aug 29, 2026

   Merge pull request #2665 from Systemorph/fix/2616-drain-residual-name…

   ...

   d4db4a8
4. rbuergi

   changed the title [-]Flake: MeshNodeLanguageServiceTest.ScriptCompletions_FilterByTypedPrefix_NotJustTheAlphabet on shard 2 — first seen right after #2598 touched MeshNodeLanguageService[/-] [+]MeshNodeLanguageServiceTest teardown DIRTY — one pooled I/O leaf still ignores cancellation after #2598 (#2665 names the pool on the next occurrence)[/+] on Aug 30, 2026
5. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   Second face, pool NAMED (#2665 delivered): DocumentBlocksAreaRenderTest leaks one Layout-pool leaf

   Observed 2026-08-30 on #2733 (run 33300432494, shard 4, head 4d7812de6). The PR moves the modules/ generations GC off the readiness path (MeshWeaver.PluginCatalog + Memex.Portal.Shared) — MeshWeaver.ContentCollections.Indexing.Graph.Test has no project-reference path to either assembly (checked every csproj in its closure; MeshWeaver.Graph.csproj mentions Memex.Portal.Shared only in a comment), so the diff is not loaded in the failing host. Main was green at d3272b5f8 (07:28) and a0d404b89 (07:55).

   The test PASSED; teardown found the leak — the #2616 shape exactly, on a different test, and this time the pool is named (_meshweaver-test-trace.log, testResults-shard4):

   08:11:34.207 [DocumentBlocksAreaRenderTest] TEST_START LegacyUntypedDocumentNode_BlocksArea_RendersExcerptAndNavigation
   08:11:34.421 [DocumentBlocksAreaRenderTest] TEST_END elapsed=213ms ... outcome=Passed
   08:11:34.421 [DocumentBlocksAreaRenderTest] DISPOSE_HOSTED_SERVICES_STOPPED elapsed=0ms
   08:11:34.446 [DocumentBlocksAreaRenderTest] DISPOSE_IOPOOL_DRAIN_START elapsed=25ms
   08:12:04.449 [DocumentBlocksAreaRenderTest] DISPOSE_IOPOOL_DRAIN_DONE elapsed=30026ms leakedIoLeaves=1 pools=[Layout=1]
   08:12:04.449 [DocumentBlocksAreaRenderTest] DISPOSE_DIRTY_TEARDOWN elapsed=30028ms teardown DIRTY — 1 pooled I/O leaf(s) still running
   

   So the leaf that will not cancel is a IoPoolNames.Layout SubscribeThroughPool leaf — the layout-area render subscribe (RenderBlocksUntil → LayoutAreaReference over the Document blocks area), not a script-completion / MeshNodeLanguageService leaf. That refutes the remaining "#2598 started this" thread here: the common factor is the render-subscribe leaf ignoring the pool's cancellation at drain, and MeshNodeLanguageServiceTest is just one of the tests that renders.

   Also in the stdout for this test (before the DIRTY teardown): three ROUTER_TRAFFIC errors — RawJson with the mesh hub as sender and DataChangedEvent/SubscribeAck with the mesh hub as target, for TestData/content/_Documents/vertrag_2025.txt — i.e. the render's data-change subscription is wired through the mesh (router) hub rather than a hub of its own, which is the likeliest place a subscribe leaf sits outside the drain's cancellation.

   Not re-run; the PR stays red until this is fixed or a fresh run happens to miss the race.

   Filed by Claude Code from #2733.
6. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   New occurrence: 2026-08-30, on #2760 (a permission-fold security fix), shard 2

   Same test, same signature, same 30 s drain:

   MeshWeaver.Hosting.Monolith.Test.MeshNodeLanguageServiceTest.ScriptCompletions_FilterByTypedPrefix_NotJustTheAlphabet [FAIL]
   System.InvalidOperationException : MeshNodeLanguageServiceTest teardown left work RUNNING:
   teardown DIRTY — 1 pooled I/O leaf(s) still running, async dispose queue drained.
     at MonolithMeshTestBase.DisposeAsync() : MonolithMeshTestBase.cs(1621,0)
   [DISPOSE] Mesh.Disposal completed in 30043ms — teardown DIRTY — 1 pooled I/O leaf(s) still running
   

   Run: https://github.com/Systemorph/MeshWeaver/actions/runs/33308671083/job/99250133646 · commit e0cd6e9f5 · 11:28:39Z.

   Attribution evidence, so the next reader does not have to redo it

   • The same src passed this shard 20 minutes earlier. fix(#2742): a permission fold that terminates without a verdict is Undetermined, not an ALLOW (both gates) #2760's commit eace590e carries every src change in that PR and Run tests (shard 2) was success; the red commit e0cd6e9f5 differs from it by three files in test/MeshWeaver.Security.Test/ only — a different assembly from MeshWeaver.Hosting.Monolith.Test.
   • The test itself PASSES. === TEST END === is logged with no assertion failure; only the class DisposeAsync fails, 30 s later. Whatever the leaf is, it is not the completion assertion.
   • 20 local runs, zero reproductions, split evenly across the PR branch and main (be39fc607) — single test ×5 each, and the whole class under DOTNET_PROCESSOR_COUNT=4 ×5 each. It does not reproduce on this Mac even under the repo's usual CI-race lever, which reinforces that the trigger is shard-level load rather than anything in the class.

   Still unnamed

   Consistent with the note in the title, this occurrence still does not name the pool. The only IoPool stack in the shard log belongs to MeshWeaver.Hosting.Test's FileSystemStorageAdapter.WriteAtomic diagnostic — a different, passing project — so it is not evidence about this leaf. Whatever #2665 was expected to surface did not appear here either.

   Cost recorded: this is now a second PR blocked by this flake — a security fix (a live authorization bypass) held out of main behind it, in a window where merge slots are being rationed because CD is starving.

   🤖 Generated with Claude Code
7. rbuergi commented on Aug 30, 2026

   

   rbuergi

   on Aug 30, 2026

   ContributorAuthor

   More actions

   Third occurrence, 2026-08-30 12:48Z on #2766 (shard 1) — and this time the pool IS named

   Run https://github.com/Systemorph/MeshWeaver/actions/runs/33312105107/job/99259302099 · commit 664494d6b (a PR whose diff is deploy/homebrew/**, .github/workflows/homebrew.yml, docs and two doc-test guards — nothing that can reach a script-completion test; main's last three Build-and-Test runs 0c584a2d, d9ef9503, d1a82597 are green).

   Same signature: the test passes (=== TEST END … ScriptCompletions_FilterByTypedPrefix_NotJustTheAlphabet === at 12:48:27.592, no assertion), Mesh.Dispose() runs the full 30 s drain, DisposeAsync throws teardown DIRTY — 1 pooled I/O leaf(s) still running.

   #2665's naming did fire — in the trace artifact, not the job's stdout, which is why the previous occurrence read it as absent. testResults-shard1/collected-logs/_meshweaver-test-trace.log:

   12:48:57.619 pid=3447 [MeshNodeLanguageServiceTest] DISPOSE_IOPOOL_DRAIN_DONE elapsed=30024ms leakedIoLeaves=1 pools=[Query=1]
   

   So the leaf that outlives the drain is on the Query pool — a MeshQuery / IMeshService.Query leaf, not the script-completion/reference build #2598 touched (that runs on the compile lane). teardown-stragglers.log captured nine first-chance exceptions in this shard, at 12:46:46 and 12:50:44–50 — none inside the 12:48:27–12:48:57 window, so the Query leaf never threw: it is parked, not faulting. The MeshQuery.MergeProviderObservables frames that do appear in the other captures ride Observable.FromAsync/StartAsync (MeshQuery.cs:554/612), which is the shape a leaf that cannot observe cancellation would have.

   Next reader: the search is now bounded to the Query pool's leaves that MeshNodeLanguageServiceTest's completion path opens (Admin/Partition/script and script/Prefix node-type sources are created in the test output right before the completion) and that do not join on the mesh's teardown token within 30 s.
8. rbuergi

   added a commit that references this issue on Aug 30, 2026

   fix(#2616): the script reference set must not freeze the assembly list (

   ...

   ead524e
9. rbuergi

   closed this as completedin #2769on Aug 30, 2026