Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 17 additions & 0 deletions src/MeshWeaver.Documentation/Data/Architecture/TeardownLayers.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
53 changes: 46 additions & 7 deletions src/MeshWeaver.Messaging.Hub/MessageService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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.",
Comment on lines +2928 to +2929
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: "
Expand Down
Original file line number Diff line number Diff line change
@@ -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;
Expand Down Expand Up @@ -44,7 +45,14 @@ public class DeferredDeliveryNackedOnDisposeTest : HubTestBase

public DeferredDeliveryNackedOnDisposeTest(ITestOutputHelper output) : base(output)
{
Services.AddLogging(l => l.Services.AddSingleton<ILoggerProvider>(log));
Services.AddLogging(l =>
{
l.Services.AddSingleton<ILoggerProvider>(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<DeferredLog>(null, LogLevel.Debug);
});
}

private record GatedRequest : IRequest<GatedResponse>;
Expand Down Expand Up @@ -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");

/// <summary>
/// Systemorph/MeshWeaver#4178 — the <c>$model-probe</c> shape. A hub disposed with its OWN
/// deferred request strands NOBODY, so event 7301 must report it at Debug, not Error.
///
/// <para><b>Why it is not a silenced fault.</b> <c>NackThroughParent</c> declines this
/// delivery one method down with <c>NACK_DECLINED reason=sender-is-self</c> — 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 <c>Dispose</c>. 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 <c>$model-probe/{guid}</c> discarding its own
/// <c>GetDataRequest</c> — a lifetime <c>TransientNodeProbe</c> declares by design.</para>
///
/// <para><b>Negative control.</b> 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.</para>
/// </summary>
// 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<GatedRequest>((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");
Comment on lines +173 to +175
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)");
}

/// <summary>
/// Polls the public disposal diagnostics (which report <c>deferred=&lt;N&gt;</c> per hub,
/// walking hosted hubs) until something is parked. The gated hub is the only hub in this test
Expand All @@ -126,19 +196,26 @@ await Observable.Interval(TimeSpan.FromMilliseconds(50))
}
private sealed class DeferredLog : ILoggerProvider
{
public ConcurrentQueue<string> Messages { get; } = new();
public ILogger CreateLogger(string categoryName) => new Capture(Messages);
public ConcurrentQueue<(LogLevel Level, string Message)> Lines { get; } = new();

/// <summary>Event 7301 messages, any level — what the original assertions read.</summary>
public IEnumerable<string> Messages => Lines.Select(l => l.Message);

public IEnumerable<string> 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<string> messages) : ILogger
private sealed class Capture(ConcurrentQueue<(LogLevel, string)> lines) : ILogger
{
public IDisposable? BeginScope<TState>(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<TState>(LogLevel level, EventId eventId, TState state,
Exception? exception, Func<TState, Exception?, string> formatter)
{
if (eventId.Id == 7301)
messages.Enqueue(formatter(state, exception));
lines.Enqueue((level, formatter(state, exception)));
}
}
}
Expand Down
Loading