RoutingGrain routing pool exhausted by slow dispatch legs — 51 of 64 in-flight dispatches waiting on a pool slot, oldest leg 26s #5261

Activity

1. systemorph-com

   added

   bugSomething isn't workingSomething isn't working

   sev:HBLOCKING: primary path broken, intermittent user-visible failure, or silently wrong results.BLOCKING: primary path broken, intermittent user-visible failure, or silently wrong results.

   on Sep 22, 2026
2. rbuergi commented on Sep 22, 2026

   

   rbuergi

   on Sep 22, 2026

   Contributor

   More actions

   #5261 is not a recurrence of #5009 — and it is #5009's first post-roll POSITIVE reading

   #5261's body offers that it "may simply be a production recurrence of #5009". Its own log text refutes that, using the discriminator #5009 comment 3 fixed in advance: "a line still spelling deepest per-destination queue is a PRE-FIX REPLICA, not a result" — #5151 renamed the field.

   • RoutingGrain routing pool exhausted by slow dispatch legs — 51 of 64 in-flight dispatches waiting on a pool slot, oldest leg 26s #5261's line spells the POST-fix wording: ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0. Incident 2026-09-22T17:45:19Z, pod memex-portal-deployment-5c99d79997-xs87x, namespace memex.
   • Denominator: RoutingGrain dispatch slots saturate with legs head-of-line blocked behind one shared-cache destination while the second pod starves on load #5009 carries 155 occurrences across its bot updates plus 17 in its body, and every sample text quoted on that thread — including the newest, 07:00:24Z — spells per-destination. RoutingGrain dispatch slots saturate with legs head-of-line blocked behind one shared-cache destination while the second pod starves on load #5009 comment 22 records that an incident-store search for per-channel queue / ordered channels queued found no hit anywhere. RoutingGrain routing pool exhausted by slow dispatch legs — 51 of 64 in-flight dispatches waiting on a pool slot, oldest leg 26s #5261 is 1 of 1 carrying the post-fix spelling.

   So on that replica the head-of-line queueing is gone: 0 channels queued over 0 destinations, deepest 0. That is the positive signal #5151 has been missing, and it is the first one on file.

   And in-flight still reached 64 anyway — for a different reason. #5261's own gauges: waiting for a pool slot 51, subscribing 0, deepest 0, oldest leg 26,372 ms, that leg's target Ops/Logs/memex-cloud-…-v7q45. By the log line's own rubric ("High [waiting] while subscribing is below the pool's cap is a THREAD shortage") this reads as the unbounded pre-subscribe wait the slot is held across — not a too-coarse channel key.

   🚨 So deduping #5261 into #5009 would destroy the only post-roll positive sample on file. They are two defects that raise the same gauge, which is exactly the trap of reading a symptom gauge as an identity.

   Not excluded, and worth the next session's first hour: a slot that is never decremented. Core #5281 (f2f00c9db4, merged 18:35:15Z) fixed precisely the class "a pooled leaf holds a permit across work that cannot observe its token" — in OrleansRoutingService.cs, the same file family — so that shape was live today rather than speculative. It is not this fix: it touches the teardown unsubscribe leaf, not the routing dispatch leg or the pool's slot accounting, and it merged 50 minutes after the #5261 incident, so that pod cannot have carried it. The place to start is its new guard, test/MeshWeaver.Documentation.Test/PooledLeafObservesItsTokenGuard.cs — does its sweep cover the routing dispatch leg?

   What is NOT established here: none of this was read from code. The channel key's construction, the pool's cap, and whether any path fails to release a slot are all unverified — the above is the issue record plus #5261's own instrument reading, with no control run and no two-sided verification. #5037 and #2299 were not examined at all.

   🤖 Generated with Claude Code
