Skip to content

Route dispatch saturation on portal/reads channels: burst drains in seconds but still mints a per-stamp Critical incident — normaliser masking rule still missing #5593

Closed as not planned

Description

@systemorph-com

What is failing. The core RoutingGrain (MeshWeaver.Hosting.Orleans, silo memex) is hitting its 64-in-flight route-dispatch saturation threshold, with the backlog concentrated head-of-line in one or two ordered channels toward the portal/reads stream destinations (deepest per-channel queue 52–62). This is a recurrence of the already-tracked routing-saturation family: core issue #5009 (head-of-line verdict, fixed by core PR 5151, awaiting production verification), #5018 (load verdict), and #5118 (the alert flood).

Probable cause — two layers, with confidence.

  1. This burst reads as absorbed load, not a leak (high confidence, from the samples): the oldest leg in flight is 27 ms–2.7 s on every line, episodes on the same activation (506f05fc moved canEdit and canRun permissions to props #6→[Snyk] Upgrade react-dropzone from 12.0.5 to 12.1.0 #9, e9f417e5 Determine back-end contributors #3) advance across the 33 s window — i.e. each episode drained — routing pool subscribing 0, waiting for a pool slot 0–1, and the dispatch legs are _Activity/compile-* script executions fanning out to portal/reads streams. No leg is minutes old, so no slot leak is visible here.
  2. Why this is still an open defect (medium confidence): the log-watch filer's message normaliser still has no masking pattern for the [activation#episode started timestamp] identity group inside the message, so one recurring condition mints a fresh Critical incident per crossing instead of folding. The Admin partition holds 50+ distinct RoutingGrain back-pressure LogIncidents from today alone (16:00–20:00 UTC), each with its own fingerprint — this one being yet another. A full analysis with the per-issue measurements was handed over 2026-09-21 in the mesh at rbuergi/Feedback/route-backpressure-fingerprint-splits-20260921-2236 and evidently has not landed. The long diagnostic text the log line now carries (it self-describes the verdicts for issues RoutingGrain dispatch slots saturate with legs head-of-line blocked behind one shared-cache destination while the second pod starves on load #5009/RoutingGrain dispatch pool saturates repeatedly on portal silos; slots held through unbounded ThreadPool wait and episode-stamp splitting floods incidents #5018) also inflates every occurrence.

Impact. Two portal pods, 10 occurrences in 33 s on top of hours of identical episodes — user-visible latency on portal/reads streams of at most a few seconds while the bursts drain, no evidence of stuck legs in this incident. The material harm is operational: dozens of near-identical Critical incidents per day bury any genuine slot-leak signal (issue #5118's own stated worry) and flood the incident stream.

Where to look. Emission site: src/MeshWeaver.Hosting.Orleans/RoutingGrain.cs, method ReportSaturation (per the mesh feedback above; source not readable from this partition). The fix for the flood is the normaliser pattern masking [activation#episode started timestamp], so recurrences fold onto one incident whose occurrence count becomes the signal — the log line itself is deliberately diagnostic and should stay. If this ticket is judged a duplicate of #5009/#5018/#5118 consolidation, close it against those — the masking-gap argument in the feedback node is the only new evidence here.


Evidence

Fingerprint 1bf5bed7965fbb13
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex
Pods memex-portal-deployment-56fbdcd48f-4dpcn, memex-portal-deployment-56fbdcd48f-sz5st
Occurrences 10
First seen 2026-09-23 19:59:20Z
Last seen 2026-09-23 19:59:53Z
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-23 19:59:36Z memex-portal-deployment-56fbdcd48f-4dpcn crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [506f05fc#6 started 2026-09-23T19:59:36.1976685Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 1 over 1 stream destination(s), deepest per-channel queue 52, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 2084 ms — dispatch → Manufacturing/MaintenancePlanner/_Activity/compile-20260923195923724072e90cfb4b64c5094997a149d70bdc2 (delivery pjQ-m0urskOCrsavliqGMQ). Latest dispatch target portal/reads-rqEHlOPNSkCV1G34WXuQ9A — 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 …[truncated]
2026-09-23 19:59:37Z memex-portal-deployment-56fbdcd48f-sz5st crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [e9f417e5#3 started 2026-09-23T19:59:37.3353671Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 2 over 2 stream destination(s), deepest per-channel queue 62, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 1133 ms — stream-routed → portal/reads-jll3sSZfx061jLrYC3JaUA (delivery LA5W2M1fYUizY2XnmaP_lQ). Latest dispatch target portal/reads-jll3sSZfx061jLrYC3JaUA — 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 …[truncated]
2026-09-23 19:59:43Z memex-portal-deployment-56fbdcd48f-4dpcn crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [506f05fc#7 started 2026-09-23T19:59:43.3475683Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 1 over 1 stream destination(s), deepest per-channel queue 60, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 1731 ms — dispatch → Manufacturing/Customer/_Activity/compile-20260923195924035cccea18a26b744fca413153050f288d8 (delivery nn5YSGdyyUG8DvCRAihNqA). Latest dispatch target portal/reads-rqEHlOPNSkCV1G34WXuQ9A — 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 l…[truncated]
2026-09-23 19:59:50Z memex-portal-deployment-56fbdcd48f-4dpcn crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [506f05fc#8 started 2026-09-23T19:59:50.7379258Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 1 over 1 stream destination(s), deepest per-channel queue 62, routing pool subscribing 0, waiting for a pool slot 0; oldest leg in flight 27 ms — dispatch → Hosting/Issue/_Activity/compile-20260923195938239fd7402304963494290814a9fdf7a3ad4 (delivery zCfR02EJ6kG4kBw9orN_dQ). Latest dispatch target portal/reads-rqEHlOPNSkCV1G34WXuQ9A — 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 …[truncated]
2026-09-23 19:59:53Z memex-portal-deployment-56fbdcd48f-4dpcn crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [506f05fc#9 started 2026-09-23T19:59:53.4119775Z]: 64 route dispatches in flight (reporting threshold 64); ordered channels queued 2 over 2 stream destination(s), deepest per-channel queue 58, routing pool subscribing 0, waiting for a pool slot 1; oldest leg in flight 2701 ms — dispatch → Hosting/Issue/_Activity/compile-20260923195938239fd7402304963494290814a9fdf7a3ad4 (delivery zCfR02EJ6kG4kBw9orN_dQ). Latest dispatch target portal/reads-rqEHlOPNSkCV1G34WXuQ9A — 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 sa…[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/1bf5bed7965fbb13. 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 23, 2026
  2. rbuergi commented on Sep 23, 2026

    @rbuergi
    Contributor

    Duplicate of #5118 — same log site: MeshWeaver.Hosting.Orleans.RoutingGrain ReportSaturation ([ROUTE] Routing back-pressure [<activation>#<episode> started …]). The body's own gauge reading (young oldest leg / episode stamps advancing / waiting for a pool slot vs subscribing) is the load or thread-shortage shape #5118 tracks; no new defect is evidenced. It was minted as a separate ticket only because the filer split the fingerprint per episode/cut — fixed in Systemorph/MeshWeaver.Plugins#2290 (fold onto the site issue) and #2325 (truncation-stable identity), live once memex.systemorph.com rolls onto a portal image containing plugins cfd0576631.

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