From 3c421609e677cde8634ef59c3e421706dcb46571 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Sun, 13 Sep 2026 16:53:16 +0200 Subject: [PATCH] =?UTF-8?q?fix(teardown):=20a=20hub=20disposing=20with=20i?= =?UTF-8?q?ts=20OWN=20deferred=20delivery=20strands=20nobody=20=E2=80=94?= =?UTF-8?q?=20Debug,=20not=20Error=20(#4178)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `MessageService.Dispose` logged event 7301 at Error for every deferred delivery it discarded, with the sentence "the sender is answered ShuttingDown". For a SELF-ADDRESSED delivery that sentence is false: `NackThroughParent` declines it one method down with `NACK_DECLINED reason=sender-is-self`, because the pending-response registry that would resolve it is this hub's own and is cancelled in the same disposal. The reader is told by `CancelCallbacks` instead ("Hub … was disposed before the response arrived") β€” a better report, to the same reader. So the Error alleged stranded work, named an answer that was never sent, and pointed the reader at a producer that had done nothing wrong. Measured (#4178): 76 Error lines per plugin-gate shard, every one a `$model-probe/{guid}` hub discarding its own `GetDataRequest` parked behind [DataContextInit,MeshNodeInit] β€” the lifetime `TransientNodeProbe` declares by design ("created, read once, disposed"), and which `MessageHub.HandleInitialize` already classifies as a recognized shutdown rather than a failure (#1122-#1125). The rule is the FACT, not the probe: when the sender IS this hub, nobody outside is waiting, so the discard is teardown-internal. The line still fires and still names the message, id, gates and run level β€” at Debug, with a sentence that no longer claims an answer went out. A delivery from any OTHER sender still strands a real waiter on a transient NACK and stays an Error, unchanged. Both halves pinned, each watched failing: - widen the predicate to always-true -> the external-sender test reds for LOSING the Error - narrow it to always-false -> the self-addressed test reds for STOPPING to report The second control is the one that matters: a reclassification that quietly stopped reporting would be a silenced fault, not a classification. Docs: TeardownLayers.md gains the split; What's New entry (Fix). Co-Authored-By: Claude Opus 5 (1M context) --- .../Data/Architecture/TeardownLayers.md | 17 ++++ ...own-question-unanswered-is-not-an-error.md | 53 +++++++++++ .../MessageService.cs | 53 +++++++++-- .../DeferredDeliveryNackedOnDisposeTest.cs | 93 +++++++++++++++++-- 4 files changed, 201 insertions(+), 15 deletions(-) create mode 100644 src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-13-a-hub-disposing-with-its-own-question-unanswered-is-not-an-error.md diff --git a/src/MeshWeaver.Documentation/Data/Architecture/TeardownLayers.md b/src/MeshWeaver.Documentation/Data/Architecture/TeardownLayers.md index a69b2dac95..86885b459a 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/TeardownLayers.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/TeardownLayers.md @@ -264,6 +264,23 @@ version) and logged at **Error** (`[DISPOSE-DISCARD]`, event 7301) with the mess sender, the gates it sat behind and the run level. A hub that disposes with its gates still shut is the defect that line points at. +🚨 **Unless the sender is the hub ITSELF β€” then it is Debug, and the reason is one method down.** +`NackThroughParent` declines a self-addressed delivery with `NACK_DECLINED reason=sender-is-self`: +there is nothing to post an answer *to*, because the pending-response registry that would resolve it +is this hub's own and is cancelled in the same `Dispose` (`CancelCallbacks` errors those subjects +with *"Hub … was disposed before the response arrived"* β€” a more informative report, reaching the +same reader). So the Error's own sentence, *"the sender is answered `ShuttingDown`"*, was **false** +for exactly that shape, and the defect it told the reader to hunt has no external victim to find. +Measured in [#4178](https://github.com/Systemorph/MeshWeaver/issues/4178): 76 Error lines per +plugin-gate shard, every one a `$model-probe/{guid}` hub discarding its **own** `GetDataRequest` +parked behind `[DataContextInit,MeshNodeInit]` β€” a lifetime [Transient Node +Probe](/Doc/Architecture/TransientNodeProbes) declares by design ("created, read once, disposed"), +and which `MessageHub.HandleInitialize` already classifies as a recognized shutdown rather than a +failure (#1122–#1125). The rule is the **fact, not the probe**: whenever the sender is this hub, +nobody outside is waiting, so the discard is teardown-internal. The line still fires, still names the +gates β€” only the level and the sentence follow what actually happened. A delivery from any **other** +sender strands a real waiter on a transient NACK and stays an Error, unchanged. + 🚨 **There used to be a second, and it was not real.** Event 7302 reported the turns still in the MAIN queue when `messageService.Dispose()` ran, at Error, claiming *"the pump stops with this call"*. **The pump does not stop with that call and cannot**: `Dispose()` is invoked from inside the diff --git a/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-13-a-hub-disposing-with-its-own-question-unanswered-is-not-an-error.md b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-13-a-hub-disposing-with-its-own-question-unanswered-is-not-an-error.md new file mode 100644 index 0000000000..4527d9163c --- /dev/null +++ b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-13-a-hub-disposing-with-its-own-question-unanswered-is-not-an-error.md @@ -0,0 +1,53 @@ +--- +Name: A hub disposing with its own question unanswered is no longer reported as lost work +Category: Fix +Description: A transient type probe is created, read once and disposed β€” by design. When it was torn down with its own self-addressed read still parked behind its initialization gates, the teardown reported an Error claiming the sender had been answered. Nobody had been answered, and nobody was waiting: the sender was the probe itself. 76 such lines per gate shard. The line now follows the fact. +Icon: Checkmark +Order: -20260913 +--- + +A hub that is disposed while a message it accepted is still parked behind an initialization gate +reports that at **Error**, and it should: the message never ran, its sender gets a transient +`ShuttingDown` NACK instead of an answer, and somebody has to find out why the hub went down with +its gates still shut. That contract is in [Teardown Layers](/Doc/Architecture/TeardownLayers). + +There is one shape where every clause of that sentence is false, and it was the loudest one in +production. A **transient node probe** β€” the short-lived hub a NodeType's instance configuration is +applied to so its type registry can be read β€” is *created, read once and disposed*, in that order, +on purpose ([Transient Node Probes](/Doc/Architecture/TransientNodeProbes)). The configuration it +applies was written for a real per-node hub, where the hub's address IS its mesh path, so a loader +deriving a path from the hub's address and reading it is ordinary, correct code β€” and on the probe +that derivation collapses onto the probe's own synthetic address. The probe asks itself a question, +the question parks behind the probe's own `DataContextInit` / `MeshNodeInit` gates, and the probe is +disposed before they open. + +The teardown then logged: + +``` +[DISPOSE-DISCARD] Hub $model-probe/f27ab9f9… is disposing with GetDataRequest +(id=beQyWMaX60eN-jRJQeKllw, from $model-probe/f27ab9f9…) still deferred; initialization gates +closed at deferral: [DataContextInit,MeshNodeInit] β€” the message is NOT processed; the sender is +answered ShuttingDown. +``` + +**The sender was not answered.** One method below the log call, `NackThroughParent` declines exactly +this delivery β€” `NACK_DECLINED reason=sender-is-self` β€” because there is nowhere to post the answer: +the pending-response registry that would resolve it belongs to this hub and is being cancelled in the +same disposal. The reader that would have received it is told by a different and better route +(`CancelCallbacks` errors those subjects with *"Hub … was disposed before the response arrived"*). +So the Error alleged stranded work, named an answer that was never sent, and told whoever read it to +go and find a producer that had done nothing wrong. + +It was not rare. Measured on a plugin-gate shard: **76 of these per shard**, every one a probe +discarding its own read. + +The classification now follows what happened. When the sender is this hub itself, the discard is +teardown-internal: the line still fires, still names the message, the id, the gates it sat behind and +the run level β€” at **Debug**, and with a sentence that no longer claims an answer went out. When the +sender is any **other** hub, a real waiter is left holding a transient NACK, and that stays an Error +exactly as before. + +Both halves are pinned by tests that were each watched failing: removing the split turns the +self-addressed case red for *stopping to report*, and widening it turns the external-sender case red +for *losing the Error*. A reclassification that quietly stopped reporting would have been a silenced +fault rather than a classification. diff --git a/src/MeshWeaver.Messaging.Hub/MessageService.cs b/src/MeshWeaver.Messaging.Hub/MessageService.cs index f3ba39301c..1909aeeedf 100644 --- a/src/MeshWeaver.Messaging.Hub/MessageService.cs +++ b/src/MeshWeaver.Messaging.Hub/MessageService.cs @@ -2887,17 +2887,56 @@ public void Dispose() // red-log pipeline files an Error as an issue. The line carries what a reader needs to // reproduce it: the hub, the message type and id, its sender, the gates it was parked // behind and this hub's run level. + // 🚨 …AND THE LEVEL FOLLOWS WHO IS STRANDED, because for a SELF-ADDRESSED delivery the + // answer is not merely undelivered β€” it is declined by design, one method down. + // + // `NackThroughParent` returns early with `NACK_DECLINED reason=sender-is-self` when + // `delivery.Sender` is this hub's own address: there is nothing to post an answer TO, since + // the pending-response registry that would resolve it is THIS hub's and is being cancelled + // in this same Dispose (CancelCallbacks errors those subjects with "Hub … was disposed + // before the response arrived" β€” a more informative report, delivered to the same reader). + // So the Error's own sentence, "the sender is answered ShuttingDown", was FALSE for exactly + // this shape, and the defect it told the reader to hunt ("find why this hub disposed before + // its deferred work could run") has no external victim to find. + // + // MEASURED (Systemorph/MeshWeaver#4178): 76 Error lines per plugin-gate shard, every one a + // `$model-probe/{guid}` hub discarding its OWN `GetDataRequest` parked behind + // [DataContextInit,MeshNodeInit]. A transient node probe is CREATED, READ ONCE AND DISPOSED + // β€” TransientNodeProbe states that outright, and MessageHub.HandleInitialize already + // classifies the same probe's dispose-during-init as a recognized shutdown rather than a + // failure (#1122–#1125). Its own-node read collapsing onto its synthetic address is the + // shape TransientProbeAddresses exists for; two other read seams already answer it + // directly, and this is the third, reached as a raw deferral. + // + // The rule is the FACT, not the probe: whenever the sender IS this hub, nobody outside is + // waiting, so the discard is teardown-internal and belongs at Debug β€” with the same facts, + // and a sentence that no longer claims an answer was sent. A delivery from ANY OTHER sender + // still strands a real waiter on a transient NACK and stays an Error, unchanged. This is + // the same discipline as the queued-turn site below (#3647): an Error that names work as + // lost, where no reader is left to act on it, sends the next investigator hunting a + // producer that did nothing wrong. var discarded = 0; DrainDeferredDeliveries((delivery, gatesAtDeferral) => { discarded++; - logger.LogError(DisposalDiscardedDeferredDelivery, - "[DISPOSE-DISCARD] Hub {Address} is disposing with {MessageType} (id={MessageId}, from {Sender}) " - + "still deferred; initialization gates closed at deferral: [{Gates}] β€” the message is NOT processed; " - + "the sender is answered ShuttingDown. RunLevel={RunLevel}. Accepted work must be drained " - + "before a hub goes down; find why this hub disposed before its deferred work could run.", - Address, delivery.Message.GetType().Name, delivery.Id, delivery.Sender, - gatesAtDeferral, hub.RunLevel); + if (delivery.Sender is null || delivery.Sender.Equals(Address)) + logger.LogDebug(DisposalDiscardedDeferredDelivery, + "[DISPOSE-DISCARD] Hub {Address} is disposing with its OWN {MessageType} " + + "(id={MessageId}) still deferred; initialization gates closed at deferral: [{Gates}]. " + + "RunLevel={RunLevel}. The sender IS this hub, so no answer is owed outside it and " + + "none is posted β€” this hub's pending-response registry is cancelled in the same " + + "disposal. Teardown-normal (a transient node probe is created, read once and " + + "disposed by design); not a discard of anybody else's work.", + Address, delivery.Message.GetType().Name, delivery.Id, + gatesAtDeferral, hub.RunLevel); + else + logger.LogError(DisposalDiscardedDeferredDelivery, + "[DISPOSE-DISCARD] Hub {Address} is disposing with {MessageType} (id={MessageId}, from {Sender}) " + + "still deferred; initialization gates closed at deferral: [{Gates}] β€” the message is NOT processed; " + + "the sender is answered ShuttingDown. RunLevel={RunLevel}. Accepted work must be drained " + + "before a hub goes down; find why this hub disposed before its deferred work could run.", + Address, delivery.Message.GetType().Name, delivery.Id, delivery.Sender, + gatesAtDeferral, hub.RunLevel); NackThroughParent(delivery, $"Hub {Address} was disposed while {delivery.Message.GetType().Name} " + $"(id={delivery.Id}) was still deferred; initialization gates closed at deferral: " diff --git a/test/MeshWeaver.Messaging.Hub.Test/DeferredDeliveryNackedOnDisposeTest.cs b/test/MeshWeaver.Messaging.Hub.Test/DeferredDeliveryNackedOnDisposeTest.cs index dc8086e76b..073a6908ee 100644 --- a/test/MeshWeaver.Messaging.Hub.Test/DeferredDeliveryNackedOnDisposeTest.cs +++ b/test/MeshWeaver.Messaging.Hub.Test/DeferredDeliveryNackedOnDisposeTest.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Concurrent; +using System.Collections.Generic; using System.Linq; using System.Reactive.Linq; using System.Text.RegularExpressions; @@ -44,7 +45,14 @@ public class DeferredDeliveryNackedOnDisposeTest : HubTestBase public DeferredDeliveryNackedOnDisposeTest(ITestOutputHelper output) : base(output) { - Services.AddLogging(l => l.Services.AddSingleton(log)); + Services.AddLogging(l => + { + l.Services.AddSingleton(log); + // Event 7301 is asserted at BOTH levels here, so the capture must be able to SEE a + // Debug line β€” otherwise "the Error is gone" and "the line vanished entirely" read + // identically and the self-addressed test would pass having checked nothing. + l.AddFilter(null, LogLevel.Debug); + }); } private record GatedRequest : IRequest; @@ -100,14 +108,76 @@ public async Task DeferredRequest_IsNacked_WhenHubIsDisposedBeforeItsGateOpens() failure.Failure!.ErrorType.Should().Be(ErrorType.ShuttingDown); failure.Failure.Message.Should().Contain("test-never-opens", "the shutdown answer must name the gates recorded before teardown opened them"); - log.Messages.Should().Contain(message => message.Contains("test-never-opens"), - "event 7301 must preserve the gate that actually held the delivery (#3712)"); + log.At(LogLevel.Error).Should().Contain(message => message.Contains("test-never-opens"), + "event 7301 must preserve the gate that actually held the delivery (#3712), and a " + + "delivery from ANOTHER hub strands a real waiter on a transient NACK β€” that stays " + + "an Error (the control for the self-addressed case below, #4178)"); failure.Failure.Message.Should().Contain("deferred", "the NACK must name WHY the message was abandoned β€” a bare failure sends the next " + "investigator hunting the wrong layer"); } + private static readonly Address SelfTalkerAddress = new("self-talker", "1"); + + /// + /// Systemorph/MeshWeaver#4178 β€” the $model-probe shape. A hub disposed with its OWN + /// deferred request strands NOBODY, so event 7301 must report it at Debug, not Error. + /// + /// Why it is not a silenced fault. NackThroughParent declines this + /// delivery one method down with NACK_DECLINED reason=sender-is-self β€” there is no + /// external registry to post an answer to, because the pending-response registry that would + /// resolve it is this hub's own and is cancelled in the same Dispose. So the Error's + /// sentence "the sender is answered ShuttingDown" was false for this shape, and the defect it + /// told the reader to hunt has no victim. Production measurement in #4178: 76 such lines per + /// plugin-gate shard, every one a $model-probe/{guid} discarding its own + /// GetDataRequest β€” a lifetime TransientNodeProbe declares by design. + /// + /// Negative control. The Debug line is asserted POSITIVELY (it must exist, and + /// name the gate), so "classified as teardown-normal" cannot be confused with "the site stopped + /// reporting". The external-sender Error is pinned by the test above, on the same event id. + /// + // No literal method timeout: every wait below carries TestTimeouts.Convergence, which is the + // reasoned bound, and xunit.runner.json's methodTimeout bounds the body. A hand-written + // `Timeout = 30_000` here would be a guessed wait on top of a measured one + // (TestTimeoutLiteralRatchetGuard). + [Fact] + public async Task SelfAddressedDeferredRequest_IsTeardownNormal_NotAnError() + { + var host = GetHost(); + + var selfTalker = host.GetHostedHub( + SelfTalkerAddress, + c => c.WithTypes(typeof(GatedRequest), typeof(GatedResponse)) + // The hub posts on its own behalf below; PostPipeline fails closed with no + // AccessContext, so the infrastructure identity is what a probe hub carries too. + .WithPostingIdentity(PostingIdentity.System) + .WithInitializationGate("self-gate-never-opens", _ => false) + .WithHandler((h, d) => + { + h.Post(new GatedResponse(), o => o.ResponseFor(d)); + return d.Processed(); + })); + selfTalker.Should().NotBeNull(); + + // THE SHAPE: the hub posts to ITSELF, so Sender == Target == this hub's address β€” + // byte-for-byte the production line's "Hub $model-probe/x … (from $model-probe/x)". + selfTalker!.Post(new GatedRequest(), o => o.WithTarget(SelfTalkerAddress)); + + await WaitForDeferredBacklog(host); + + host.Post(new DisposeRequest(), o => o.WithTarget(SelfTalkerAddress)); + await selfTalker.DisposalCompleted.FirstAsync().Timeout(TestTimeouts.Convergence) + .Await(TestContext.Current.CancellationToken); + + log.At(LogLevel.Debug).Should().Contain(m => m.Contains("self-gate-never-opens"), + "the discard must STILL be reported and still name the gate that held it β€” a " + + "reclassification that stops reporting would be a silenced fault, not a classification"); + log.At(LogLevel.Error).Should().NotContain(m => m.Contains("self-gate-never-opens"), + "the sender IS this hub, so no answer is owed outside it and NackThroughParent declines " + + "it as sender-is-self β€” an Error here alleges stranded work that has no waiter (#4178)"); + } + /// /// Polls the public disposal diagnostics (which report deferred=<N> per hub, /// walking hosted hubs) until something is parked. The gated hub is the only hub in this test @@ -126,19 +196,26 @@ await Observable.Interval(TimeSpan.FromMilliseconds(50)) } private sealed class DeferredLog : ILoggerProvider { - public ConcurrentQueue Messages { get; } = new(); - public ILogger CreateLogger(string categoryName) => new Capture(Messages); + public ConcurrentQueue<(LogLevel Level, string Message)> Lines { get; } = new(); + + /// Event 7301 messages, any level β€” what the original assertions read. + public IEnumerable Messages => Lines.Select(l => l.Message); + + public IEnumerable At(LogLevel level) => + Lines.Where(l => l.Level == level).Select(l => l.Message).ToArray(); + + public ILogger CreateLogger(string categoryName) => new Capture(Lines); public void Dispose() { } - private sealed class Capture(ConcurrentQueue messages) : ILogger + private sealed class Capture(ConcurrentQueue<(LogLevel, string)> lines) : ILogger { public IDisposable? BeginScope(TState state) where TState : notnull => null; - public bool IsEnabled(LogLevel level) => level >= LogLevel.Error; + public bool IsEnabled(LogLevel level) => level >= LogLevel.Debug; public void Log(LogLevel level, EventId eventId, TState state, Exception? exception, Func formatter) { if (eventId.Id == 7301) - messages.Enqueue(formatter(state, exception)); + lines.Enqueue((level, formatter(state, exception))); } } }