3. rbuergi commented on Sep 22, 2026

   

   rbuergi

   on Sep 22, 2026

   Contributor

   More actions

   Read against the code: the 51 waiters are ThreadPool work items that had not started, not legs waiting for a pool slot that was taken

   Picking up the 19:06Z comment's open question ("the pool's cap, and whether any path fails to release a slot are all unverified"). Read from main at f2f00c9db4:

   1. The pool is not small. This body says "only ~13 slots existed". The Routing pool's cap is 256 (IoPoolOptions.Routing, src/MeshWeaver.Mesh.Contract/Threading/IoPoolOptions.cs). Nothing in the line measures 13; that number is 64 − 51.

   2. What the two gauges count, in IoPool.SubscribeThroughPoolCore:

   • waiting for a pool slot = _waiting: incremented at SUBSCRIBE, decremented when the setup leaf gets past _gate.WaitAsync (or is cancelled/unsubscribed first — every exit path calls LeaveWaitOnce, exactly once, latch-guarded).
   • routing pool subscribing = _inFlight: incremented only after the gate grants, decremented in ReleaseGate() as soon as source.Subscribe(observer) returns.
   • The setup leaf is Observable.FromAsync(…).SubscribeOn(TaskPoolScheduler.Default) — it cannot reach the gate until the ThreadPool runs it.

   So subscribing 0 with waiting 51 and a 256-permit gate means no permit was held and 51 setup leaves had not yet been run by the ThreadPool. A leaked permit is excluded by the same reading: a leaked one would have to have been taken by a leaf that incremented _inFlight, and ReleaseGate is in a finally. The routing-side slot (inFlightRoutes) is a counter only — nothing throttles, queues or refuses on it (ReportSaturation's own doc) — so it cannot be what the 51 are waiting for.

   Verdict: thread shortage on pod xs87x at 17:45:19Z, exactly the rubric's "High while subscribing is below the pool's cap is a THREAD shortage". That root — what starves the ThreadPool — is being worked separately as the starvation investigation, not here.

   3. The 26 s oldest leg is a separate reading and is not a leak. dispatch → Ops/Logs/memex-cloud-…-v7q45 is a grain route (Dispatch, not the ordered stream branch) to a Hosting/LogEntry node — i.e. a node a Logs InstanceAction on the control instance had just landed. Such a leg is bounded by ResolveTimeout (30 s) plus the grain call's own retries, so 26 s is inside its bounds; with the ThreadPool short it is also consistent with the leg itself waiting for a thread. Worth knowing when reading any future sample: a Logs action writes a burst of fresh nodes whose first messages each activate a per-node hub, on the same silo the reading was taken from.

   4. The flood half. This incident's fingerprint split from its siblings not on the episode stamp but on the oldest-leg label's delivery id and single-segment destination, which the normaliser did not mask. Fixed in Systemorph/MeshWeaver.Plugins#2286 (measured over the 146 back-pressure samples in the open core issues: 43 filed fingerprints → 3).

   Status: open, owner-side. Nothing in core's routing code is implicated by this sample. What would close it is the starvation root and a post-fix reading; the one read that attributes this particular episode is a Logs InstanceAction (not mine to run):

   { "requestedAction": "Logs", "deployment": "Deployments/memex", "query": "LocalSiloHealthMonitor", "sinceMinutes": 360 }

   — a thread-pool-delay / "has not been responsive" line on memex-portal-deployment-5c99d79997-xs87x around 17:44–17:46Z confirms the verdict above; its absence would leave the 51 unexplained and should be written back here.

   What I did NOT establish: I ran no Logs read, have no dump of that pod, and did not find what blocked the threads. I did not check whether a second line (clear or higher episode) for activation 1f8bc242 followed.
4. rbuergi commented on Sep 22, 2026

   

   rbuergi

   on Sep 22, 2026

   Contributor

   More actions

   Closing as a duplicate of #5118 — the fingerprint-split flood.

   Why this is a duplicate. Every one of these comes from the same log site — [ROUTE] Routing back-pressure, category MeshWeaver.Hosting.Orleans.RoutingGrain — split into one issue per grain activation. The 8-hex activation id survived normalization (a0e2984b → a0e2{n}b): HexBlob required 16+ chars, and Number() then masked only the digit-run preceded by a digit, leaving a per-activation residue in the hash.

   Measured over 101 verbatim bursts drawn from 29 issues, covering 42 activation ids: the old parser yields 41 distinct fingerprints, the current parser yields 1.

   The fix is already merged in MeshWeaver.Plugins — #2165 (MixedHexId), #2167, #2168 (positional episode/target masking) and #2218 (the portal re-parses raw samples, instead of hashing text a stale watcher already masked).

   It is not live yet. The control instance is sealed on an older set because the Plugins Portal image rebuild workflow fails at its GitHub App token step — actions: write is not granted to the installation — so core's rebuild is never dispatched. Until that is granted, new split issues will keep arriving, and an issue whose activation is still alive may reopen here.

   Not closed by this. The underlying routing condition — cache-destination head-of-line blocking versus ThreadPool starvation — is a real defect and stays open in #5118. The normaliser itself is tracked in #5270 and #5271.
5. rbuergi

   closed this as not plannedon Sep 22, 2026