Report the HANDLER side when a callback outlives the quiescing budget by rbuergi · Pull Request #1011 · Systemorph/MeshWeaver

rbuergi · 2026-08-09T12:47:29Z

Refs #981.

This is instrumentation, not a fix. It does not change the quiescing budget, add a retry, or post a response from anywhere. #981 stays open.

The gap it closes

Every capture of "callbacks still pending past the teardown quiescing budget" has been caller-only: the hub names the request type, its target and its age, and nothing about what happened to the delivery at the receiving end. Two occurrences — 2 738 ms and 6 153 ms against a 2 s budget, both a CreateNodeRequest addressed to the mesh hub itself, every queue empty — therefore left the mechanism unnamed. Further members have since landed in other projects, one on a docs-only PR with zero C#.

RequestFateLedger records, per awaited request id, the stages the delivery actually reached, and folds the trail into every place a pending callback is already reported.

What a capture now says

[QUIESCE-TIMEOUT] client/ccfc…: 1 callback(s) still pending after 0.3s.
  Pending: WqgJwZojREesGMav5jZf2Q=MisroutedReplyRequest@host/1(303ms)
  handler-side fate (what happened to the delivery):
    WqgJwZojREesGMav5jZf2Q=MisroutedReplyRequest:
      POSTED target=host/1@client/ccfc…(+0ms) → RECEIVED runLevel=Started@client/ccfc…(+0ms)
      → ROUTED onTarget=False state=Forwarded@mesh/1(+1ms) → RECEIVED runLevel=Started@host/1(+1ms)
      → ROUTED onTarget=True state=Submitted@host/1(+1ms) → HANDLER_ENTER@host/1(+1ms)
      → RESPONSE_POSTED type=SwallowedResponse target=mesh/1@host/1(+1ms)
      → HANDLER_EXIT state=Processed@host/1(+2ms)
      → RESPONSE_ARRIVED_NO_SUBJECT type=SwallowedResponse@mesh/1(+2ms)
      ⇒ a reply WAS posted for this correlation and the callback is STILL pending — the reply was
        lost between the responder and the requester, so chase the response delivery, not the handler.

Each trail ends in a verdict naming which of the mutually exclusive shapes it is: never delivered / delivered-but-parked / no handler matched / handler ran and never replied / chain completed without producing a reply / reply posted and lost. The stages stay above it as the evidence.

Answering the binary question

The specific ambiguity to remove was: does the chain that owes the reply complete slowly, or terminate without responding? Three parts close it:

HANDLER_COMPLETED_WITHOUT_DELIVERY — a rule chain that completes without emitting is otherwise silent in every diagnostic and reads exactly like one still running.
hub.NoteRequestStage(requestId, stage) — the seam a HANDLER uses to report on work it detached from the rule chain. The canonical mesh handlers return request.Processed() immediately and owe their reply from a composed observable, so the pipeline's own HANDLER_EXIT proves nothing about whether a reply is coming. HandleCreateNodeRequest — the handler named in every capture — now records CREATE_CHAIN_SUBSCRIBED / _EMITTED / _ERROR / _COMPLETED_EMPTY plus the post-creation handler arms.
A verdict per trail, so the report states the shape instead of leaving it to be inferred.

While instrumenting (2) I found that the create handler's outer Subscribe has no onCompleted arm, and both save paths filter with .Where(n => n is not null). An empty completion there posts nothing and the caller waits forever — the #981 signature exactly. The new arm records it and deliberately does not post: which response is correct depends on why the chain went empty, and that is unknown until a capture names the branch. Recording is instrumentation; posting would be a guessed fix. Flagging it here as a code-reading observation, not a proven cause.

Cost and bounds

