From 9de6a757305b5e5eeb25ebf5938f526c81f9259c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Wed, 9 Sep 2026 13:31:03 +0200 Subject: [PATCH] diag(#3510): [QUIESCE-START] names who asked for the teardown MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #3510's wedge turned on one unknown the log could not answer. The Hosting root was disposed at 23:37:51Z WHILE its own 145-file install was in flight; its per-node children went with it; the writes they owed acks for were stranded; four creates never got a reply and the install ran out a ten-minute bound. The issue's own words: "Who disposed the root is not in the log at this level" — so the leading hypothesis, a NodeType rebind posting DisposeRequest to the root, stayed a hypothesis. Its Expected section asks for this line. 🚨 The ShutdownRequest's own sender cannot answer it, which is why nothing was there to read: Dispose() posts that request to ITSELF, so its Sender is always the dying hub — the field that looks like it answers "who asked" is the one field that cannot. The discriminating fact is one frame earlier: whether a DisposeRequest arrived over the bus at all, and from where. Recorded in HandleDispose, at the point such a request is HONOURED — not merely received, since the root-mesh refusal above it returns without disposing. Three readings, because a reader has three real cases to tell apart: requested by portal/installer (routed DisposeRequest) requested by itself — a self-posted DisposeRequest (Hosting), i.e. a rebind or self-heal recycle requested by a direct Dispose() (no routed DisposeRequest) 🚨 The self-posted case is called out rather than printed as an address. The automatic recycles post to their OWN hub (NodeTypeRebindWatcher, WithOverlaySelfHeal), so a bare sender renders "Hosting: requested by Hosting" — true, useless, and easy to misread as a routing oddity. That case is #3510's leading hypothesis, so it is the one reading that must not be ambiguous. 🚨 The third is not an absence of information: it rules out the whole message path in one reading, which is the deduction #3510 could not make. Negative control: run against the previous log line, all three assertions of QuiesceStartNamesTheAskerTest fail. 🚨 And the first version of that test observed NOTHING — a precondition guard caught it rather than a vacuous pass. TestBase binds log-level filters from test/appsettings.json (logging.AddConfiguration("Logging")), which leaves MeshWeaver above Information, so the line is dropped before any provider sees it; the sibling DisposalDeadlockDiagnosticsTest works without noticing because the verdicts it captures are Errors. The test raises the filter in its own DI — the src-tree appsettings.json is committed contract and is not edited to make a test see a line. The wait uses TestTimeouts.Convergence, never a literal: the TestTimeoutLiteralRatchetGuard holds the hand-written count to a number that only goes down, and caught the literal I first wrote. This does NOT stop a shutdown landing mid-install. #3510's other two Expectations — defer a recycle while an install holds the root, or NACK every in-flight write under it — are untouched and the issue stays open for them. Verified: solution build Release -warnaserror 0 warnings 0 errors; Messaging.Hub.Test 387, Documentation.Test 368, Hosting.Test 539 passed. Co-Authored-By: Claude Opus 5 (1M context) --- .../Architecture/DisposalStallVerdicts.md | 44 +++++ ...6-09-09-the-shutdown-log-says-who-asked.md | 36 ++++ src/MeshWeaver.Messaging.Hub/MessageHub.cs | 51 +++++- .../QuiesceStartNamesTheAskerTest.cs | 156 ++++++++++++++++++ 4 files changed, 285 insertions(+), 2 deletions(-) create mode 100644 src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-09-the-shutdown-log-says-who-asked.md create mode 100644 test/MeshWeaver.Messaging.Hub.Test/QuiesceStartNamesTheAskerTest.cs diff --git a/src/MeshWeaver.Documentation/Data/Architecture/DisposalStallVerdicts.md b/src/MeshWeaver.Documentation/Data/Architecture/DisposalStallVerdicts.md index 5d029ecb21..c15f8639ea 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/DisposalStallVerdicts.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/DisposalStallVerdicts.md @@ -256,6 +256,50 @@ mesh, which the attached recursive snapshot lists. --- +## Who asked for the teardown + +`[QUIESCE-START]` names the requester (#3510): + +``` +[QUIESCE-START] Hosting: requested by portal/installer (routed DisposeRequest); 4 pending callbacks … +[QUIESCE-START] Hosting: requested by itself — a self-posted DisposeRequest (Hosting), i.e. a rebind or self-heal recycle; … +[QUIESCE-START] Hosting: requested by a direct Dispose() (no routed DisposeRequest); … +``` + +**Why it was missing, and why the obvious source could not supply it.** `Dispose()` posts its +`ShutdownRequest` to ITSELF, so that message's `Sender` is always the dying hub — the field that +looks like it answers "who asked" is the one field that cannot. The discriminating fact is one frame +earlier: whether a `DisposeRequest` arrived over the bus at all, and from where. That is recorded in +`HandleDispose`, where such a request is *honoured* (not merely received — the root-mesh refusal +returns without disposing). + +**The three readings, and what each rules out:** + +| line says | means | rules out | +|---|---|---| +| a named sender | another hub asked — e.g. `PackageInstaller` posting to a package root | a recycle; a host teardown | +| `itself — a self-posted DisposeRequest` | an automatic recycle: `NodeTypeRebindWatcher`, `WithOverlaySelfHeal` | an external actor | +| `a direct Dispose() (no routed DisposeRequest)` | host teardown, an owner disposing its children, a `using` | **the whole message path** | + +🚨 The third is not an absence of information — it is the deduction #3510 could not make. That issue +turned on one unknown: the Hosting root was disposed at 23:37:51Z *while its own 145-file install was +in flight*, its per-node children went with it, the writes they owed acks for were stranded, four +creates never got a reply and the install ran out a ten-minute bound. Its own words: *"Who disposed +the root is not in the log at this level"* — so the leading hypothesis (a NodeType rebind posting +`DisposeRequest` to the root) stayed a hypothesis, and its Expected section asks for this line. + +🚨 The **self-posted** case is called out rather than printed as an address on purpose: the automatic +recycles post to their own hub, so a bare sender renders `Hosting: requested by Hosting` — true, +useless, and easy to misread as a routing oddity. That case is #3510's leading hypothesis, so it is +the one reading that must not be ambiguous. + +**This names the disposer; it does not stop the wedge.** #3510's other two Expectations — deferring a +recycle while an install holds the root, or NACKing every in-flight write under it so the install +fails in milliseconds with a name — are untouched. `QuiesceStartNamesTheAskerTest` pins all three +readings, and the line is `Information`: a test asserting it must raise its own filter +(`AddFilter("MeshWeaver", LogLevel.Information)`), because `TestBase` binds levels from +`test/appsettings.json` and an Information line is otherwise dropped before any provider sees it. + ## What this page does not claim The wedge in #3593 is **not fixed**. What changed is that the next occurrence is nameable: the diff --git a/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-09-the-shutdown-log-says-who-asked.md b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-09-the-shutdown-log-says-who-asked.md new file mode 100644 index 0000000000..f75ae52add --- /dev/null +++ b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-09-the-shutdown-log-says-who-asked.md @@ -0,0 +1,36 @@ +--- +Name: The shutdown log says who asked +Category: Feature +Description: When a hub tears down, the log line that opens the teardown now names what asked for it — another component, the hub itself recycling, or nothing at all. Until now it named only the hub going down, which left the most consequential question about a stalled shutdown unanswerable from the log. +Icon: PersonQuestionMark +Order: -20260909 +--- + +When something inside the platform shuts down, it opens with a line naming itself and the work still +outstanding. What it never said is **what asked it to shut down** — and in the one incident where +that mattered most, there was no way to find out afterwards. + +A package was installing 145 files. Partway through, the thing that owned those files was torn down +underneath the install. Everything it was responsible for went with it, the install sat waiting for +answers that could no longer come, and ten minutes later it gave up. Reading the logs afterwards, +the teardown was plainly visible and its cause was not: nothing recorded who had asked. The +investigation's own note was *"who disposed the root is not in the log at this level"*, and the +leading explanation stayed an explanation. + +## What the line says now + +Three answers, because there are three genuinely different situations: + +- **another component asked** — it is named, so the thing that ordered the shutdown can be found; +- **it asked itself** — the routine self-refresh that happens when something is rebuilt in place, + said in those words rather than printed as the component naming itself, which reads like a fault + and is not one; +- **nothing asked over the wire** — an ordinary shutdown from the host, or from whatever owns it. + +That last one carries as much information as the other two. It rules out an entire class of cause in +one reading, which is exactly the deduction that could not be made before. + +## What it does not do + +It does not stop a shutdown from landing in the middle of an install — that is a separate piece of +work, still open. This makes the next occurrence explicable instead of a dead end. diff --git a/src/MeshWeaver.Messaging.Hub/MessageHub.cs b/src/MeshWeaver.Messaging.Hub/MessageHub.cs index 067f7d6683..5344acd464 100644 --- a/src/MeshWeaver.Messaging.Hub/MessageHub.cs +++ b/src/MeshWeaver.Messaging.Hub/MessageHub.cs @@ -110,6 +110,33 @@ internal void NoteRequestStage(string? requestId, string stage) /// Monotonic counter, incremented once per message processed; used for ordering and disposal sequencing. public long Version { get; private set; } + /// + /// 🚨 Who asked for this teardown (#3510). null until a routed + /// is honoured, and then the sender that posted it. + /// + /// The bake wedge of #3510 turned on one unknown the log could not answer: the Hosting + /// root was disposed at 23:37:51Z while its own 145-file install was in flight, its per-node + /// children went with it, and the writes they owed acks for were stranded — but "who + /// disposed the root is not in the log at this level", so the leading hypothesis (a + /// NodeType rebind posting DisposeRequest to the root) stayed a hypothesis. The issue + /// asks for exactly this: "[QUIESCE-START] on a root should name who asked". + /// + /// Why the ShutdownRequest's own sender cannot answer it. Dispose() posts + /// that request to ITSELF, so its Sender is always this hub — the question it looks like + /// it answers is the one it cannot. The discriminating fact is one frame earlier: whether a + /// DisposeRequest arrived over the bus at all, and from where. A direct Dispose() + /// (host teardown, an owner tearing down its children, a using) leaves this null, and + /// that absence is itself the answer — it rules the message path out. + /// + private volatile string? disposeRequestedBy; + + /// + /// What [QUIESCE-START] prints when no routed brought this + /// hub down — host teardown, an owner disposing its children, or a using. Spelled once so + /// a log reader and a log QUERY agree on the token. + /// + internal const string DirectDisposeSource = "a direct Dispose() (no routed DisposeRequest)"; + /// /// Disposal-health diagnostic: how many turns this hub /// has handled. A healthy disposal handles exactly the three phase requests @@ -2685,8 +2712,10 @@ IMessageDelivery request var initialPendingSnapshot = SnapshotPendingCallbacks(); TryLog(LogLevel.Information, - "[QUIESCE-START] {Address}: {Count} pending callbacks at dispose entry: {Pending}", - Address, initialPendingSnapshot.Length, FormatPendingCallbacks(initialPendingSnapshot)); + "[QUIESCE-START] {Address}: requested by {RequestedBy}; {Count} pending callbacks " + + "at dispose entry: {Pending}", + Address, disposeRequestedBy ?? DirectDisposeSource, + initialPendingSnapshot.Length, FormatPendingCallbacks(initialPendingSnapshot)); // CRITICAL: do the wait OFF the action block. The action block processes // messages serially (MaxDegreeOfParallelism = 1) — a blocking wait on the @@ -3337,6 +3366,24 @@ private IMessageDelivery HandleDispose(IMessageDelivery request) if (!IsShuttingDown) AnnounceRecycle(); + // Recorded BEFORE Dispose(), because Dispose() is what logs [QUIESCE-START] (#3510). Set + // here rather than at the top of the handler so it means what it says: this request was + // honoured, not merely received — the root-mesh refusal above returns without disposing. + // + // 🚨 SELF-POSTED is called out, not printed as an address. The automatic recycles post to + // their OWN hub (NodeTypeRebindWatcher, WithOverlaySelfHeal), so the bare sender would read + // "[QUIESCE-START] Hosting: requested by Hosting" — true, useless, and easy to misread as a + // routing oddity. The reader's question is which of three things happened, so the line says + // which: a recycle this hub asked for, a teardown someone else asked for, or no message at + // all. #3510's leading hypothesis is precisely the first, and the installer + // (PackageInstaller posting to a package root) is the second. + disposeRequestedBy = request.Sender is null + ? "an unnamed sender (routed DisposeRequest)" + : Equals(request.Sender, Address) + ? $"itself — a self-posted DisposeRequest ({request.Sender}), i.e. a rebind or " + + "self-heal recycle" + : $"{request.Sender} (routed DisposeRequest)"; + Dispose(); return request.Processed(); } diff --git a/test/MeshWeaver.Messaging.Hub.Test/QuiesceStartNamesTheAskerTest.cs b/test/MeshWeaver.Messaging.Hub.Test/QuiesceStartNamesTheAskerTest.cs new file mode 100644 index 0000000000..e942721ef3 --- /dev/null +++ b/test/MeshWeaver.Messaging.Hub.Test/QuiesceStartNamesTheAskerTest.cs @@ -0,0 +1,156 @@ +using System; +using System.Collections.Concurrent; +using System.Linq; +using System.Reactive.Linq; +using System.Threading.Tasks; +using MeshWeaver.Fixture; +using MeshWeaver.Mesh; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace MeshWeaver.Messaging.Hub.Test; + +/// +/// 🚨 [QUIESCE-START] must name who asked for the teardown (#3510). +/// +/// #3510's bake wedge turned on one unknown the log could not answer. The Hosting root was +/// disposed at 23:37:51Z while its own 145-file install was in flight; its per-node children went +/// with it; the writes they owed acks for were stranded, so four creates never got a reply and the +/// install ran out a ten-minute bound. The issue's own words: "Who disposed the root is not in +/// the log at this level" — so the leading hypothesis, a NodeType rebind posting +/// DisposeRequest to the root, stayed a hypothesis through the whole investigation. Its +/// Expected section asks for this line directly. +/// +/// 🚨 The ShutdownRequest's own sender cannot answer it, which is why nothing +/// was there to read: Dispose() posts that request to ITSELF, so its sender is always the +/// dying hub. The discriminating fact is one frame earlier — whether a DisposeRequest +/// arrived over the bus at all, and from where. +/// +/// Three outcomes, because a reader has three real cases to tell apart and the automatic +/// recycles post to their own hub: a recycle this hub asked for, a teardown another hub asked for, +/// and no message at all. +/// +public class QuiesceStartNamesTheAskerTest : HubTestBase +{ + private readonly QuiesceLogCapture _capture = new(); + + public QuiesceStartNamesTheAskerTest(ITestOutputHelper output) + : base(output) + { + // 🚨 The filter, not just the provider. TestBase binds log-level filters from + // test/appsettings.json (`logging.AddConfiguration("Logging")`), which leaves MeshWeaver + // above Information — so an Information line is dropped BEFORE any provider sees it, and a + // capture alone observes nothing. The sibling DisposalDeadlockDiagnosticsTest works without + // this only because the verdicts it watches for are Errors. Raising it HERE, in this test's + // own DI, is the self-contained way: the src-tree appsettings.json is committed contract and + // is never edited to make a test see a line. + Services.AddLogging(l => + { + l.Services.AddSingleton(_capture); + l.AddFilter("MeshWeaver", LogLevel.Information); + }); + } + + private async Task QuiesceLineFor(MessageHub hub) + { + // TestTimeouts.Convergence, never a literal: it scales with MW_TEST_TIMEOUT_FACTOR on CI and + // stays strictly below the [Fact(Timeout)] outer bound, so a wait that loses says WHAT did + // not converge instead of dying as an anonymous xunit timeout. TestTimeoutLiteralRatchetGuard + // holds the hand-written count to a number that only goes down. + await hub.DisposalCompleted.FirstOrDefaultAsync().Timeout(TestTimeouts.Convergence).Await(); + var address = hub.Address.ToString(); + var line = _capture.Entries.FirstOrDefault(e => e.Contains(address, StringComparison.Ordinal)); + line.Should().NotBeNull( + $"PRECONDITION: a [QUIESCE-START] line must have been logged for {address} — without one " + + "there is nothing for this test to assert about, and it would pass vacuously"); + return line!; + } + + [HubFact] + public async Task ARoutedDisposeRequestFromAnotherHub_NamesThatSender() + { + var victim = (MessageHub)Mesh.GetHostedHub(new Address("victim", "asked-by-other"), c => c)!; + var asker = (MessageHub)Mesh.GetHostedHub(new Address("asker", "installer"), c => c)!; + + asker.Post(new DisposeRequest(), o => o.WithTarget(victim.Address)); + + var line = await QuiesceLineFor(victim); + + line.Should().Contain("requested by", "the line must answer the question at all"); + line.Should().Contain("asker/installer", + "this is the shape that matters most — PackageInstaller posting a DisposeRequest to a " + + "package ROOT while that package installs is #3510's wedge, and the sender is the one " + + "fact that identifies it"); + line.Should().NotContain("no routed DisposeRequest", + "a teardown that came over the bus must not read as a direct Dispose()"); + } + + /// + /// 🚨 The self-posted case is called out rather than printed as an address. The automatic + /// recycles (NodeTypeRebindWatcher, WithOverlaySelfHeal) post to their OWN hub, so + /// a bare sender would render "Hosting: requested by Hosting" — true, useless, and easy to + /// misread as a routing oddity. This is #3510's LEADING hypothesis, so it is the reading that + /// must not be ambiguous. + /// + [HubFact] + public async Task ASelfPostedDisposeRequest_SaysSoRatherThanNamingTheHubTwice() + { + var victim = (MessageHub)Mesh.GetHostedHub(new Address("victim", "asked-by-self"), c => c)!; + + victim.Post(new DisposeRequest(), o => o.WithTarget(victim.Address)); + + var line = await QuiesceLineFor(victim); + + line.Should().Contain("itself", + "a rebind/self-heal recycle must be readable as one, not as a hub naming itself"); + line.Should().Contain("self-posted DisposeRequest"); + line.Should().NotContain("no routed DisposeRequest", + "it DID come over the bus — that is exactly what distinguishes a recycle from a " + + "teardown by an owner"); + } + + /// + /// The negative case, and it carries real information: an absent DisposeRequest RULES OUT the + /// message path, which is what #3510 needed and could not get. Host teardown, an owner + /// disposing its children and a using all land here. + /// + [HubFact] + public async Task ADirectDispose_SaysNoRoutedRequestBroughtItDown() + { + var victim = (MessageHub)Mesh.GetHostedHub(new Address("victim", "asked-by-nobody"), c => c)!; + + victim.Dispose(); + + var line = await QuiesceLineFor(victim); + + line.Should().Contain("no routed DisposeRequest", + "the ABSENCE of a request is the answer here — it rules the message path out, which is " + + "the deduction #3510 could not make"); + line.Should().NotContain("itself", "nothing asked; there is no requester to name"); + } + + private sealed class QuiesceLogCapture : ILoggerProvider + { + public ConcurrentQueue Entries { get; } = new(); + public ILogger CreateLogger(string categoryName) => new Capturing(Entries); + public void Dispose() { } + + private sealed class Capturing(ConcurrentQueue sink) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + // Information: [QUIESCE-START] is an Information line, unlike the Error-level + // deadlock verdicts the sibling capture watches for. + public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Information; + public void Log(LogLevel logLevel, EventId eventId, TState state, + Exception? exception, Func formatter) + { + if (logLevel < LogLevel.Information) + return; + var message = formatter(state, exception); + if (message.Contains("[QUIESCE-START]", StringComparison.Ordinal)) + sink.Enqueue(message); + } + } + } +}