Orleans grain placement for routing/default times out under cluster load, dropping all default-routed mesh messages #5037

Activity

1. systemorph

   added

   bugSomething isn't workingSomething isn't working

   on Sep 20, 2026
2. rbuergi commented on Sep 21, 2026

   

   rbuergi

   on Sep 21, 2026

   Contributor

   More actions

   Consolidation: #4672 closed into this ticket — same placement timeout, different grain and day

   #4672 is this defect three days earlier against a different target: Orleans.Runtime.Placement.PlacementService.PlacementWorker.ExecutePlacementAsync (PlacementService.cs:602) exceeding its 30-second Polly timeout, with the identical exception chain TimeoutException → TimeoutRejectedException → TaskCanceledException, so IMessageHubGrain.DeliverMessage never reaches the grain. Migrating it:

   • The 2026-09-17 instance: 8 occurrences over ~60 seconds, pod memex-portal-deployment-6c967c7c4c-kdff5, namespace memex, from the hosted client sys.client/hosted-10.244.3.244:11111, all for one grain — messagehub/UWDeepfield/_Activity/1851e7d7. One activity's messages were dropped for about a minute; users of that activity would have seen stalled updates.
   • The discriminating detail: placement timed out for exactly one grain while the pod itself stayed up. That is a different shape from this ticket's 331-delivery burst against routing/default under cluster-wide stress, and it narrows the candidates — either the target silo could not answer placement/directory lookups for that one grain (it was being activated or was blocked at that moment), or transient membership churn at 18:37–18:38Z. Orleans grain placement times out for a single activity message-hub grain, blocking DeliverMessage #4672 also raises a lead this ticket does not: a Recycle on the hub forces re-activation, which can interact with placement — worth correlating recycles against placement timeouts.
   • What neither establishes: why the placement worker's queue is not draining. Both stop at Orleans internals; neither has silo-side placement counters.

   Three tickets at this boundary, deliberately kept apart

   • This one — the placement worker times out (30 s) and the message is dropped. ExecutePlacementAsync.
   • Silo shutdown drops in-flight MessageHub deliveries during rolling deploys (Orleans placement fails with SiloUnavailableException) #4961 — the placement target is a silo that is shutting down (SiloUnavailableException: Silo … is shutting down, GetOrPlaceActivationAsync → MessageCenter.AddressAndSendMessage, ForwardCount=1). Expected churn during a rolling deploy; the open question there is whether MeshWeaver retries.
   • Orleans placement retries during transient silo unavailability in memex-portal pods #4890 — Polly retrying placement through transient unavailability (OrleansMessageRejectionException, ConnectionFailedException, SocketConnectionException), 60 occurrences, recovering.

   They share a subsystem and a window, not a fix. The product question all three raise — is a dropped DeliverMessage surfaced to the sender or retried at the MeshWeaver level? — is the thing worth answering once, and #4961 is where it is stated most directly.

   _{Severity assigned per Doc/Architecture/IssueTaxonomy: sev:M. 331 deliveries lost in one burst is serious, but every frame is Orleans-internal and both tickets read it as a symptom of cluster stress rather than a defect with an owner in src/. 🚨 If application-level message loss is confirmed — a delivery dropped with no failure visible to the sender — this is sev:H, and the check for that is cheap.}
3. rbuergi

   added

   area:orleansCore subsystem: the Orleans silo - grains, placement, routingCore subsystem: the Orleans silo - grains, placement, routing

   feature:message-deliveryFeature: message deliveryFeature: message delivery

   sev:MMedium - secondary path broken, or easy workaroundMedium - secondary path broken, or easy workaround

   on Sep 21, 2026
