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
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
51 changes: 49 additions & 2 deletions src/MeshWeaver.Messaging.Hub/MessageHub.cs
Original file line number Diff line number Diff line change
Expand Up @@ -110,6 +110,33 @@ internal void NoteRequestStage(string? requestId, string stage)
/// <summary>Monotonic counter, incremented once per message processed; used for ordering and disposal sequencing.</summary>
public long Version { get; private set; }

/// <summary>
/// 🚨 <b>Who asked for this teardown (#3510).</b> <c>null</c> until a routed
/// <see cref="DisposeRequest"/> is honoured, and then the sender that posted it.
///
/// <para>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 <i>"who
/// disposed the root is not in the log at this level"</i>, so the leading hypothesis (a
/// NodeType rebind posting <c>DisposeRequest</c> to the root) stayed a hypothesis. The issue
/// asks for exactly this: <i>"[QUIESCE-START] on a root should name who asked"</i>.</para>
///
/// <para><b>Why the ShutdownRequest's own sender cannot answer it.</b> <c>Dispose()</c> posts
/// that request to ITSELF, so its <c>Sender</c> 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
/// <c>DisposeRequest</c> arrived over the bus at all, and from where. A direct <c>Dispose()</c>
/// (host teardown, an owner tearing down its children, a <c>using</c>) leaves this null, and
/// that absence is itself the answer — it rules the message path out.</para>
/// </summary>
private volatile string? disposeRequestedBy;

/// <summary>
/// What <c>[QUIESCE-START]</c> prints when no routed <see cref="DisposeRequest"/> brought this
/// hub down — host teardown, an owner disposing its children, or a <c>using</c>. Spelled once so
/// a log reader and a log QUERY agree on the token.
/// </summary>
internal const string DirectDisposeSource = "a direct Dispose() (no routed DisposeRequest)";

/// <summary>
/// Disposal-health diagnostic: how many <see cref="ShutdownRequest"/> turns this hub
/// has handled. A healthy disposal handles exactly the three phase requests
Expand Down Expand Up @@ -2685,8 +2712,10 @@ IMessageDelivery<ShutdownRequest> 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
Expand Down Expand Up @@ -3337,6 +3366,24 @@ private IMessageDelivery HandleDispose(IMessageDelivery<DisposeRequest> 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)";
Comment on lines +3380 to +3385

Dispose();
return request.Processed();
}
Expand Down
156 changes: 156 additions & 0 deletions test/MeshWeaver.Messaging.Hub.Test/QuiesceStartNamesTheAskerTest.cs
Original file line number Diff line number Diff line change
@@ -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;

/// <summary>
/// 🚨 <b><c>[QUIESCE-START]</c> must name who asked for the teardown (#3510).</b>
///
/// <para>#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: <i>"Who disposed the root is not in
/// the log at this level"</i> — so the leading hypothesis, a NodeType rebind posting
/// <c>DisposeRequest</c> to the root, stayed a hypothesis through the whole investigation. Its
/// Expected section asks for this line directly.</para>
///
/// <para>🚨 <b>The <c>ShutdownRequest</c>'s own sender cannot answer it</b>, which is why nothing
/// was there to read: <c>Dispose()</c> posts that request to ITSELF, so its sender is always the
/// dying hub. The discriminating fact is one frame earlier — whether a <c>DisposeRequest</c>
/// arrived over the bus at all, and from where.</para>
///
/// <para>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.</para>
/// </summary>
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<ILoggerProvider>(_capture);
l.AddFilter("MeshWeaver", LogLevel.Information);
});
}

private async Task<string> 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));
Comment on lines +62 to +63
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()");
}

/// <summary>
/// 🚨 The self-posted case is called out rather than printed as an address. The automatic
/// recycles (<c>NodeTypeRebindWatcher</c>, <c>WithOverlaySelfHeal</c>) 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.
/// </summary>
[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");
}

/// <summary>
/// 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 <c>using</c> all land here.
/// </summary>
[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<string> Entries { get; } = new();
public ILogger CreateLogger(string categoryName) => new Capturing(Entries);
public void Dispose() { }

private sealed class Capturing(ConcurrentQueue<string> sink) : ILogger
{
public IDisposable? BeginScope<TState>(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<TState>(LogLevel logLevel, EventId eventId, TState state,
Exception? exception, Func<TState, Exception?, string> formatter)
{
if (logLevel < LogLevel.Information)
return;
var message = formatter(state, exception);
if (message.Contains("[QUIESCE-START]", StringComparison.Ordinal))
sink.Enqueue(message);
}
}
}
}
Loading