Entries exist only for ids with a live Observe callback, and are dropped the moment one resolves, is cancelled, or its subscription is disposed — so the ledger is bounded by the in-flight set, needs no eviction policy, and needs no Clear() for test isolation.
One ledger per hub tree (the root creates it, hosted hubs inherit their parent's instance) — an instance owned by the mesh, no static state. The tree scope is what lets the RECEIVING hub's stages land on the trail the REQUESTING hub reads.
Hot path: one ConcurrentDictionary lookup that short-circuits on an empty ledger. Stage strings are formatted only after a lookup HITS, so an un-awaited delivery allocates nothing.
A long trail keeps its head and its tail, suppressing the middle — the terminal stages decide the verdict, so they can never be the part that gets dropped. Rendering is capped by the existing PendingCallbackLogCap.

Reaching CI

The trail rides the channel that already works: QuiescingTimeoutDetail → GetQuiescingTimeoutSummary() → MonolithMeshTestBase's DISPOSE_QUIESCE_LEAK phase trace → /tmp/meshweaver-test-trace.log, which dotnet-test.yml copies with if: always(). All four reported #981 members derive from MonolithMeshTestBase.

Two checks against known traps:

Not budget-suppressed. TestPhaseTrace writes through TestTraceLog.Append, not AppendFault, so FaultRecordBudget (Bound the trace log's fault RATE, not its lifetime total — a spent budget silenced the wedge #994) does not apply and no [FAULT-BUDGET] marker can swallow these records.
No configuration to get wrong (Three read-after-write flakes, three unrelated defects (#978) #997's duplicate-appsettings.json failure). TestTraceLog writes to a fixed path and reads no config, so there is no per-project file that could win locally and lose on CI.

The trail is also rendered on two other paths: [STALE-CALLBACK] (fires while the mesh is still live — relevant because #981's callbacks go unanswered ~3.1 s before Dispose() is invoked; dial MESHWEAVER_STALE_CALLBACK_MS down on a repro run) and GetDisposalDiagnostics (the DISPOSE_TIMEOUT case, where no QuiescingTimeoutDetail exists yet).

Also in this PR

HandleCreateNodeRequest's doc-comment claimed its async work was wrapped in Observable.FromAsync. It is not, and that pattern is forbidden outside IoPool — a stale doc advertising a banned pattern is one copy away from becoming true. Corrected, with the reason.

Verification

dotnet build MeshWeaver.slnx -c Release -warnaserror — 0 warnings, 0 errors.
MeshWeaver.Messaging.Hub.Test — 156/156, including three new tests that pin the trail and two verdicts end-to-end: a self-addressed request handled but unanswered (the Callbacks still pending past the teardown quiescing budget (FutuRe EuropeRe, Cession, PandasExplorer) — a CreateNodeRequest the mesh hub never answers #981 shape), the same across two hubs (which is what proves the ledger is tree-scoped), and a reply posted to the wrong target, which must not read like a handler that never replied.
MeshWeaver.Graph.Test — 850/850 (exercises the instrumented create path).
DocumentationLinkIntegrityTest — green.

No What's New entry: internal test/diagnostic infrastructure, nothing user-facing.

🤖 Generated with Claude Code

Refs #981. Every capture of the pending-callback teardown failure has been caller-only: the hub names the request type, its target and its age, and nothing about what happened to the delivery at the receiving end. Two occurrences (2738ms and 6153ms against a 2s budget, both a CreateNodeRequest addressed to the mesh hub itself, every queue empty) therefore left the mechanism unnamed. RequestFateLedger records, per AWAITED request id, the stages the delivery actually reached — posted, received, routed, deferred, dropped, handler entered/exited with a state, and whether a response was ever posted for that correlation. One ledger per hub tree (the root creates it, hosted hubs inherit their parent's), so the hub that registered the callback and the hub that received the delivery write to the same trail. It holds only ids with a live Observe callback and drops each the moment it resolves, so it is bounded by the in-flight set; the hot path is one dictionary lookup that short-circuits on an empty ledger and formats nothing when it misses. The trail is folded into QuiescingTimeoutDetail, which MonolithMeshTestBase already writes to /tmp/meshweaver-test-trace.log (the one diagnostic CI keeps). Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Refs #981. Three places report a pending callback and all three were caller-only: - [QUIESCE-TIMEOUT] (teardown budget) — already enriched in the previous commit. - [STALE-CALLBACK] — the scanner that fires while the mesh is still SERVING. This is the one that matters for #981's first hard constraint: the callback predates disposal by ~3.1s on a fully live mesh, so teardown only DETECTS it. Dial MESHWEAVER_STALE_CALLBACK_MS down on a repro run and this line names the handler side before disposal is involved at all. - GetDisposalDiagnostics — what the test base writes on a DISPOSE_TIMEOUT, i.e. the case where the hub never reached its quiescing timeout and so has no QuiescingTimeoutDetail to read. Also documents how to read the trail (and what it cannot see) in DebuggingMessageFlow.md, next to the manual Trace-log reconstruction it replaces. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

…f403445e4e8

…chain Refs #981. The open question is binary — does the chain that owes the reply complete SLOWLY, or terminate WITHOUT responding? A trail that only says "no reply yet" reproduces exactly that ambiguity, so three things close it: - HANDLER_COMPLETED_WITHOUT_DELIVERY — a rule chain that completes without emitting is otherwise silent in every diagnostic and reads identically to one still running. - hub.NoteRequestStage(requestId, stage) — the seam a HANDLER uses to report on work it detached from the rule chain. The canonical mesh handlers return Processed() immediately and owe their reply from a composed observable, so the pipeline's own HANDLER_EXIT proves nothing about whether a reply is coming. HandleCreateNodeRequest — the handler named in every #981 capture — now records CREATE_CHAIN_SUBSCRIBED / _EMITTED / _ERROR / _COMPLETED_EMPTY and the post-creation handler arms. Its outer Subscribe had NO onCompleted arm, and two save paths filter with .Where(n => n is not null), so an empty completion posts nothing and the caller waits forever. The new arm RECORDS that and deliberately does NOT post — which response is correct depends on WHY the chain went empty, and that is unknown until a capture names the branch. Instrumentation, not a guessed fix. - A verdict line per trail, so the report states which failure shape it is instead of leaving the reader to infer it. Two verdicts are pinned by tests, including the discriminator that matters most: a reply posted but lost on the way home must not read like a handler that never replied (one says chase the response delivery, the other says chase the handler). Also corrects HandleCreateNodeRequest's doc-comment, which claimed the async work was wrapped in Observable.FromAsync. It is not, and that pattern is now forbidden outside IoPool — a stale doc advertising a banned pattern is one copy away from becoming true. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Refs #981. A head-only stage cap was actively harmful: HANDLER_EXIT, RESPONSE_POSTED, *_COMPLETED_EMPTY and faults are always the LAST stages, and a cross-hub request already spends ~12 stages on routing hops before a handler is entered at all. The cap would have silently truncated exactly the evidence the verdict reads. Keep the first 10 and a sliding last 8; suppress the middle and say so. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

…f403445e4e8

Copilot

Pull request overview

Adds handler-side instrumentation to pending-callback / quiescing-timeout diagnostics so #981 captures can distinguish “never delivered”, “no handler matched”, “handler ran but didn’t reply”, and “reply was posted but lost”.

Changes:

Introduces RequestFateLedger, a hub-tree-scoped in-flight ledger that records request/response delivery stages and emits a single “verdict” per pending callback.
Threads fate-stage recording through MessageService/MessageHub post, routing, deferral, handler-enter/exit, and response-arrival paths; exposes hub.NoteRequestStage(...) for handlers with detached work.
Adds end-to-end tests pinning the enriched quiescing-timeout summary (including cross-hub and misrouted-reply discriminators) and documents how to read the new trail.

Reviewed changes

Copilot reviewed 7 out of 7 changed files in this pull request and generated 1 comment.

Show a summary per file

File	Description
test/MeshWeaver.Messaging.Hub.Test/QuiescingTimeoutNamesHandlerSideTest.cs	New tests that pin the enriched quiescing-timeout output and key fate/verdict distinctions.
src/MeshWeaver.Messaging.Hub/RequestFateLedger.cs	New in-flight ledger that records handler-side request fate stages and renders a capped trail + verdict.
src/MeshWeaver.Messaging.Hub/MessageService.cs	Records fate stages across intake, routing, deferral/drop, handler execution, and correlated response posting.
src/MeshWeaver.Messaging.Hub/MessageHubExtensions.cs	Adds `NoteRequestStage` extension for handlers to record detached-chain terminal stages.
src/MeshWeaver.Messaging.Hub/MessageHub.cs	Hooks fate rendering into `[STALE-CALLBACK]`, quiesce-timeout, and disposal diagnostics; tracks/untracks with response-subject lifecycle.
src/MeshWeaver.Mesh.Contract/MeshExtensions.cs	Instruments `HandleCreateNodeRequest` with `NoteRequestStage` stages (subscribe/emitted/error/completed-empty) and updates the related doc comment.
src/MeshWeaver.Documentation/Data/Architecture/DebuggingMessageFlow.md	Documents the new handler-side fate trail and how to interpret the verdicts/stage omissions.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Refs #981. A local trace holds 30 DISPOSE_QUIESCE_LEAK records and 26 of them say "0 pending callback(s) after 2.00s: <none>" — the poll reported not-drained, and by the time the verdict was rendered every callback had already resolved inside the timeout hand-off. Nothing leaked; the detector raced its own budget. But the report is indistinguishable at a glance from #981's, and "<none>" reads as a diagnostic that failed to collect its evidence, so an investigator hunts a leak that was never there. Three classes produce it locally (TodoDataChangeWorkflowTest, TodoGraphIntegrationTest, TodoViewsTest). Say what actually happened instead. Behaviour is unchanged — the hub still flags QuiescingTimedOut and the class still fails; only the sentence changes, so a grep over the trace can separate the two shapes. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

…f403445e4e8

github-actions · 2026-08-09T13:16:07Z