4. systemorph commented on Sep 21, 2026

   

   systemorphBot

   on Sep 21, 2026

   ContributorAuthor

   More actions

   Still occurring: 89 more since the last update (420 total).

   • Last seen: 2026-09-20 22:25:30Z
   • Pods: memex-portal-deployment-75b545bbd-nssvp, memex-portal-deployment-75b545bbd-gwrc6, memex-portal-deployment-6b7c4f94db-zzvfq

   Recent log lines

   2026-09-20 22:25:29Z memex-portal-deployment-75b545bbd-gwrc6 fail: Orleans.Messaging[100071]
         Failed to address message Request [S10.244.9.104:11111:148947670 sys.client/hosted-10.244.9.104:11111@148947670]->[ messagehub/MyAi/_Activity/import-07d0621ce97bcc96-20260920222449088-c7bd3ee3] MeshWeaver.Connection.Orleans.IMessageHubGrain.DeliverMessage(MeshWeaver.Messaging.IMessageDelivery) #43DCEF65C874B2AB
         System.TimeoutException: Grain placement operation timed out for grain messagehub/MyAi/_Activity/import-07d0621ce97bcc96-20260920222449088-c7bd3ee3.
          ---> Polly.Timeout.TimeoutRejectedException: The operation didn't complete within the allowed timeout of '00:00:30'.
          ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.ExecutePlacementAsync(PlacementContext context, CancellationToken cancellationToken) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 602
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.<ExecutePlacementOutcomeAsync>g__AwaitOutcome|21_0(ValueTask`1 pending) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 576
            --- End of inner exception stack trace ---
            at Polly.Utils.ExceptionUtilities.TrySetStackTrace[T](T exception)
            at Polly.Timeout.TimeoutResilienceStrategy.ExecuteCore[TResult,TState](Func`3 callback, ResilienceContext context, TState state)
            at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
            at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
            at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
            at Polly.Retry.RetryResilienceStrategy`1.ExecuteCore[TState](Func`3 callback, ResilienceContext context, TState state)
            at System.Th…[truncated]
   2026-09-20 22:25:29Z memex-portal-deployment-75b545bbd-gwrc6 fail: Orleans.Messaging[100071]
         Failed to address message Request [S10.244.9.104:11111:148947670 sys.client/hosted-10.244.9.104:11111@148947670]->[ messagehub/MyAi/_Activity/import-07d0621ce97bcc96-20260920222449088-c7bd3ee3] MeshWeaver.Connection.Orleans.IMessageHubGrain.DeliverMessage(MeshWeaver.Messaging.IMessageDelivery) #43DCEF65C874B2F9
         System.TimeoutException: Grain placement operation timed out for grain messagehub/MyAi/_Activity/import-07d0621ce97bcc96-20260920222449088-c7bd3ee3.
          ---> Polly.Timeout.TimeoutRejectedException: The operation didn't complete within the allowed timeout of '00:00:30'.
          ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.ExecutePlacementAsync(PlacementContext context, CancellationToken cancellationToken) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 602
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.<ExecutePlacementOutcomeAsync>g__AwaitOutcome|21_0(ValueTask`1 pending) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 576
            --- End of inner exception stack trace ---
            at Polly.Utils.ExceptionUtilities.TrySetStackTrace[T](T exception)
            at Polly.Timeout.TimeoutResilienceStrategy.ExecuteCore[TResult,TState](Func`3 callback, ResilienceContext context, TState state)
            at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
            at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
            at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
            at Polly.Retry.RetryResilienceStrategy`1.ExecuteCore[TState](Func`3 callback, ResilienceContext context, TState state)
            at System.Th…[truncated]
   2026-09-20 22:25:30Z memex-portal-deployment-75b545bbd-gwrc6 fail: Orleans.Messaging[100071]
         Failed to address message Request [S10.244.9.104:11111:148947670 sys.client/hosted-10.244.9.104:11111@148947670]->[ messagehub/Video/_Activity/import-cd01f53d0f1991fe-20260920222449585-fc3435e7] MeshWeaver.Connection.Orleans.IMessageHubGrain.DeliverMessage(MeshWeaver.Messaging.IMessageDelivery) #43DCEF65C874B245
         System.TimeoutException: Grain placement operation timed out for grain messagehub/Video/_Activity/import-cd01f53d0f1991fe-20260920222449585-fc3435e7.
          ---> Polly.Timeout.TimeoutRejectedException: The operation didn't complete within the allowed timeout of '00:00:30'.
          ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.ExecutePlacementAsync(PlacementContext context, CancellationToken cancellationToken) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 602
            at Orleans.Runtime.Placement.PlacementService.PlacementWorker.<ExecutePlacementOutcomeAsync>g__AwaitOutcome|21_0(ValueTask`1 pending) in /_/src/Orleans.Runtime/Placement/PlacementService.cs:line 576
            --- End of inner exception stack trace ---
            at Polly.Utils.ExceptionUtilities.TrySetStackTrace[T](T exception)
            at Polly.Timeout.TimeoutResilienceStrategy.ExecuteCore[TResult,TState](Func`3 callback, ResilienceContext context, TState state)
            at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
            at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
            at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
            at Polly.Retry.RetryResilienceStrategy`1.ExecuteCore[TState](Func`3 callback, ResilienceContext context, TState state)
            at System.…[truncated]
   

   _{Re-addressed by the current identity function: this incident inherited c4e121bf40d7f9f6 (Systemorph/MeshWeaver.Plugins#1796). Those nodes are superseded and will not fold, file or comment again.}
5. rbuergi commented on Sep 21, 2026

   

   rbuergi

   on Sep 21, 2026

   Contributor

   More actions

   Disposition: downstream of a silo-level stall — and deliberately NOT folded into #4886

   Reviewed as part of the RoutingGrain saturation cluster. Full grouping and evidence:
   #5018 (comment).

   This ticket's own reading holds. The failure is in
   PlacementService.PlacementWorker.ExecutePlacementAsync — Orleans runtime work, on the silo's own
   ThreadPool, before RoutingGrain exists to run anything. routing/default is the grain that could not
   be placed; it is the victim in this stack, not the subject. Nothing in MeshWeaver's routing code is
   implicated by these 331 occurrences.

   That also settles the direction, which is easy to get backwards in this cluster: the concurrent
   [ROUTE] back-pressure crossings in the same 21:55–22:28Z window are not what caused this, and
   this is not what caused them. Both are downstream of the same thing — a silo that cannot run work — and
   the routing line says so itself: "a CPU-starved silo raises this with nothing stuck."

   🚨 Not a duplicate of #4886, although it is the same family

   #4886 measures the ThreadPool stalls directly (LocalSiloHealthMonitor, 12–18 s). Folding this into it
   would be the obvious move and it is not supported:

   	this ticket	#4886
   log site	Orleans.Messaging / PlacementWorker	LocalSiloHealthMonitor
   namespace	memex	memex-cloud
   window	2026-09-20 22:25:14Z	2026-09-15 23:45Z, 2026-09-19 06:29Z, 2026-09-19 08:57Z
   pod	75b545bbd-nssvp	7fd9668b69-sjm5v, 58dbb6d98d-8msww, 69956b6dbc-gj8m2

   There is no measured stall inside this ticket's window — #4886's latest occurrence is more than a
   day earlier, on a different portal. So "this burst was a ThreadPool stall" is the plausible reading
   this ticket already gives at medium confidence; it is not a measured one, and merging the tickets would
   assert a correlation nothing has measured. Both stay open.

   What would settle it, and what would not

   The decisive evidence is a LocalSiloHealthMonitor stall (or a CPU-throttling / GC reading) on
   memex-portal-deployment-75b545bbd-nssvp covering 2026-09-20 22:25:14Z. I have not taken it: live
   portals are read-only to me and a Loki window is a Hosting/InstanceAction on the control instance,
   which is not mine to run. That read is the next step on this ticket, and it is one query.

   🚨 What must not happen is a bound being raised. The 30 s Polly placement timeout is the reporter
   here, not the constraint — 331 deliveries in a ~50 ms burst all hit it because placement was not
   progressing at all. Widening it would convert a loud burst into a slow one and remove the only signal
   this ticket exists on.

   Also recorded: the same-shape incident that never filed

   This ticket names incident 4904510fe3c3c60b (2026-09-19, the same shape against message-hub grains)
   and notes its ticket failed to file. I searched and confirm there is no issue for it, so this
   ticket is the only record of that shape as well.
6. rbuergi

   added a commit that references this issue on Sep 21, 2026

   fix(routing): the saturation report prints the gauge that can see the…

   ...

   d5f4f2d
7. rbuergi

   added

   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.

   and removed

   sev:MMedium - secondary path broken, or easy workaroundMedium - secondary path broken, or easy workaround

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

   

   rbuergi

   on Sep 22, 2026

   Contributor

   More actions

   Re-read 2026-09-22: still owner-blocked on one read; one narrowing from the grain's own declaration

   RoutingGrain is [StatelessWorker(1)] (src/MeshWeaver.Hosting.Orleans/RoutingGrain.cs). Orleans places a stateless worker on the calling silo with no directory lookup and no remote hop, so a 30 s Grain placement operation timed out for grain routing/default cannot be a slow remote directory or a departed peer — it means the local placement worker made no progress for 30 s on memex-portal-deployment-75b545bbd-nssvp. 331 of them inside ~50 ms is 331 messages that had all been waiting on that one stalled worker, released together when its timeout fired. That fits a silo that could not run work (the ThreadPool-starvation reading this thread already gives) and does not fit anything in MeshWeaver's routing code, which had not been instantiated yet. The messagehub/*/_Activity/import-… samples in the bot's 14:27Z update are the same stall seen from placements of non-stateless grains on the second pod, 15 s later.

   Nothing in src/ to change here: the grain's constructor only resolves already-built singletons, and the 30 s Polly bound is the reporter, not the constraint (widening it is refused for the reason the 22:24Z comment gives).

   Still the one read that settles it (a Logs InstanceAction on the control instance — not mine to run):

   { "requestedAction": "Logs", "deployment": "Deployments/memex", "query": "LocalSiloHealthMonitor", "sinceMinutes": 2940 }   // reaches back to 2026-09-20 ~22:20Z from ~19:30Z today

   A thread-pool-delay line on 75b545bbd-nssvp in that window attributes this to the starvation root being worked separately; none there means the stall is something else and should be written back here. Note Loki retention may already have dropped a two-day-old window — then the next occurrence has to be read live.

   What I did NOT establish: no Logs read, no dump; whether the placement worker was blocked by starvation or by something inside Orleans is unmeasured.
9. rbuergi commented on Sep 22, 2026

   

   rbuergi

   on Sep 22, 2026

   Contributor

   More actions

   A likely cause for this landed tonight, and it is not in a running portal yet — so this stays open for post-roll verification.

   This issue is the second of the two measured placement failures written up in Doc/Architecture/RoutingEntryPoint (PR #5361): Grain placement operation timed out for grain routing/default, Polly 00:00:30, 331 distinct deliveries dropped inside a ~50 ms burst, all upstream of any turn ("failed to address").

   Why #5327 is a candidate cause rather than a coincidence. Placement runs on the silo's shared .NET ThreadPool. #5327 (merged) found that a runtime NodeType compile was holding that same pool two ways: OnThreadPool bound the Func<Task<T>> overload (Task.Run) so everything after the first await resumed on a pool worker, and Roslyn's ConcurrentBuild fanned each emit back onto TaskScheduler.Default with no DOP cap. Its probe at 6 concurrent emits — the portal's ProcessorCount — measured p99 dispatch 417 ms with 115 items queued, against 0.18 ms and queue 1 once fixed. A 30-second placement budget expiring under that is consistent; a placement operation is exactly the kind of work that starves when the pool is saturated.

   What that does NOT establish. I have not shown these timeouts were caused by a compile — no correlation was run between compile windows and the 22:25:14Z burst, and placement can time out for reasons that have nothing to do with the local pool (directory instability, a silo mid-handoff). Treat this as the first hypothesis to test, not a diagnosis.

   The verification this is waiting on. Both portals currently serve 3da3423c / 3.0.0-ci.9193; the newest sealed tag is 3.0.0-ci.9204, which carries #5327. Once an instance actually runs it, re-measure Failed to address message Request … [routing/default] over a comparable window. If it is gone, this closes with that reading. If it persists, the remedy is the structural one in #5361 — a local routing service where a silo is co-hosted, so the co-hosted caller stops paying a cluster placement to reach a grain that StatelessWorkerDirector would place back in its own process.

   Per the severity policy a sev:H closes on post-roll production verification, never on a merge, so nothing here is a closing claim.
10. rbuergi commented on Sep 23, 2026

    

    rbuergi

    on Sep 23, 2026

    Contributor

    More actions

    Post-roll reading (2026-09-23): the placement timeout recurred on an image that contains #5327/#5375, so the compile lane was not the whole cause

    The recurrence. Admin/_LogIncident/f7d8f9982b20cce5 (filed as #5334) is the same shape as this issue: Grain placement operation timed out, Polly 00:00:30, PlacementService.cs:602, raised on IMessageHubGrain.DeliverMessage. It folded 27 occurrences on memex-cloud between 2026-09-22 14:41Z and 2026-09-23 14:22:28Z. Its newest 10 samples are all from pod memex-portal-deployment-777677694-p6hbn at 14:22:23–28Z, which is five minutes after Ops/Actions/selfupdate-roll-memex-cloud-3-0-0-ci-9259-37f42697 (14:17Z). Every image memex-cloud ran after 04:32Z today descends from 39f49494 (#5375).

    The destinations. 9 of the 10 retained samples place a messagehub/*/_Activity/compile-state grain (Ifrs17/LineOfBusiness, Ifrs17/ProjectionConfiguration, LinkedIn/Position, …/Northwind/ReportsCatalog, felice.buergi/AnimalMemory). The tenth is messagehub/felice.buergi.

    Why those grains. NodeTypeCompileStateMirror activated one satellite grain per NodeType whenever that type's compile state moved, and a roll re-stamps every type (about 371). Nothing reads those satellites. So every roll produced a burst of hundreds of fresh grain placements into a cluster whose membership was changing at that moment. PR #5571 removes the write: Doc/Architecture/CompileStateSatelliteRetired, with a test and a negative control.

    Not established.

    • Whether the placement worker also stalls on directory churn from the departing silo. This thread's routing/default burst (a StatelessWorker, placed locally) is not explained by compile-state.
    • No LocalSiloHealthMonitor read. The Logs InstanceActions I issued on the control instance failed to land or went Unobserved (details on Portal routing legs starved of ThreadPool threads during install burst (routing saturation gauge, not a routing defect) #5389).

    What closes this. After a roll carrying #5571: no Failed to address message … Grain placement operation timed out in the ~15 minutes after pod start, and in particular no _Activity/compile-state targets.

    Refs #5571 #5334
11. rbuergi commented on Sep 24, 2026

    

    rbuergi

    on Sep 24, 2026

    Contributor

    More actions

    Post-roll reading 2026-09-24 ~06:51Z (memex-cloud): still firing on the fixed image

    Image. Every memex-cloud pod that booted in the window ran core 9a61fed964 (ci.9260, ci.9262 and ci.9263, per Ops/logs-memexcloud-20260924-verify-platformstartup). That build contains #5327 / #5375.

    Reading. Ops/logs-memexcloud-20260924-verify-5037-placement, {namespace="memex-cloud"} |~ "(?i)Grain placement operation timed out", 900 min (2026-09-23 ~15:45Z to 2026-09-24 06:51Z): 177 lines, not truncated.

    Related, same window. Response did not arrive on time was cut at 200. The landed sample is one [ROUTE] Grain <X> delivery failed after transient retries burst across many grains on 7d7f4d84f9-mvzb5 at 18:11:59Z (Ops/logs-memexcloud-20260924-verify-5288-ontime). Thread-pool stalls of 1–9 s are also frequent (see #5388).

    Stays open. ci.9287 (core bf5ac85526 + Plugins c4795a8d5b, which carries #5635 and Plugins#2329) has been handed to the control lane and has not rolled. Re-read after it does.

    Not established. How the 177 lines split across pods and time. The action lands entries slowly, and I did not wait for all 177.
12. rbuergi commented on Sep 25, 2026

    

    rbuergi

    on Sep 25, 2026

    Contributor

    More actions

    Triage re-read 2026-09-25 ~15:30Z. Running builds (/api/version): memex.systemorph.com = 39f49494eb (ci.9218), memex.meshweaver.cloud = 140c5fb7ae (ci.9291). Ancestry was checked with git merge-base --is-ancestor against origin/main. Both portals are still held at the V58 migration: the ci.9332 pods crash-loop on DbVersionGate db_version=57 < expected 58. Nothing will roll until a governed Reconcile of Deployments/memex runs the migration Job.

    Status: fixed in #5675 and waiting for deploy. 4028fd6468 is not an ancestor of either running build, and #5571 is live on memex-cloud only. The close condition is the one in the 05:24Z comment: after a roll that carries #5675, no Grain placement operation timed out for grain routing/* appears over a comparable window that includes a roll. No code action remains.
13. rbuergi commented on Sep 26, 2026

    

    rbuergi

    on Sep 26, 2026

    Contributor

    More actions

    Post-roll verification, memex.systemorph.com, 2026-09-26 ~05:55Z. memex serves 3.0.0-ci.9332 = core 4028fd6468 (/api/version), Plugins half 1470fbf3 (CD run 9332 portal-ai job HEAD is now at 1470fbf; same ref as the /health publication-seal line). The DB is at V58: memex-migration-63 logged Database migration completed. Version: 58 at 2026-09-25 17:58:03Z. The roll is not converged: Ops/Status/memex at 05:48Z reads 1/3 ready; only 5dbb7df97b-dktrd (booted 04:06:39Z) serves. So every post-roll window below is about 1 h 50 min on one serving replica. All reads are Logs InstanceActions under Ops/Actions/logs-memex-20260926-postroll-*.

    Still open: the fix is live, and the zero is not yet informative for routing/*.

    • 4028fd6468 is fix(orleans): a stateless worker's placement no longer waits on the grain directory (#5037) #5675's own merge commit, so the fix is in the build.
    • Ops/Actions/logs-memex-20260926-postroll-placement (Grain placement operation timed out, 300 min, includes the 04:06Z roll) returned 0.
    • Control: …-placement-48h (2880 min) returned ≥ 50 lines (CUT). The newest is at about 2026-09-25 15:28Z on 56fbdcd48f-cbms9 (ci.9218). Every grain named in them is messagehub/* or podhub/*. None is routing/*. So in the 48 h before the fix, memex was not producing this issue's routing/default shape at all, and a post-roll zero cannot distinguish "fixed" from "not triggered".
    • The post-roll window is about 1 h 50 min on one ready replica. The 09-25 condition asks for a window comparable to 24 h that includes a roll.

    Closes when: ≥ 24 h after 04:06Z with no routing/* placement timeout, on memex and on memex-cloud once it runs a build that contains 4028fd6468.
14. rbuergi commented on Sep 27, 2026

    

    rbuergi

    on Sep 27, 2026

    Contributor

    More actions

    Production verification complete for this issue's routing/* placement failure, 2026-09-27.

    The two governed Logs actions below each queried Grain placement operation timed out over a full 1,440-minute window, limit 200, including the recent rolls. Both are Done, with no truncation or landing failures:

    • Ops/Actions/verify-5037-memex-20260927-placement: 0 read, 0 landed, 0 failed; finished 11:56:56Z.
    • Ops/Actions/verify-5037-memexcloud-20260927-placement: 35 read, 35 landed, 0 failed; finished 11:57:40Z. Twenty-eight name messagehub/*; the seven generic timeout lines occur within 100 ms of those named failures on the same pod. None names routing/*. These are real remaining single-activation placement failures, not reported as fixed by this closure (the distinction is already documented in RoutingEntryPoint and Recurrence: Orleans silo thread-pool stall (~25s) in memex-portal — continued from #4886, risk of missed heartbeats and cluster eviction #5388).

    Positive control: Ops/Actions/verify-5037-memex-20260927-startup is Done with 126 PlatformStartup lines read and landed, 0 failed, no truncation. Thirty-nine carry versions, ci.9406 through ci.9445: the window contains repeated rolls and live processes. The cloud window's 35 placement lines provide a positive same-event control.

    Current replica provenance (notScraped=false): memex has 3/3 ready on ci.9445, core db9f332bf3d9fa9935799ccbfda4ef0f7fed221e; cloud has 6/6 ready on ci.9443, core 311108bf16a70eee39a6618b36456cf82c58a85f. GitHub ancestry checks place #5675's 4028fd6468 behind both, with behind_by=0. Memex's current generation started 07:09–07:28Z; the cloud image has served since 06:15Z, with further same-image starts. Fresh reads of Doc/Architecture/RoutingEntryPoint returned typed MarkdownContent on both portals; these prove node reads serve, not which delivery fast path was used.

    The stated 24-hour, roll-inclusive closure condition is met for the routing-grain shape. Closing as completed. The production measurements are being added to the existing RoutingEntryPoint documentation page; broader placement and activation failures remain open.
15. rbuergi

    closed this as completedon Sep 27, 2026
16. rbuergi

    reopened this on Sep 27, 2026
17. rbuergi commented on Sep 27, 2026

    

    rbuergi

    on Sep 27, 2026

    Contributor

    More actions

    Correction to the closure above: reopened pending complete verification.

    The cloud sample contains 28 explicitly identified messagehub/* placement failures and seven generic timeout lines with no grain identity. Temporal proximity on the same pod does not attribute those seven. They remain unclassified; this sample establishes zero named routing/* failures, but does not establish that all remaining placement failures are outside this issue.

    The original governed actions used sinceMinutes: 1440, but retain neither exact millisecond query bounds nor an explicit start/end. I am collecting an independently reproducible fixed UTC window. The first timestamp-filter attempt failed on the deployed Loki version (and two companion requests returned 429); these are failed measurements, not clean results. No production changes were made by these read-only actions.

    The resolver fix is deployed on both portals, with the provenance listed above. Production closure remains pending an attributable, reproducible observation. PR #5806 is being corrected to preserve these limitations.
18. rbuergi commented on Sep 27, 2026

    

    rbuergi

    on Sep 27, 2026

    Contributor

    More actions

    The prerequisite exact-window log instrument is now verified in production. Plugins PR #2449's publishing run 36345451159 completed successfully. The Main portal's Hosting/InstanceAction reports compiled/adopted module 1.33 / 1.33.0, compilation Ok, AdoptedVerified provenance, platform 3.0.0-ci.9501.

    Two independent completed ordinary Logs actions:

    • rbuergi/Requests/logs-fixed-window-133-a-20260927 (Done 21:32:51Z)
    • rbuergi/Requests/logs-fixed-window-133-b-20260927 (Done 21:33:19Z)

    Both recorded exactly 2026-09-27T11:01:40.123Z through 2026-09-27T11:02:40.123Z, identical namespace/pod/query, 14 lines read / 14 landed / 0 failed, untruncated. This was a known-positive historical window from memex-cloud's qntsh replica, using the published logUntil input; no manual log access or production restart was used.

    An untruncated Ops-only search found all 14 rows last attributed to B. All were individually read through MCP: all 14 retained B's actionPath, all had the requested pod, and every source timestamp lay inside the exact recorded bounds. Six actual LIVENESS ticks (1692–1697) span 11:01:40.478Z–11:02:30.835Z; other matched rows are metadata/allocation headers, not six more heartbeat observations.

    This proves the deployed instrument's reproducible millisecond window and landing provenance. It does not fix or close #5037: routing/default placement still needs source grain-address attribution and a verified root-cause remedy. The false closure remains corrected; this issue stays open.
19. rbuergi commented on Sep 27, 2026

    

    rbuergi

    on Sep 27, 2026

    Contributor

    More actions

    The production-verified Hosting 1.33 fixed-window instrument now supplies original source-address attribution for #5037. Ordinary Logs action rbuergi/Requests/logs-5037-exact-placement-address-20260927 completed 2026-09-27 21:35:06Z. It recorded the exact historical window 2026-09-20T22:24:15.999Z–22:25:15.999Z, deployment memex, original pod memex-portal-deployment-75b545bbd-nssvp, and query Grain placement operation timed out for grain routing/default.

    The action read and landed 20 lines with 0 landing failures and explicitly truncated:true. This is an attribution sample, not the incident denominator and not a claim that only 20 failures occurred. An Ops-only normal MCP search returned all 20 landed rows untruncated; every one was individually read, carried this actionPath and the original pod, and named System.TimeoutException: Grain placement operation timed out for grain routing/default. Source timestamps span 22:25:14.536Z–14.539Z and lie inside the recorded window.

    The failed grain identity is therefore the routing/default placement target, not an inferred MessageHub node activation. This does not supply a counterfactual or prove the placement worker’s root cause; it confirms where the original failure occurred and supports continuing the placement/queue investigation. No image pin, timeout increase, watchdog, restart, manual log access, or issue closure was performed.
20. rbuergi commented on Sep 28, 2026

    

    rbuergi

    on Sep 28, 2026

    Contributor

    More actions

    Production closure check, 2026-09-28: the routing/default placement failure fixed by #5675 is absent from a fixed, roll-inclusive 24-hour window on Main and Cloud. Both current installations run ci.9526 (commit 1d2c1a4d7cf9f8e952ecbe7c8ba46b7b0ba22fe1, 3/3 ready each); #5675's 4028fd6468 is an ancestor. Current replicas started inside the observation window. The documentation correction in #5806 is merged.

    • Main exact-window Logs action: 2026-09-27 06:45:00Z to 2026-09-28 06:45:00Z, Grain placement operation timed out, 0 read, 0 failed, untruncated.
    • Cloud exact-window Logs action: same UTC bounds, 35 read and landed, 0 failed, untruncated. Twenty-eight lines name messagehub/Ops/Logs/...; seven are Orleans' generic Grain placement operation timed out after 00:00:30 line. Zero name routing/*.
    • Cloud request-header context: the only placement burst in that window is 2026-09-27 11:02:40–45Z on pod ...-qntsh. Fourteen Failed to address message Request headers, untruncated, name exactly seven distinct messagehub/Ops/Logs/... grain ids (two requests per grain); none targets routing/*. Each generic line is adjacent to one of those named placement failures. The full first-event context also preserves the grain id on its original request header. This classifies the previously unclassified generic lines rather than assuming their identity from timing alone.
    • The original pod's pre-failure back-pressure body records one routing episode at 22:23:51Z with 0 stream destinations queued; it cleared in 15 ms. That burst is not evidence of a routing-leg stall causing the 22:25 placement failure.

    Closing this issue for routing/default placement. The Cloud messagehub/* placement failures are real and remain outside this fix, tracked separately under #5388; this closure does not claim all Orleans placement failures are gone.
21. rbuergi

    closed this as completedon Sep 28, 2026
22. rbuergi commented on Oct 11, 2026

    

    rbuergi

    on Oct 11, 2026

    Contributor

    More actions

    (re-posted 2026-10-11; originally by @rbuergi on 2026-09-25)

    Root cause for the routing/default shape found and fixed (#5675, merged); the premise "still firing after #5571" does not hold

    1. The 177 lines predate #5571. Ops/logs-memexcloud-20260924-verify-5037-placement landed 171 of its 177 lines under Ops/Logs. By timestamp and pod they are two bursts on replicaset 7d7f4d84f9: 2026-09-23 17:57–17:58Z (-mvzb5, -n7g6b) and 18:11Z (-wl8mv 99 lines, -mvzb5 45). That replicaset ran core 9a61fed964. git merge-base --is-ancestor b9142174 9a61fed964 is false, so #5571 is not in that image. In the 18:11 burst the timed-out grains are space hubs (messagehub/AgenticBusiness/Menu, messagehub/Store, messagehub/ClientFReporting/Fund, messagehub/MeshWeaverInstance/03349f5b76b5), plus 10 podhub/* and 2 pubsubrendezvous/*. None of them is routing/default.

    2. On the current image it is quiet. memex-cloud /api/version reports 140c5fb7ae (contains #5571). Replicaset f8f895 came up at 2026-09-24 08:42Z and 8 of its pods have booted since. Ops/logs-memexcloud-20260925-5037-placement (1440 min, not truncated) found one event in the last 24 h, from the previous replicaset: messagehub/Admin/Build on 76cf776847-v4txp at 2026-09-24 06:51:09Z. That is 6 lines for 1 grain. On f8f895 the count is 0.

    3. What stalled the 18:11 burst. Ops/logs-memexcloud-20260925-5037-silohealth shows a third silo, 7d7f4d84f9-n7g6b, logging LocalSiloHealthMonitor warnings every 10–13 s from 17:58:43 to 18:10:27Z, and then nothing. The 26 placements that timed out in the same millisecond at 18:11:19Z on -wl8mv were started about 30 s earlier, right after that silence. The pods that dropped traffic were not the stalled pod. They were waiting on the stalled pod's grain directory partition.

    4. The stateless-worker premise was wrong. Earlier comments here say a [StatelessWorker] placement makes "no directory lookup and no remote hop". I decompiled Orleans 10.3.1 PlacementService.PlacementWorker.ExecutePlacementAsync. It starts every placement with GrainLocator.Lookup(grainId). On the portal's DHT that call forwards to the silo that owns the grain id's hash, and the answer is always "not registered", because stateless workers are never registered. The cache entry is dropped on membership change, so a roll forces the remote lookup. The lookup is retried as transient until the 30 s Polly budget runs out, and then every message queued on that work item is rejected together. That is the 331-in-50 ms burst.

    Fix (#5675): StatelessWorkerGrainDirectoryResolver sends every type declaring StatelessWorkerPlacement to an in-process directory, so placing routing/default no longer depends on any other silo. No bound was changed. The test StatelessWorkerPlacementSkipsTheDirectoryTest runs on a real TestCluster with a directory stand-in that cannot answer for marked ids. As a negative control I removed the registration, and the routing fact failed with the refusal.

    Not fixed and not established:

    • Single-activation grains (messagehub/*, podhub/*, pubsubrendezvous/*) need the directory by design. Their timeouts follow from the stalled owner silo; that stall is Recurrence: Orleans silo thread-pool stall (~25s) in memex-portal — continued from #4886, risk of missed heartbeats and cluster eviction #5388 / Orleans silo thread-pool stalls (12–18s) across all memex-portal pods risk missed heartbeats and cluster eviction #4886.
    • I did not establish why n7g6b stalled. Its own log in that window is full of EnrichWithNodeType probe … faulted (TimeoutException) and MeshQuery.InitialStallProbe lines (Ops/logs-memexcloud-20260925-5037-tpdelays).
    • The TestCluster runs Orleans' distributed directory, not the DHT. The test therefore stands in for the owner that cannot answer; it does not reproduce DHT timing.

    Closes on: a roll that carries #5675, followed by no Grain placement operation timed out for grain routing/* over a comparable window that includes a roll. Doc: Doc/Architecture/RoutingEntryPoint, section "Why a stateless worker's placement could wait 30 s at all".

    Refs #5675 #5571 #5388