Skip to content

Portal routing grain saturates on slow EntityViews/AgenticOffice deliveries — dispatch legs held ~26s with all channel queues and pool gauges at zero #5374

Closed as not planned

Description

@systemorph

What is failing

The portal silo's MeshWeaver.Hosting.Orleans.RoutingGrain crossed its dispatch back-pressure threshold (64 legs in flight) twice within 43 seconds on the same grain activation (440d2a6b, episodes #1 and #2). In both crossings every channel queue is empty (deepest 0) and both routing-pool gauges — subscribing and waiting for a pool slot — are zero, which by the log line's own semantics means the legs are past their subscribe prologue and the wait is downstream I/O, not a thread or pool-slot shortage. The oldest leg grew from 7.7 s to 26.1 s between the two lines.

Probable cause

Moderate confidence: transient downstream slowness on the destinations named in the lines — dispatches toward EntityViews and AgenticOffice (pod hub deliveries) were holding their routing slots for tens of seconds with nothing queued behind them and nothing waiting upstream. This is the "load the silo is absorbing" shape, not the "slot never came back" leak shape: the oldest leg is 26 s, not minutes, and episode #2 starting means episode #1 ended. Cause of the downstream slowness itself is unclear from this evidence alone — no corresponding exception or refusal burst appears in the samples. It resembles the load verdict of core issue #5018 (see below).

Impact

Small so far: 2 occurrences in one minute on a single portal pod (memex-portal-deployment-…-2c25b). No evidence it is widespread. For the affected window, route legs toward EntityViews and AgenticOffice were delayed up to ~26 s — a short, intermittent user-visible latency spike for anything reading those views, and the routing slots were pinned so further dispatches could have queued behind them had the episode persisted.

Where to look

  • Report site: MeshWeaver.Hosting.Orleans.RoutingGrain.ReportSaturation (src/MeshWeaver.Hosting.Orleans/RoutingGrain.cs). The line itself explains its gauges — read it alongside Doc/Architecture/RouterTrafficDetection.
  • First check: whether a cleared after … ms line (or a higher episode) with activation 440d2a6b follows on this pod — if neither appears, this is a slot leak, not load, and the severity should be re-ruled upward.
  • Then the delivery legs toward EntityViews and AgenticOffice around 17:45–17:46 UTC on that pod, to find what held the oldest leg for 26 s.

Possibly known

This log site has history: core #5009 (head-of-line blocking, fixed via core PR 5151, awaiting production verification) and core #5018 (load verdict, consolidation carries the fingerprint-splitting measurement). This incident's shape — empty queues, zero pool gauges, young-but-growing oldest leg — is closest to #5018's load verdict and may be the same underlying condition resurfacing; a human should check #5018 before treating this as new. Related: feedback node rbuergi/Feedback/route-backpressure-fingerprint-splits-20260921-2236 documents that this site's episode stamps split fingerprints, so recurrences may already be scattered across other incidents.


Evidence

