fix(#3477): correlate a re-enqueued write with the NACK that caused it by rbuergi · Pull Request #3532 · Systemorph/MeshWeaver

rbuergi · 2026-09-07T05:43:16Z

Closes #3477.

Pairs-with: none — adds no public type or member and removes none; format arguments, one new log line, one test.

Parser-delta: none — does not touch scripts/check-type-forwards.py.

The defect: a fresh `requestId` per attempt, so the chain broke exactly where it mattered

var requestId = Guid.NewGuid().AsString();      // ~1941, per ATTEMPT
lateRegistry?.Register(requestId, _path!, resp => { … });

The re-enqueue calls UpdateRemote(update, attempt + 1, …), which runs that line again and registers under a different id. So after

[UpdateRemote] LATE_NACK_REENQUEUE … attempt=1 code=OwnerDisposing

there was no id to follow, and the three outcomes were indistinguishable in the log: the re-enqueue never left the cache hub; it left and never activated the owner; it activated and never answered. #3477's own words — "a write that was NACKed, re-enqueued and then neither applied nor answered is the write-loss class this test exists to refuse" — and it could not be attributed.

The fix: one correlation id, minted at entry, inherited by every re-attempt

UpdateRemote gains correlationId; corr = correlationId ?? Guid.NewGuid().AsString() mints once at the caller's entry, and both re-enqueue arms pass correlationId: corr.

corr= now appears on BEGIN, LATE_ACK, LATE_NACK_REENQUEUE, LATE_NACK_REENQUEUE failed, OWNER_NACK_REENQUEUE and VERDICT_TIMEOUT — the last being the line an operator actually reaches for, which now carries the instruction outright: grep corr=<id> yields every attempt of this write, including re-enqueues that registered under a different requestId. A new LATE_VERDICT_REGISTERED names the per-attempt requestId beside the stable corr.

Purely additive. Nothing new is awaited, bounded or retried; no behaviour changes.

🚨 Why it matters more since tonight

#3505 reclassifies owner-side teardown faults as OwnerDisposing, which feeds this arm — and not incidentally. Once HostedHubsCollection closes a hosted hub's scope, the hub is past DisposeHostedHubs, PostImplGeneric refuses its own post, and the verdict routes through ILatePatchVerdictSink by construction: the late half, which is the half #3477 measured going dark. #3505's cost argument — "a false retryable costs at most two idempotent re-diffs" — holds only if the re-enqueue answers.

Log levels, stated rather than assumed

src/ levels are committed contract, not a verbosity knob. LATE_VERDICT_REGISTERED and BEGIN are Debug — one per write and one per late-registered write, on the hot path. The Warning that pays for them is VERDICT_TIMEOUT, which fires only once a write has already failed to settle, i.e. exactly when the chain is worth its cost.

🚨 What the test covers — and what it does NOT

LateNackReenqueueCorrelationTest drives the real sequence on the sibling's proven rig: park the owner's merge executor, write cross-hub, fence on the armed late watch, fence on the handler having run, dispose the owner so its NACK is necessarily late. It then asserts the LATE_NACK_REENQUEUE line carries a correlation id — which before this change it did not. Passes in ~190 ms, deterministic: a disposed owner's post is refused, so the verdict routes through the late sink immediately rather than after the 2 s response bound.

It deliberately does not assert on the write landing — its sibling LateNackReenqueueTest does, and is 1-in-330 flaky on exactly that wait, which is #3477's own open subject.

And it does not pin INHERITANCE. That needs the re-attempt's own BEGIN, which is LogDebug and is dropped by the harness's filter before any provider sees it. Two attempts to raise that filter for one category did not reach the factory the hub resolves. The honest options were to promote a hot-path line to Information so a test could see it — forbidden — or to say so. So the inheritance is guaranteed by the two call sites passing correlationId: corr, which the compiler checks and no test does. That gap is stated in the test's own doc comment and on the issue, rather than left for someone to find behind a green suite.

Verification

MeshWeaver.Mesh.Contract Release -warnaserror → 0 Warning(s), 0 Error(s)
MeshWeaver.Graph.Test Release -warnaserror → 0 Warning(s), 0 Error(s)
LateNackReenqueueCorrelationTest → 1 passed, real .trx, and the captured line verified in the run output: LATE_NACK_REENQUEUE … code=OwnerDisposing corr=s00FLGaix0yWYK2z8alWWQ

After LATE_NACK_REENQUEUE the trail went dark. The late registry mints a FRESH requestId per attempt, so the re-enqueued write registered under an id unrelated to the one that produced it — and "the re-enqueue never left the cache hub", "it never activated the owner" and "it activated and never answered" were indistinguishable in the log. A write that was NACKed, re-enqueued and then neither applied nor answered is the write-loss class LateNackReenqueueTest exists to refuse, and it could not be attributed. UpdateRemote now threads ONE correlation id, minted at the caller's entry and passed unchanged into both re-enqueue arms, on BEGIN, LATE_ACK, LATE_NACK_REENQUEUE (+ its failure), OWNER_NACK_REENQUEUE and VERDICT_TIMEOUT — which is the line an operator actually reaches for, and which now says to grep the corr for the whole chain. A new LATE_VERDICT_REGISTERED names the per-attempt requestId beside it. Purely additive diagnostics: nothing is awaited, bounded or retried, and no behaviour changes. Levels are deliberate — registration at Debug (one per late-registered write, hot path), the Warning that pays for it is VERDICT_TIMEOUT, which fires only once a write has already failed to settle. This matters more since #3505: reclassifying owner teardown as OwnerDisposing routes MORE traffic into this arm, and preferentially into the late half.

Copilot

🟡 Changes recommended

The new test contains a direct await on an IObservable (violating the repo’s ObservableAwait.Await convention) and has misleading/internally inconsistent documentation/naming that should be corrected before merge.

Once you've addressed the issues Copilot identified, you can request another Copilot review.

Pull request overview

Adds end-to-end log correlation for re-enqueued cross-hub mesh node writes by threading a stable corr id through UpdateRemote attempts, and introduces a regression test to ensure the late NACK re-enqueue log line carries that correlation id so operators can follow the full attempt chain.

Changes:

Extend MeshNodeStreamExtensions.UpdateRemote with an optional correlationId, mint once per write chain, and include corr= in key diagnostic logs (BEGIN, LATE_*, OWNER_*, VERDICT_TIMEOUT).
Add a new LATE_VERDICT_REGISTERED debug log that records both corr and the per-attempt requestId.
Add a new test that drives the late-OwnerDisposing NACK path and asserts LATE_NACK_REENQUEUE includes a non-empty corr.

File summaries

File	Description
test/MeshWeaver.Graph.Test/LateNackReenqueueCorrelationTest.cs	New test to exercise the late NACK re-enqueue path and validate the presence of `corr=` in the diagnostic log trail.
src/MeshWeaver.Mesh.Contract/MeshNodeStreamExtensions.cs	Thread a stable correlation id through `UpdateRemote` reattempts and add/augment diagnostic logging to make re-enqueue chains followable.

Review details

Files reviewed: 2/2 changed files
Comments generated: 4
Review effort level: Lite

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

+                .Configure<LoggerFilterOptions>(o =>
+                {
+                    o.MinLevel = LogLevel.Debug;
+                    o.Rules.Add(new LoggerFilterRule(
+                        providerName: null,
+                        categoryName: "MeshWeaver.Mesh.MeshNodeStreamHandle",
+                        logLevel: LogLevel.Debug,
+                        filter: null));
+                }));


+            var reenqueue = await captured.FirstMatching(
+                @"LATE_NACK_REENQUEUE .*corr=(?<corr>[^\s]+)", TestTimeouts.Convergence);


+/// <para>The fix threads ONE correlation id, minted at the caller's entry and passed unchanged into
+/// every re-attempt. This test pins that inheritance: the re-attempt's own <c>BEGIN</c> must carry
+/// the SAME <c>corr=</c> as the <c>LATE_NACK_REENQUEUE</c> that caused it.</para>


+                }));
+
+    [Fact(Timeout = 90_000)]
+    public async Task AReenqueuedAttemptInheritsTheCorrelationIdOfTheNackThatCausedIt()


github-actions · 2026-09-07T05:47:45Z