Skip to content

Portal RoutingGrain repeatedly saturates its 64-dispatch threshold, with head-of-line queuing on cache/ stream destinations #4942

Closed as not planned

Description

@systemorph-com

What is failing

The portal's RoutingGrain repeatedly hit its reporting threshold (64 route dispatches in flight) across all three pods of the memex-cloud namespace. On one pod nothing was actually blocked (deepest per-destination queue 0 — pure load), but on others 62 of the 64 legs were queued behind a single destination (cache/... streams) — a genuine head-of-line blockage on one route leg.

Probable cause

Medium confidence, from the numbers rather than a stack: one destination's leg was slow to terminate, and its per-destination queue held 62 legs while it finished. The episode stamps incremented monotonically on the same activations (#11 → #12 → #13; #1 → #4), which per the alert's own semantics means each episode drained — a recurring-but-cleared blockage, not a leaked slot. The samples with deepest queue 0 on other pods are consistent with general CPU pressure at the same instant (a slot includes the unbounded ThreadPool wait before the leg's own timeouts start). Cause unclear beyond that: whether the blocked cache/... destination was slow by defect or by load cannot be determined from these lines. This same log site has fired ~50 times across incidents since 2026-09-19, so it is a recurring systemic condition, not a one-off.

Impact

Limited per window, but recurring: 9 critical lines over ~13 minutes on all 3 pods, every episode apparently drained; no evidence of user-visible outage, at most transiently delayed dispatches to the affected destination. The pattern's recurrence over the past day is what warrants attention.

Where to look

MeshWeaver.Hosting.Orleans.RoutingGrain — the per-destination queue handling and leg termination path. Start from the routing-alert semantics notes (Doc/WhatsNew/2026-08-12-routing-alerts-name-what-they-actually-saw) describing how slots and episode stamps work, and the 2026-09-16/17 changes that moved agent/editor/recycle traffic off the portal's routing. If this recurs, check whether the cache/... destination's legs have their own timeouts.


Evidence

Fingerprint e50e711170bb232f
Category MeshWeaver.Hosting.Orleans.RoutingGrain
Severity Critical
Namespace memex-cloud
Pods memex-portal-deployment-69956b6dbc-s246c, memex-portal-deployment-69956b6dbc-gx6z6, memex-portal-deployment-69956b6dbc-ndnxt
Occurrences 9
First seen 2026-09-20 00:35:47Z
Last seen 2026-09-20 00:48:48Z
Recent log lines
2026-09-20 00:35:47Z memex-portal-deployment-69956b6dbc-s246c crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [26c5da8a#1 started 2026-09-20T00:35:47.4708967Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 0, deepest per-destination queue 0, routing pool subscribing 0. Latest dispatch target ILS/Journal — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:35:47Z memex-portal-deployment-69956b6dbc-gx6z6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [25882269#11 started 2026-09-20T00:35:47.4949508Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 1, deepest per-destination queue 62, routing pool subscribing 0. Latest dispatch target cache/YORFhwiyqEyTP9ESF-NUNg — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:35:47Z memex-portal-deployment-69956b6dbc-gx6z6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [25882269#12 started 2026-09-20T00:35:47.8094199Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 1, deepest per-destination queue 62, routing pool subscribing 0. Latest dispatch target cache/12xX8OXQIEmdwvf_ZZ8LjA — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:40:09Z memex-portal-deployment-69956b6dbc-s246c crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [26c5da8a#2 started 2026-09-20T00:40:09.9347818Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 1, deepest per-destination queue 62, routing pool subscribing 0. Latest dispatch target cache/12xX8OXQIEmdwvf_ZZ8LjA — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:40:10Z memex-portal-deployment-69956b6dbc-ndnxt crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [e32409d1#23 started 2026-09-20T00:40:10.1273608Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 0, deepest per-destination queue 0, routing pool subscribing 0. Latest dispatch target Underwriting/Decision — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:40:10Z memex-portal-deployment-69956b6dbc-gx6z6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [25882269#13 started 2026-09-20T00:40:10.1458508Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 1, deepest per-destination queue 62, routing pool subscribing 0. Latest dispatch target cache/12xX8OXQIEmdwvf_ZZ8LjA — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:40:28Z memex-portal-deployment-69956b6dbc-s246c crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [26c5da8a#3 started 2026-09-20T00:40:28.8066793Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 0, deepest per-destination queue 0, routing pool subscribing 1. Latest dispatch target Reinsurance/Broker — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:40:28Z memex-portal-deployment-69956b6dbc-gx6z6 crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [11336d01#1 started 2026-09-20T00:40:28.8282488Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 1, deepest per-destination queue 62, routing pool subscribing 0. Latest dispatch target cache/YORFhwiyqEyTP9ESF-NUNg — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.
2026-09-20 00:48:48Z memex-portal-deployment-69956b6dbc-s246c crit: MeshWeaver.Hosting.Orleans.RoutingGrain[0]
      [ROUTE] Routing back-pressure [26c5da8a#4 started 2026-09-20T00:48:48.8058671Z]: 64 route dispatches in flight (reporting threshold 64); stream destinations queued 0, deepest per-destination queue 0, routing pool subscribing 0. Latest dispatch target Ifrs17/CreditRiskRating — 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 deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load. 🚨 Deepest is sampled AT THE CROSSING, so like the in-flight count it is partly an artefact of the threshold: with N destinations sharing the backlog it is ~InFlight/N whatever is wrong. READ THE EPISODE STAMP, not the depth: a later line with a HIGHER episode on this activation means this episode drained; a line with a DIFFERENT activation id means the grain was recycled; and if neither a clear nor a higher episode ever follows, the in-flight count never fell below half the threshold — which means a leg never terminated and its slot leaked, not that the silo was busy.

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/e50e711170bb232f. Recurrences are folded into this issue rather than opening new ones.

Activity

  1. rbuergi commented on Sep 20, 2026

    @rbuergi
    Contributor

    Closing as a duplicate of #4904, which stays open and carries the real condition.

    This is one of 12 issues filed from the same RoutingGrain back-pressure log line between 2026-09-19 20:05Z and 2026-09-20 05:14Z — roughly one an hour, overnight. They are not 12 events. They are one sentence whose Orleans activation id is unnormalized on the deployed log-watcher, so every activation mints a fresh fingerprint and every fingerprint files its own ticket. This one records Occurrences: 1, which is the signature.

    Measured yesterday 19:25Z on the control instance: 86 distinct fingerprints for this single line, all created that day, which had already produced 62 GitHub issues (59 hand-closed as duplicates). The normalizer that folds them is merged in MeshWeaver.Plugins (LogLineParser.cs, with tests built from the very issue numbers this line filed) and has not been rolled. Detail and the delivery blocker: Systemorph/MeshWeaver.Plugins#2156.

    🚨 The underlying condition is real and is NOT being dismissed. These episodes report a non-zero deepest queue — 62 legs behind a single cache/… destination — and by the log line's own rule that is head-of-line blocking, not load:

    "A deepest queue of 1 or more means legs are blocked behind a leg (head-of-line on one destination); 0 means nothing is waiting on anything, so read it as load."

    That is exactly why #4904 was left open rather than closed with the load-shaped reports. The engineering question — why route legs pile up behind one cache destination — belongs there, in one place, with all the samples.

    If this particular report carries something #4904 does not, reopen it: closed on fingerprint identity and an identical stated mechanism, not on a judgement that the fault is uninteresting.

  2. rbuergi commented on Sep 20, 2026

    @rbuergi
    Contributor

    Duplicate of #4908 — one of twelve filed for the same log site between 20:05Z and 05:14Z, which was the whole of core's overnight issue growth.

    They are one fault, not twelve. The normalized message that keys each fingerprint still carries the activation id partly masked — the hex mask replaces digit runs and leaves letters, so 8977c61d becomes {n}c6{n}d and every activation mints its own fingerprint. An all-digit id collapses to {n}#{n}; one beginning with a letter is not masked at all. A search of this category returns 25 back-pressure fingerprints, truncated at the limit.

    Also worth recording: these tickets were split from one another on the deepest-per-destination-queue value, and the log line explicitly forbids reading it that way — "Deepest is sampled AT THE CROSSING … READ THE EPISODE STAMP, not the depth." A single fingerprint holds both faces in its own samples, minutes apart on one activation.

    Its incident node Admin/_LogIncident/e50e711170bb232f has been repointed to #4908, so the next occurrence comments there instead of reopening this — a close alone is undone within the hour, because LogIncidentFiler.Reopen reads closed_at and never state_reason.

    The fingerprint fix is on MeshWeaver.Plugins main and is not live: normalization runs on the log watcher, which nothing rolls. Full analysis and the episode-stamp reading are on #4908.

    🤖 Generated with Claude Code

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 working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions