diff --git a/src/MeshWeaver.Documentation/Data/Architecture/LogWatchTriage.md b/src/MeshWeaver.Documentation/Data/Architecture/LogWatchTriage.md index f802b39cfd..f1feb2b9e1 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/LogWatchTriage.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/LogWatchTriage.md @@ -899,9 +899,26 @@ each produced a steady ticket stream: can still resolve. A live scope that threw that type for its own reasons still reads as a fault, and a probe that cannot answer leaves the outcome LOUD. +- 🚨 **Classify EVERY reporter of the fault, or the ticket does not stop — and this is the identity + rule above working as designed, not a bug.** Because the fingerprint identifies the fault and not + the reporter (the category is excluded once a frame is present, and the discriminating text is the + *exception's* message rather than the reporter's prose), downgrading one site leaves the incident + firing through every other site that prints the same exception. Measured on #3243: the missing-hub + line was classified on 2026-09-04, and the incident reopened on 2026-09-18 carrying + `[ACTIVATE] Grain Admin/_Notification/…: activation faulted for …` — the *activation chain's* + error arm, a few lines away in the same grain, still an unconditional `LogError`. The same + `ObjectDisposedException`, a different `catch`, one fingerprint. So when you downgrade an expected + condition, grep the component for its SIBLING arms first: the thing that keeps a ticket alive is + the one you did not classify. `MessageHubGrain.ActivationFaultLevel` is that arm's classifier and + shares the two existing predicates — `HubDisposingException.IsHubDisposal` (the hub announced its + own disposal) and `IsDisposedContainer` (a scope closed underneath live work) — rather than + re-deriving the fact a third time. + `CancellationIsNotAFaultTest` pins the cancellation directions, including the timeout impostor; `HubCreationDuringTeardownIsNotAFaultTest` and `HubConstructionOutcomeReportingTest` pin the -hub-creation ones, including the configuration-throw that must stay red. +hub-creation ones, including the configuration-throw that must stay red and the activation arm's +own control — a `TimeoutException` or an unresolvable node stays red, and a null fault is an unknown +rather than a shutdown. ## What this is not diff --git a/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-19-a-pod-shutting-down-is-no-longer-an-error-on-the-other-path-too.md b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-19-a-pod-shutting-down-is-no-longer-an-error-on-the-other-path-too.md new file mode 100644 index 0000000000..93699fb64b --- /dev/null +++ b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-19-a-pod-shutting-down-is-no-longer-an-error-on-the-other-path-too.md @@ -0,0 +1,41 @@ +--- +Name: A pod shutting down is no longer an error on the second path either +Category: Fix +Description: Two weeks ago a portal stopped treating one expected condition as a failure — a node waking up on a pod that is already stopping. It turned out the platform had two places that report that, and only one of them was told. The other kept raising the alarm, and because alarms are grouped by the fault rather than by who reported it, the ticket the first fix closed kept reopening. Both now agree. +Icon: Checkmark +Order: -20260919 +--- + +# A pod shutting down is no longer an error on the second path either + +When a portal replaces its pods, some nodes are inevitably waking up on a pod that is already on its +way out. The work is abandoned, nothing is written, and the next person to open that node gets it from +a live pod. It is the most ordinary thing that happens during a deployment. + +Two weeks ago the platform stopped reporting that as a failure. Before, it could not tell the +difference between *"this pod is going away"* and *"this node's configuration is broken"* — one +message named both possibilities and committed to neither — so every rollout raised an alarm about a +condition the message itself described as expected. + +**That fix was correct and incomplete, in a way worth writing down.** A node waking up runs through +two steps, and each has its own place to report a problem. Only one of them was taught the +difference. The other went on reporting every failure at alarm level, including the shutdown. + +What makes that more than a missed line is **how alarms are grouped**. They are deliberately grouped +by *the fault*, not by *who reported it* — so that one problem printed by two different parts of the +platform raises one alarm instead of two. That is the right rule, and it has a consequence nobody had +drawn out: **quietening one reporter changes nothing while another still shouts.** The alarm the first +fix closed reopened a fortnight later, reporting the same shutdown from the second step, and looked +for all the world like the fix having come undone. + +Both steps now agree: a node abandoned because its pod is tearing down is recorded as the routine +event it is, and says so in a sentence instead of listing possibilities. + +**Nothing became quieter than that.** A node that genuinely cannot start — a configuration that +throws, a node that never resolves, a step that times out — still raises the alarm, with the same +wording as before, and with no change at all to what actually happens: the failure is still recorded, +still reported to whoever was waiting, and the node still tries again on the next access. The only +thing that changed is whether a deployment doing its job wakes somebody up. + +The general lesson is recorded with the machinery: when an expected condition is downgraded, the +thing that keeps the alarm alive is the reporter nobody thought to look for. diff --git a/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs b/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs index 0ee4917a26..55d3ef4e12 100644 --- a/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs +++ b/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs @@ -378,7 +378,20 @@ public override Task OnActivateAsync(CancellationToken cancellationToken) node => CompleteActivation(streamId, address, grainScheduler, node), ex => { - logger.LogError(ex, "[ACTIVATE] Grain {StreamId}: activation faulted for {Path}", streamId, addressPath); + // 🚨 The SIBLING reporter of the same fault (#3243, second half). The + // missing-hub line below classifies HostShuttingDown down to Debug; this arm + // did not, and reported EVERY activation fault at fail level — including the + // teardown race that line exists to excuse. Because the incident fingerprint + // identifies the fault and NOT the reporter (Doc/Architecture/LogWatchTriage: + // the category is not in the identity when a frame is present, and the + // discriminating text is the EXCEPTION's message, never the reporter's prose), + // a teardown-race ObjectDisposedException logged here lands on the very + // incident the first half was closing — so the ticket kept reopening through + // the unclassified sibling. Classifying the level is what stops that; the + // wording is for the human and cannot split anything. + logger.Log(ActivationFaultLevel(ex), ex, + "[ACTIVATE] Grain {StreamId}: {Reason}", streamId, + ActivationFaultReason(addressPath, ex)); // Defect 3: stash the REAL cause so a caller whose delivery only ever sees the // raw Orleans rejection (grain mid-deactivation) still gets the actionable error. activationFailures?.Record(streamId, ex.Message); @@ -789,6 +802,62 @@ internal static string HubConstructionFailureReason(MeshNode node, HostedHubOutc internal static LogLevel HubConstructionFailureLevel(HostedHubOutcome outcome) => outcome == HostedHubOutcome.HostShuttingDown ? LogLevel.Debug : LogLevel.Error; + /// + /// True when an activation fault is the host/scope teardown race rather than a defect — + /// the ACTIVATION-chain counterpart of (#3243). + /// + /// Both classifiers already exist and are deliberately shared rather than re-derived + /// here: covers the case where the hub + /// announced its own disposal, and + /// the case a scope was closed underneath live work — an + /// naming a disposed Autofac LifetimeScope, which + /// is exactly the signature #3243 was filed on. Both walk the exception CHAIN, because the + /// fault reaches this arm wrapped. + /// + /// The activation fault; may be null. + /// true when the fault is a teardown race. + internal static bool IsActivationTeardownRace(Exception? ex) => + HubDisposingException.IsHubDisposal(ex) || HubDisposingException.IsDisposedContainer(ex); + + /// + /// The level the activation-fault line is logged at — a TICKETING decision, not a verbosity + /// knob, for the same reason is one (#3243). + /// Everything a portal reports as red becomes an incident and a GitHub issue + /// (Doc/Architecture/LogWatchTriage), so an expected teardown race logged at + /// fail: is indistinguishable from an activation that genuinely cannot resolve. + /// + /// 🚨 Only the teardown race is benign. Anything else — a node that never resolved, a + /// configuration that threw, an unknown — stays at , and nothing + /// about the arm's BEHAVIOUR changes either way: the fault is still recorded on + /// activationFailures, still pushed to _hubReadyRaw.OnError, and the grain still + /// deactivates so the next access re-runs resolution. + /// + /// The activation fault; may be null. + /// The log level to report it at. + internal static LogLevel ActivationFaultLevel(Exception? ex) => + IsActivationTeardownRace(ex) ? LogLevel.Debug : LogLevel.Error; + + /// + /// What the activation-fault line says. Two sentences rather than one union, so a reader is + /// told WHICH condition fired instead of being handed both and left to guess — the same + /// correction made for the sibling line. + /// + /// 🚨 This wording splits no incident and is not trying to: when a burst carries an + /// exception, the fingerprint's discriminating text is the EXCEPTION's message and the + /// reporter's prose is excluded by design, so that two catch sites printing one fault stay one + /// ticket. The level above is what changes whether this is ticketed at all. + /// + /// The address being activated. + /// The activation fault; may be null. + /// The sentence to log. + internal static string ActivationFaultReason(string path, Exception? ex) => + IsActivationTeardownRace(ex) + ? $"activation of {path} was abandoned because the host (or its DI scope) is tearing " + + "down — an expected teardown race, not a fault. Nothing was written; the next " + + "access re-activates this node on a live host." + : $"activation faulted for {path}"; + + /// /// Composes the per-emission "enrich with HubConfiguration" step as an /// observable so the activation chain stays purely reactive. diff --git a/test/MeshWeaver.Hosting.Orleans.Test/HubConstructionOutcomeReportingTest.cs b/test/MeshWeaver.Hosting.Orleans.Test/HubConstructionOutcomeReportingTest.cs index 8d73f60e1a..e9659f5143 100644 --- a/test/MeshWeaver.Hosting.Orleans.Test/HubConstructionOutcomeReportingTest.cs +++ b/test/MeshWeaver.Hosting.Orleans.Test/HubConstructionOutcomeReportingTest.cs @@ -74,4 +74,82 @@ public void EverythingElse_StaysAtFailLevel(HostedHubOutcome outcome) => MessageHubGrain.HubConstructionFailureLevel(outcome) .Should().Be(LogLevel.Error, "only a KNOWN shutdown is benign; an unknown must never be quietly downgraded"); + + // ── The SIBLING reporter (#3243, second half) ──────────────────────────────────────────────── + // + // 🚨 Why the first half did not close the incident. The fingerprint identifies the FAULT, not + // the reporter: with a frame present the reporting category is excluded from the identity, and + // the discriminating text is the EXCEPTION's message rather than the reporter's prose + // (Doc/Architecture/LogWatchTriage) — deliberately, so one fault printed by two catch sites + // stays one ticket (#1170/#1171). The activation chain's error arm reported EVERY fault at + // fail level, so the same teardown-race ObjectDisposedException kept landing on + // e2028eb86d6a85a6 through the arm the classification had not reached. Measured: the + // 2026-09-18T05:39:52Z sighting is that arm's line, `activation faulted for + // Admin/_Notification/…`, on a pod rolling. + + /// The #3243 signature exactly: Autofac's scope is gone underneath the activation. + private static Exception DisposedScope() => + new ObjectDisposedException("LifetimeScope", + "Instances cannot be resolved and nested lifetimes cannot be created from this " + + "LifetimeScope as it (or one of its parent scopes) has already been disposed."); + + /// + /// 🚨 THE PIN. Pre-fix this arm was an unconditional LogError, so the expected teardown + /// race was ticketed on every rollout — through the sibling of the line the first half fixed. + /// + [Fact] + public void AnActivationAbandonedByTeardown_IsNotReportedAsAFault() + { + MessageHubGrain.ActivationFaultLevel(DisposedScope()) + .Should().Be(LogLevel.Debug, + "a scope closed underneath an activation is the same expected race the missing-hub " + + "line already excuses — and this arm is where it was still being ticketed"); + + var reason = MessageHubGrain.ActivationFaultReason("Admin/_Notification/abc", DisposedScope()); + reason.Should().Contain("Admin/_Notification/abc"); + reason.Should().Contain("tearing", "the reader must be told WHICH condition fired"); + reason.Should().Contain("re-activates", "and that nothing is lost"); + } + + /// + /// The hub announcing its own disposal is the other half of the same fact, and + /// IsHubDisposal walks the CHAIN because this arm receives the fault wrapped. + /// + [Fact] + public void AHubDisposalRace_CountsToo_EvenWrapped() + => MessageHubGrain.ActivationFaultLevel( + new InvalidOperationException("wrapped", + new HubDisposingException(new Address("test", "1"), "stream"))) + .Should().Be(LogLevel.Debug, + "the fault reaches this arm wrapped, so the classifier must walk the chain"); + + /// + /// 🚨 THE CONTROL, and the thing that keeps this from being a mute button: a real activation + /// failure — a node that never resolved, a configuration that threw — stays red and keeps the + /// wording somebody has already learned to grep for. + /// + [Theory] + [InlineData(typeof(TimeoutException))] + [InlineData(typeof(InvalidOperationException))] + public void ARealActivationFailure_StaysAtFailLevel(Type faultType) + { + var ex = (Exception)Activator.CreateInstance(faultType)!; + + MessageHubGrain.ActivationFaultLevel(ex) + .Should().Be(LogLevel.Error, + "only a teardown race is benign; everything else is a defect someone must fix"); + MessageHubGrain.ActivationFaultReason("Admin/PlatformVersion", ex) + .Should().Be("activation faulted for Admin/PlatformVersion", + "the unclassified wording is unchanged, so an existing search still finds it"); + } + + /// + /// A null fault is an UNKNOWN, not a shutdown — the same trap + /// guards on the other arm. + /// + [Fact] + public void ANullFault_IsNotTreatedAsBenign() + => MessageHubGrain.ActivationFaultLevel(null) + .Should().Be(LogLevel.Error, + "no evidence of a teardown is not evidence of one"); }