Repository navigation
Conversation
…G ON #2543 has needed `portal/nodeops`' own queue state since 2026-08-28 and has had exactly one capture of it. Not because the state is hard to read — because no diagnostic in the system prints the TARGET's. Measured over every CD bake job 2026-09-07T00:00Z -> 2026-09-08T18:45Z (61 jobs, 61/61 logs fetched, 1,512,136 lines): * the `Hub <addr> ... exec=...` form (GetPendingRequestDiagnostics) fires 0 times — it is written on a disposal stall, which a mesh saturating mid-bake never reaches. `exec=` appears nowhere, so searching for it reads as "no dumps". * the form that DOES fire is BuildTimeoutMessage's `This hub: ...` clause — 34 occurrences in 20 of 61 jobs — and all 34 describe the REQUESTER, which is idle in 34 of 34 (`buffer=0 ... drainsInFlight=0,draining=False`, no `Executing(`). 32 of them name `-> portal/nodeops-...`. That message already ends "This message cannot distinguish them; the target's own RunLevel and queue can." Nothing took that measurement. `[STALE-CALLBACK]` fires every 5 s and 300+ times in a failing bake, and had the same defect: every field on it — address, pending list, pool counters — belongs to the hub that is waiting, and a waiting hub is idle by construction. It now resolves each distinct target to a local hub (a pure read, HostedHubCreation.Never — a diagnostic must never construct a hub, nor take the creation lock a wedged mesh may be contending on) and appends that hub's turn-loop state: TARGET portal/nodeops-... RunLevel=Started Queue(buffer=45,deferred=0,drainsInFlight=1,openGates=0,draining=True) Executing(CreateNodeRequest, 24888ms) drainsInFlight>0 with Executing = a thread is blocked inside the handler; drainsInFlight=0 with Executing = no thread there and the turn's observable never terminated; drainsInFlight=0, no Executing, draining=True, buffer>0 = the drain was scheduled and never ran. Four different defects, indistinguishable until #3593 made `exec` a measurement instead of a literal 0 — which landed 2026-09-07T15:05Z, an hour after the last comment on #2543, so nothing in that thread used the fixed instrument. Compact snapshot, not GetPendingRequestDiagnostics: the target's own callback list runs to kilobytes and multiplying it by 300 lines is how a hub once emitted a ~100 KB line that broke the TRX parsers. Capped at three DESCRIBED targets — the cap counts what was described, not what was considered, so unresolvable addresses cannot spend the budget and push the one hub that matters into "not described". `AReplyIsOwedByAShuttingDownLocalHub` now shares the resolution walk rather than carrying a second copy of it. No bound raised, nothing retried, no watchdog. This adds a measurement. Tests * TurnLoopSnapshotIsMeasuredTest — POSITIVE control (a handler genuinely holding the block must report drainsInFlight non-zero + Executing) beside a negative one. A field frozen at 0 passes every assertion that only sees an idle hub; that is exactly how the literal survived. * NodeCrudDoesNotOccupyTheExecutionBlockTest — measured, and it refuted my own first draft: with a create parked inside its own validator the node-CRUD execution hub reads completely idle, because storage reads go through IIoPool and the chain leaves the block at that hop. So a create holding the block for 24.9 s is an ANOMALY, not the cost of the pipeline. Doc: Bake Seal — NodeOps Saturation gains the instrument correction, the two-form distinction, the 61-job denominator (6 GATE FAILED, not 11 — five of the failures are a prebuilt-bundles shelf collision, so counting reds overstates this by ~2x), and the eliminations, so the next session does not re-derive them. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
🟡 Changes recommended
The updated documentation references a non-existent test (NodeCrudTurnStateIsMeasuredTest), which makes the calibration guidance inaccurate and should be corrected before merge.
Once you've addressed the issues Copilot identified, you can request another Copilot review.
Pull request overview
Improves MeshWeaver hub saturation diagnostics by extending [STALE-CALLBACK] logs to include the target hub’s compact turn-loop snapshot (run level + queue shape + currently executing turn), so investigation can distinguish “blocked handler” vs “non-terminating observable” vs “scheduler stall” vs “idle target/reply-leg issue” without needing a disposal-stall dump.
Changes:
- Extend
[STALE-CALLBACK]logging to resolve distinct callback targets to local hubs (pure read,HostedHubCreation.Never) and append each target’sGetTurnLoopSnapshot()(capped per line). - Add
MessageHub.GetTurnLoopSnapshot()plus shared target-to-local-hub resolution (ResolveLocalHub) and reuse it inAReplyIsOwedByAShuttingDownLocalHub. - Add regression tests that (1) positively prove
drainsInFlight/Executing(...)are measured under a truly blocked turn and (2) show node CRUD does not normally occupy the node-ops execution block; update the bake-saturation doc with the corrected instrument reading.
File summaries
| File | Description |
|---|---|
| test/MeshWeaver.Messaging.Hub.Test/TurnLoopSnapshotIsMeasuredTest.cs | Positive/negative controls ensuring turn-loop snapshot fields (drainsInFlight, Executing) actually move under load vs idle. |
| test/MeshWeaver.Graph.Test/NodeCrudDoesNotOccupyTheExecutionBlockTest.cs | Calibration test: a real create blocked inside its validator should not occupy the node-CRUD execution hub’s action block. |
| src/MeshWeaver.Messaging.Hub/MessageHub.cs | Appends resolved target hub snapshots to [STALE-CALLBACK] logs; introduces GetTurnLoopSnapshot and shared local-hub resolution; deduplicates shutdown-local-hub resolution logic. |
| src/MeshWeaver.Documentation/Data/Architecture/BakeSealNodeOpsSaturation.md | Documents the corrected instrument semantics and the new target-snapshot emission on stale-callback lines. |
Review details
- Files reviewed: 4/4 changed files
- Comments generated: 1
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
| **Calibration, so the reading is not itself a guess.** `NodeCrudTurnStateIsMeasuredTest` parks a real | ||
| `CreateNodeRequest` inside the node-CRUD execution hub's turn (an `INodeValidator` that blocks — | ||
| the same harness [The /api/content 503](../ContentRoute503) uses to establish that a validator runs | ||
| *inside* that turn) and asserts the hub then reports `drainsInFlight` non-zero with | ||
| `Executing(CreateNodeRequest, …)`; a negative control asserts an idle hub reports neither. That pair | ||
| is what stops the field quietly becoming a constant again — which is the whole defect above, and | ||
| the reason a field that cannot fail is not a measurement. |
Test Results (shard 4)1 860 tests +165 1 859 ✅ +358 3m 9s ⏱️ + 1m 0s For more details on these failures, see this check. Results for commit 8738db0. ± Comparison against base commit e0ad051. ♻️ This comment has been updated with latest results. |
Test Results 17 files + 1 17 suites +1 14m 30s ⏱️ +16s For more details on these failures, see this check. Results for commit 8738db0. ± Comparison against base commit e0ad051. ♻️ This comment has been updated with latest results. |
…hub's block Node CRUD in a mesh was serialised through one actor's queue. A create parked in its validator held `portal/nodeops` so completely that a second, unrelated create posted to the same hub sat unprocessed at `Queue(buffer=1,…)` for its whole budget. Delete, move and copy shared it. ROOT CAUSE, and it is not in the node-CRUD path. A response subject is signalled from INSIDE the turn that handled the response, and Rx runs a continuation on the thread that signalled it — so every `hub.Observe(x).SelectMany(…)` chain in the framework ran its entire remainder on that hub's action block, inside that turn, and the turn could not end until the chain did. The create handler is detached and correct (`Processed()` at +1 ms); the pipeline then climbed back onto the block when its partition bootstrap's nested response came home, and ran validators, save and change feed there. `ContinueOffBlockRestoringUserContext` now hops the continuation off the block before restoring the caller's identity. The order matters: `.Do(SetContext)` must run on the thread that will run the continuation, or the chain resumes unauthenticated. WHY THE OLD TEST WAS RED. It read `Executing(…)` as time-on-the-block. That field is cleared in the handler OBSERVABLE's `.Finally`, so it measures the handler's in-flight lifetime — with a create parked it read `Executing(CreateNodeResponse, 36001ms)` and tracked the observer's own sampling window. #2543's `Executing(CreateNodeRequest, 24888ms)` therefore never established that the block was held; the `buffer=45` beside it did. EVIDENCE. The claim is measured behaviourally, since those fields cannot decide it: with a create parked, an independent create must still complete. Three tests — the probe, a POSITIVE CONTROL (the same probe with nothing parked), and `TwoCreates_AreInFlightSimultaneously`, which requires two validators entered before either is released. With the hop removed the first and third fail and the control still passes; that pairing is the evidence, not the green. 4,426 tests across 8 projects green; solution clean under -warnaserror. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
rbuergi
changed the title
Pull request was converted to draft
The field reads like a statement about the pump and is not one: it is cleared in the `.Finally` of the handler's returned OBSERVABLE, so a handler that correctly detaches keeps it set, with a growing elapsed, for as long as its chain is in flight anywhere. Recorded on the field itself and in DebuggingMessageFlow, because both readers who met it today — including #2543's own headline capture — read it as block time. `buffer=N` is the occupancy signal; a behavioural probe with a positive control is the reading that cannot be misinterpreted. This half stands on its own: it is true whether or not the continuation hop on this branch ships. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…d the block was providing The hop in the previous commit removed THREE guarantees and replaced one. CI found the other two: Memex.Portal.Shared.Test ran 1156 tests with ZERO failures and the host then exited 2 (MASKED), with 7 [FATAL ERROR]s, on two consecutive heads. 1. A FAULT BOUNDARY. A continuation fault used to be thrown inside HandleMessageAsync's chain, on the block, where MessageService's catch arm logged it and called ReportFailure — a reported failure, never a crash. Off the block nothing is above it: Rx rethrows on the scheduler thread, it goes unhandled, and the process dies. GuardContinuationFaults restores the previous DISPOSITION of that exception; it does not invent a new one. Debug once this hub is shutting down (a continuation outliving the scope it resolves from is the race LayoutAreaHost already reports as transient), Error while it is still serving, where it means application code threw. 2. A BOUND. ObserveOn asks the scheduler for long-running support and, when it is offered, dedicates a drain worker PER SUBSCRIPTION — a thread per request in flight once the hop is on every hub.Observe. DefaultScheduler and TaskPoolScheduler both offer it, so neither can be used directly; PooledContinuationScheduler exists only to WITHHOLD that one capability and keep Rx on the per-item pooled path. Do not "complete" it by implementing ISchedulerLongRunning — the omission is the fix. 🚨 The crash does NOT reproduce locally: the same suite on the same head with the original hop passes 1152/1152 with zero fatals. CI is the only instrument that can judge this, so this push is the measurement, not a claim. Local (regression cover only, 4,455 tests, 0 fatals): Portal.Shared 1152, Graph 1455, Messaging.Hub 383, Data 496, Hosting 514, Layout 455; solution clean under -warnaserror. OPEN, deliberately not decided here: when a continuation loses its scope during teardown the guard turns a crash into a log line, and the caller's write simply does not complete. Whether that should instead NACK the caller is a separate question from stopping the crash. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The previous commit's guard caught a continuation fault, logged it, and then neither emitted nor errored — so anything awaiting that response waited for its full timeout instead of learning immediately that the work had failed. That is a HANG where the block used to fail fast, and it is the band-aid failure mode: the crash was stopped by making the symptom quieter rather than by giving the fault somewhere correct to go. MessageService did not swallow either — it logged AND called ReportFailure, so the caller got an answer. The guard now does the same: report, then end the sequence with the fault. Suspected cause of CI's Two_concurrent_logons_run_a_once_action_exactly_once timing out on the previous head. Not claimed as proven: neither that failure nor the host crash reproduces locally (the same suites pass here on both heads), so CI remains the only instrument and this push is the measurement. Local regression cover, 3,486 tests, 0 fatals: Data 496, Graph 1455, Portal.Shared 1152, Messaging.Hub 383; solution clean under -warnaserror. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
CI after the terminating guard: one failure left, and it names a SIXTH invariantRun 34316509035 on
So the terminating guard was necessary but is not the cause of this one. What this test is actually standing on
That is a design that reasons explicitly about which thread a response continuation completes on, Running tally of what the action block was underwriting
PositionThis is the fourth CI run to surface an invariant nobody had written down, and #6 is the first that Staying DRAFT. The scope question I put to the maintainer stands and this sharpens it: either The two findings that stand regardless of that decision, and are already merged or committed: |
Superseded by #3802 — and this branch must not be merged as-isTwo reasons, one of them mechanical and load-bearing. 1. This branch is 14,689 deletions behind 2. The scope call this PR surfaced is resolved, the conservative way. The choice was "fix the general decoupling forward (error boundary + disposal-aware + bounded pool) or narrow the hop to the node-CRUD path". #3802 takes the second: Everything this branch established is carried over — the seven host crashes and the six invariants they named, The findings are now durable rather than living in this thread: Closing this draft in favour of #3802. |
…y mesh The first cut registered PlatformMetricsHostedService in MeshHostApplicationBuilder, which puts a hosted service resolving the root hub into EVERY mesh in the fleet — including the several thousand a test run builds, none of which has a collector. CI then failed on LogonActionFrameworkTest.Two_concurrent_logons_run_a_once_action_exactly_once with a 30 s TimeoutException — the same signature as invariant #6 of the six broken by the global continuation hop in the abandoned #3759. Three local runs of that test on this branch were green, main is green on its last five runs, and the test is not in known-flakes.json; so the evidence did not settle it either way. Rather than re-push and call it a flake, remove the reason for the doubt. Instrumentation that alters the startup path of hosts that will never be scraped is cost without a reader, and it makes every timing-sensitive test's failure a question about the meter. The arming now lives beside the OpenTelemetry subscription in the portal's service defaults — both halves of the wiring in one place, in the host that actually collects — and a test mesh is untouched by this PR at all. Exactly one site arms it (verified by grep across src/, memex/, test/, tools/), and it is the collecting host's. Verified on this branch: solution build Release -warnaserror 0 warnings 0 errors; Graph.Test 1486 passed, Hosting.Test 539 passed, Messaging.Hub.Test 387 passed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
What this changes
Node CRUD in a mesh was serialised through one actor's queue. Every create/delete/move/copy
without an opted-in ancestor executes on
portal/nodeops-<meshId>, and a create parked in itsvalidator held that hub so completely that a second, unrelated create posted to the same hub sat
unprocessed at
Queue(buffer=1,…)for its entire budget.The root cause is not in the node-CRUD path. A response subject is signalled from inside the
turn that handled the response, and Rx runs a continuation on the thread that signalled it — so
every
hub.Observe(x).SelectMany(…)chain in the framework ran its whole remainder on that hub'saction block, inside that turn, and the turn could not end until the chain did.
The create handler is detached and correct —
HANDLER_EXIT state=Processedat +1 ms on the fatetrail. The pipeline then climbed back onto the block when its partition bootstrap's nested
response came home, and ran validators, save and change feed there. Delete, move and copy inherit
the same shape, which is why one line fixes all of them.
MessageHub.ContinueOffBlockRestoringUserContextnow hops the continuation off the block beforerestoring the caller's identity. The order matters:
.Do(SetContext)must run on the threadthat will run the continuation, or the chain resumes unauthenticated.
This PR started as the opposite claim — that half is corrected, not deleted
It originally argued that the create pipeline never holds the block, reading
Executing(T, N ms)astime-on-the-block. That field is cleared in the handler observable's
.Finally, so it measuresthe handler's in-flight lifetime, including hops the chain already left the block for. With a
create parked it read
Executing(CreateNodeResponse, 36001ms)and tracked the observer's ownsampling window exactly.
So #2543's
Executing(CreateNodeRequest, 24888ms)never established that the block was held for24.9 s — the
buffer=45beside it is the part that was real.BakeSealNodeOpsSaturation.mdkeepsthe original analysis and adds a correction section saying which two inferences failed and how they
were falsified; the
drainsInFlighttable there inherits the same error and is corrected with it.Evidence
Measured behaviourally, because the snapshot fields cannot decide it:
TwoCreates_AreInFlightSimultaneously(two validators entered before either is released)The control passing in both worlds is what makes the other two mean "the pump is held" rather than
"this probe never completes anyway". Both now fail deterministically in isolation (11 s / 21 s)
rather than only under assembly load, which is how the original red hid: isolated it passed 10/10.
Verification
Data 496, Layout 455, Messaging.Hub 383, Documentation 361, ContentCollections 28
dotnet build -c Release -p:CIRun=true -warnaserror— 0 Error(s), 0 Warning(s)Blast radius, stated plainly
This changes continuation threading for every request/response pair in the framework, not just
node CRUD. Anything that implicitly relied on continuations being serialised per-hub can now run
concurrently. That is the point of the change, and it is why the verification above is broad rather
than scoped to the touched path.
Related: #2543.