Fingerprint 4c1d4986bb5ccc85
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex-cloud
Pods memex-portal-deployment-857546649-2c25b
Occurrences 2
First seen 2026-09-22 17:45:17Z
Last seen 2026-09-22 17:46:00Z
Routing not determined — no configured route matches the category MeshWeaver.Hosting.Orleans.RoutingGrain. This repository is the configured fallback, not a finding about who owns the fault; the category names the LOGGER, which may not be the subject.
Recent log lines
2026-09-22 17:45:17Z memex-portal-deployment-857546649-2c25b crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [440d2a6b#1 started 2026-09-22T17:45:17.8622331Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 0 over 0 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 7732 ms — dispatch → EntityViews (delivery l8_b1me9PUm0DMYF3okJ4Q). Latest dispatch target Store/Provision — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly…[truncated]
2026-09-22 17:46:00Z memex-portal-deployment-857546649-2c25b crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [440d2a6b#2 started 2026-09-22T17:46:00.6127155Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 1 over 1 stream destination(s), deepest per-channel queue 0, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 26136 ms — dispatch → AgenticOffice (delivery semy8voOWUOKkJZH5zJE0Q). Latest dispatch target cache/JrlWjPZHp0C3Q2wuZIz-sQ — the address that happened to cross the threshold, NOT a diagnosis. A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck. A CHANNEL is (destination, stream), so a deepest queue of 1 or more means legs of the SAME stream are blocked behind one another (head-of-line within one channel); 0 means nothing is waiting on anything, so read it as load. Many channels over FEW destinations is a multiplexer hub draining in parallel, which is load too — before issue #5009 those legs shared one channel and read as head-of-line. 🚨 THE TWO POOL GAUGES ANSWER DIFFERENT QUESTIONS AND ONLY ONE SEES THE WAIT NAMED ABOVE — issue #5018. 'subscribing' counts legs inside their SUBSCRIBE PROLOGUE only, so a leg still waiting for a ThreadPool thread and a leg already past its subscribe BOTH read 0 there; 'waiting for a pool slot' is the gauge that sees the pre-subscribe wait. High while subscribing is below the pool's cap is a THREAD shortage; both near zero means the legs are past their subscribe and the wait is downstream I/O. 🚨 READ THE OLDEST LEG FIRST: it is the only load-vs-leak discriminator available from a SINGLE line — every leg young is load the silo is absorbing, one leg minutes old is a slot that never came back and the label names it — whereas the episode stamp below needs a SECOND line to say anything. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight co…[truncated]

Re-addressed by the current identity function: this incident inherited e4a97855ab595beb (Systemorph/MeshWeaver.Plugins#1796). Those nodes are superseded and will not fold, file or comment again.

Opened automatically from Admin/_LogIncident/4c1d4986bb5ccc85. Recurrences are folded into this issue rather than opening new ones.

Activity

  1. added
    bugSomething isn't working
    sev:MMedium - secondary path broken, or easy workaround
    on Sep 22, 2026
  2. rbuergi commented on Sep 22, 2026

    @rbuergi
    Contributor

    Why this is its own issue, and what stops the next one — posted on each RoutingGrain back-pressure incident issue filed 2026-09-22; not a disposition of this one.

    This incident's fingerprint was split from its siblings by two values the incident normaliser did not mask — the delivery id and a single-segment destination in the line's oldest leg in flight … — dispatch → <address> (delivery <id>) field — not by the episode stamp, which was already masked. Fixed in Systemorph/MeshWeaver.Plugins#2286 (merged 2026-09-22T21:46Z as b922f070fc): over the 146 back-pressure samples quoted in the open core issues (43 filed fingerprints), the identity now yields 3 (one per leg kind, plus the pre-#5151 wording). It reaches production with the portal roll; existing incidents re-address onto their successors through LogIncidentCorpusMigration.

    What the crossing itself means is a separate question and is not answered by the fix above. A line reading high waiting for a pool slot with routing pool subscribing 0 is legs the ThreadPool had not yet run (the pool's cap is 256 and no permit is held — see #5261 (comment)); that starvation root is being investigated separately (family: #5018, #4886). A line with a non-zero deepest per-channel queue on a cache/… destination and an old oldest leg is #5009's falsifier and should be raised there.

    Disposition stays with triage: a symptom gauge can invert the causal arrow, so this issue's own sample may carry evidence its siblings do not.

  3. rbuergi commented on Sep 23, 2026

    @rbuergi
    Contributor

    Duplicate of #5118.

    Build: pod(s) memex-portal-deployment-857546649-2c25b. ReplicaSet 857546649 runs 3da3423c / 3.0.0-ci.9193, which does not contain the compile-off-ThreadPool fix (#5327/#5375) (read from Ops/Status/memex-cloud version 3130).

    Window 2026-09-22 17:45:17Z → 2026-09-22 17:46:00Z, 2 occurrence(s), fingerprint 4c1d4986bb5ccc85.

    activation#episode started waiting subscribing deepest channels / dest oldest leg
    440d2a6b#1 17:45:17Z 0 0 0 0 / 0 7732 ms
    440d2a6b#2 17:46:00Z 0 0 0 1 / 1 26136 ms

    This issue's own discriminator: load with legs past subscribe (L): waiting 0, subscribing ≤ 1. The oldest leg is at most 26136 ms, so no leg is minutes old and no slot leaked. Episodes keep advancing on the same activation (440d2a6b), so each episode drained. It is the same log site and the same reading, sampled on the build without the fix. The cause, the fix, and the verification after memex rolls are recorded on #5118.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingsev:MMedium - secondary path broken, or easy workaround

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions