From 6181ab18761ba7e48c8c3ecfca0fedb5450bcdf7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= Date: Mon, 10 Aug 2026 07:14:17 +0200 Subject: [PATCH] Grain activation no longer times out waiting on itself MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit MessageHubGrain.OnActivateAsync merged `streamCache.GetStream(addressPath)` — the grain's OWN address — into the activation source. The cache opens that upstream with GetMeshNodeStreamBypassCache(path), i.e. a SubscribeRequest addressed at `path`, which the RoutingGrain delivers straight back to THIS grain, where DeliverMessage parks it on _hubReadyRaw until CompleteActivation runs. On a cold entry the branch is a strict self-loop: it cannot answer until the very activation it feeds has finished, so its only possible terminal is "the grain did not answer itself". Observable.Merge forwarded that terminal, so the cache hub's 60s RequestTimeout became a hard ceiling on TOTAL activation and surfaced as [ACTIVATE] Grain Edu: activation faulted for Edu TimeoutException: No response received in hub cache/ within 00:01:00 for request SubscribeRequest (id=...) -> target Edu. naming the activating grain as an unreachable target. The ceiling pre-empted both deliberate slow-path designs downstream: WaitForCompileSettled DISARMS its wall clock while a compile is in flight, and BuildEnrichmentChain catches a stuck type into a visible compilation-error overlay so the hub activates anyway. Neither could be reached. Orleans retried, the cache's transient-streak breaker replayed the cached timeout into each fresh activation, and the retries faulted in milliseconds. Measured on memex.systemorph.com (ns memex) 2026-08-09/10: ~36 activation faults an hour, and every faulting grain was a nodeType:Store/Plugin node (Edu, Agent, Collaboration, DataModelling, Essentials, Feedback, Instances, Publish, Skill). Same image on all three portals; only this one has Store/Plugin installed as a dynamic NodeType sitting at CompilationStatus=Error (CS0117 AiSettingsNodeType.AddSkillSource, deleted in #683), which is exactly the case where enrichment legitimately runs long. Data-dependent, not version- dependent. The Edu partition was unreadable to users and to MCP with the same exception. The cache branch may still supply a VALUE (a warm entry lets a reactivation skip the storage read) but no longer a TERMINAL: it is collapsed to Empty and the exception is logged in full. Activation keeps a complete set of terminal outcomes without it — the path resolver's node, the 30s first-emission TimeoutException, the "no usable node" completion (prompt, which is why Empty and not Never), and enrichment's overlay. ComposeActivationSource / BuildActivationChain are extracted as internal statics so MessageHubGrainActivationSourceTest drives the whole chain in virtual time. Co-Authored-By: Claude Opus 5 (1M context) --- ...2026-08-10-plugin-pages-stop-timing-out.md | 26 ++ .../MessageHubGrain.cs | 132 ++++++++-- .../MessageHubGrainActivationSourceTest.cs | 249 ++++++++++++++++++ 3 files changed, 390 insertions(+), 17 deletions(-) create mode 100644 src/MeshWeaver.Documentation/Data/WhatsNew/2026-08-10-plugin-pages-stop-timing-out.md create mode 100644 test/MeshWeaver.Hosting.Orleans.Test/MessageHubGrainActivationSourceTest.cs diff --git a/src/MeshWeaver.Documentation/Data/WhatsNew/2026-08-10-plugin-pages-stop-timing-out.md b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-08-10-plugin-pages-stop-timing-out.md new file mode 100644 index 0000000000..1cff46f61c --- /dev/null +++ b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-08-10-plugin-pages-stop-timing-out.md @@ -0,0 +1,26 @@ +--- +Name: Plugin pages stop timing out on themselves +Category: Fix +Description: Installed plugins such as courses could become unreachable, retry forever, and never recover on their own. +Icon: Sparkle +Order: -20260810 +--- + +# Plugin pages stop timing out on themselves + +An installed plugin — a course area, a skills or agents section — could stop opening altogether. +The page never rendered, tools reading the same content answered "unavailable", and the portal kept +retrying without ever getting further. Nothing was actually broken: the content was there, and the +part of the portal that starts a section up was working on it. + +The cause was a section asking the portal for its own page while it was still starting up. That +question could only be answered once start-up had finished, so it always ran out of time — and the +portal treated running out of time as proof that the section had failed. Start-up was abandoned at +exactly the moment it was about to succeed, and each retry inherited the same stale answer, so the +section could never get going again. It hit hardest where a section legitimately takes a little +longer to prepare, which is precisely where the extra patience was designed to go. + +Now a section no longer treats a question it can only answer itself as a verdict on whether it +started. Sections that need longer to prepare are given that time, a genuinely broken one shows the +explanatory page it was always meant to show, and a section that is missing is reported straight +away instead of after a wait. Recovery no longer needs a restart. diff --git a/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs b/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs index cf7678addc..f53ff5da60 100644 --- a/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs +++ b/src/MeshWeaver.Hosting.Orleans/MessageHubGrain.cs @@ -1,5 +1,6 @@ using System.Collections.Immutable; using System.Reactive; +using System.Reactive.Concurrency; using System.Reactive.Linq; using System.Reactive.Subjects; using System.Reactive.Threading.Tasks; @@ -221,9 +222,12 @@ public override Task OnActivateAsync(CancellationToken cancellationToken) else { logger.LogDebug("[ACTIVATE] Grain {StreamId}: no static node with HubConfig, merging path resolver + mesh-node cache", streamId); - // Path resolver gives a fast in-process answer (no SubscribeRequest round-trip) - // for routable paths; the mesh-node cache backs it up for dynamic / freshly- - // created nodes that the path resolver hasn't indexed yet. + // Path resolver gives the AUTHORITATIVE in-process answer (no SubscribeRequest + // round-trip) for routable paths; the mesh-node cache is an ACCELERATOR that + // replays an already-hydrated entry (a reader kept this path warm across an idle + // collection) so a reactivation can skip the storage read. It can only ever + // contribute a VALUE — see ComposeActivationSource for why its terminal is + // meaningless by construction and must not fault this activation. var pathResolver = meshHub.ServiceProvider.GetRequiredService(); var accessService = meshHub.ServiceProvider.GetService(); // 🚨 Grain activation is INFRASTRUCTURE — reading the node to learn its @@ -243,11 +247,18 @@ public override Task OnActivateAsync(CancellationToken cancellationToken) using (accessService?.ImpersonateAsSystem()) return streamCache.GetStream(addressPath, meshHub.JsonSerializerOptions); }); - sourceStream = Observable.Merge( + sourceStream = ComposeActivationSource( pathResolver.ResolvePath(addressPath) .Where(r => r is { Node: not null }) .Select(r => r!.Node!), - cacheStream); + cacheStream, + ex => logger.LogWarning(ex, + "[ACTIVATE] Grain {StreamId}: the mesh-node-cache read of this grain's OWN address " + + "('{Path}') terminated with an error. That read is a SubscribeRequest routed back to " + + "THIS grain, so it cannot be answered until this activation completes — its terminal " + + "says nothing about the node and must not fault the activation. Node resolution " + + "continues on the path resolver.", + streamId, addressPath)); } // Non-blocking activation: subscribe to the source stream; when it emits a @@ -273,19 +284,16 @@ public override Task OnActivateAsync(CancellationToken cancellationToken) // the source emits, Amb commits to it and the timer is unsubscribed, so a // legitimately slow enrichment (cold compile, bounded internally by the // slow-path budgets) is never cut short. - _activationSubscription = Observable.Amb( + _activationSubscription = BuildActivationChain( sourceStream, - Observable.Timer(FirstNodeResolutionTimeout).SelectMany(_ => - Observable.Throw(new TimeoutException( - $"No MeshNode emitted for '{addressPath}' within {FirstNodeResolutionTimeout.TotalSeconds:0}s. " + - "Either the node does not exist or no query provider claims its partition.")))) - .SelectMany(node => - { - logger.LogDebug("[ACTIVATE] Grain {StreamId}: source emitted node={Path} NodeType={NodeType} hasHubConfig={HasConfig}", - streamId, node.Path, node.NodeType ?? "(null)", node.HubConfiguration != null); - return ResolveHubConfigurationObservable(node); - }) - .Take(1) + addressPath, + FirstNodeResolutionTimeout, + node => + { + logger.LogDebug("[ACTIVATE] Grain {StreamId}: source emitted node={Path} NodeType={NodeType} hasHubConfig={HasConfig}", + streamId, node.Path, node.NodeType ?? "(null)", node.HubConfiguration != null); + return ResolveHubConfigurationObservable(node); + }) .Subscribe( node => CompleteActivation(streamId, address, grainScheduler, node, sourceStream), ex => @@ -315,6 +323,96 @@ public override Task OnActivateAsync(CancellationToken cancellationToken) return Task.CompletedTask; } + /// + /// Composes the activation SOURCE from its two branches, and neutralises the one branch + /// whose terminal is meaningless by construction. + /// + /// The branches. is authoritative: it reads + /// the node straight out of storage, in-process, with no hub round-trip. + /// is an ACCELERATOR: when the process-wide + /// IMeshNodeStreamCache already holds a hydrated entry for this path (a reader kept it + /// warm across an idle-collection), it replays the node instantly and activation skips the + /// storage read. + /// + /// 🚨 Why the cache branch may supply a VALUE but never a TERMINAL. The cache + /// opens its upstream with GetMeshNodeStreamBypassCache(path) — a + /// SubscribeRequest addressed at path. For the grain's OWN address that request + /// is routed straight back to THIS grain, where parks it on + /// until runs. So on a COLD entry + /// the branch is a strict self-loop: it cannot answer until the very activation it feeds has + /// finished. Its only possible terminal is "the grain did not answer itself", which carries no + /// information about the node — and letting Observable.Merge forward it made that + /// terminal the ACTIVATION's terminal. + /// + /// Measured consequence (memex.systemorph.com, 2026-08-09/10 — ~36 activation faults an + /// hour, every one of them a nodeType:Store/Plugin node): the cache hub's request budget + /// (MessageHubConfiguration.RequestTimeout, 60 s) became a hard 60 s ceiling on TOTAL + /// activation, and it fired as "No response received in hub cache/… for request + /// SubscribeRequest → target Edu" — an error naming the activating grain as an unreachable + /// target. That ceiling pre-empted BOTH of the deliberate slow-path designs downstream: + /// NodeTypeEnrichmentHelpers.WaitForCompileSettled DISARMS its wall clock while a + /// compile is in flight (a cold pod compiling many dynamic types legitimately runs past the + /// budget), and BuildEnrichmentChain catches a stuck type into a visible + /// compilation-error OVERLAY so the hub activates anyway. Neither could ever be reached: the + /// self-loop faulted the activation first, 100% of the time. Orleans then retried, the cache's + /// transient-streak breaker replayed the cached timeout into each fresh activation, and the + /// retries faulted in milliseconds — the node stayed unreadable to users and to MCP. + /// + /// This is not a swallowed fault. The exception is logged in full via + /// , and activation keeps a COMPLETE set of terminal + /// outcomes without it: a node from the path resolver drives enrichment; nothing from either + /// branch within throws the precise + /// "no MeshNode emitted / no query provider claims its partition" TimeoutException; both + /// branches finishing with no node completes the source (the "no usable node" handler in + /// ); and an enrichment fault surfaces as the overlay. Collapsing + /// the branch to Empty rather than Never is what keeps that last case PROMPT — + /// a genuinely missing node is reported immediately instead of waiting out the budget. + /// + internal static IObservable ComposeActivationSource( + IObservable pathResolverStream, + IObservable ownAddressCacheStream, + Action onOwnAddressCacheFault) + => Observable.Merge( + pathResolverStream, + ownAddressCacheStream.Catch(ex => + { + onOwnAddressCacheFault(ex); + // The branch stops contributing — exactly as if it had never had anything to + // say, which is the truth for a request routed back at the activating grain. + return Observable.Empty(); + })); + + /// + /// The activation chain: bound the wait for the FIRST node, enrich it with a + /// HubConfiguration, and take the first enriched result. + /// + /// The Amb timer bounds ONLY the wait for the first source emission — once the + /// source emits, Amb commits to it and the timer is unsubscribed, so a legitimately slow + /// enrichment (a cold compile, bounded internally by the slow-path budgets) is never cut + /// short. That "never cut short" property is only real because + /// has already stopped the self-referential cache branch + /// from injecting its own deadline into the same chain. + /// + /// exists so the budget can be driven in virtual time by + /// MessageHubGrainActivationSourceTest (same seam as + /// NodeTypeEnrichmentHelpers.WaitForCompileSettled); production passes null and uses + /// the default scheduler. + /// + internal static IObservable BuildActivationChain( + IObservable sourceStream, + string addressPath, + TimeSpan firstNodeResolutionTimeout, + Func> enrich, + IScheduler? scheduler = null) + => Observable.Amb( + sourceStream, + Observable.Timer(firstNodeResolutionTimeout, scheduler ?? Scheduler.Default) + .SelectMany(_ => Observable.Throw(new TimeoutException( + $"No MeshNode emitted for '{addressPath}' within {firstNodeResolutionTimeout.TotalSeconds:0}s. " + + "Either the node does not exist or no query provider claims its partition.")))) + .SelectMany(enrich) + .Take(1); + /// /// Builds the hosted hub and feeds it onto . Called from /// the activation subscription's onNext. Idempotent — re-entry while diff --git a/test/MeshWeaver.Hosting.Orleans.Test/MessageHubGrainActivationSourceTest.cs b/test/MeshWeaver.Hosting.Orleans.Test/MessageHubGrainActivationSourceTest.cs new file mode 100644 index 0000000000..4bcbcbe7fe --- /dev/null +++ b/test/MeshWeaver.Hosting.Orleans.Test/MessageHubGrainActivationSourceTest.cs @@ -0,0 +1,249 @@ +using System; +using System.Collections.Generic; +using System.Reactive.Linq; +using MeshWeaver.Mesh; +using Microsoft.Reactive.Testing; +using Xunit; + +namespace MeshWeaver.Hosting.Orleans.Test; + +/// +/// Pins the activation-source composition of : the mesh-node-cache +/// branch reads THIS grain's OWN address, so its upstream SubscribeRequest is routed back +/// to this grain and parks until the activation it feeds has completed. It may hand over a warm +/// VALUE; its TERMINAL says nothing about the node and must never fault the activation. +/// +/// The prod defect (memex.systemorph.com, 2026-08-09/10): Observable.Merge forwarded +/// that branch's terminal, so the cache hub's 60 s request budget became a hard ceiling on TOTAL +/// activation and surfaced as "[ACTIVATE] Grain Edu: activation faulted" / +/// "No response received in hub cache/… for request SubscribeRequest → target Edu". Every +/// faulting grain was a nodeType:Store/Plugin node whose NodeType sat at +/// CompilationStatus = Error, i.e. exactly the case where enrichment legitimately runs long: +/// NodeTypeEnrichmentHelpers.WaitForCompileSettled DISARMS its wall clock while a compile is +/// in flight, and BuildEnrichmentChain falls back to a visible compilation-error overlay so +/// the hub activates anyway. The self-loop pre-empted both, every time, and Orleans retried +/// forever. +/// +/// Virtual time throughout — the 60 s budget is driven by a , not +/// the wall clock, so the repro is deterministic and instant. +/// +public class MessageHubGrainActivationSourceTest +{ + private static readonly TimeSpan FirstNodeBudget = TimeSpan.FromSeconds(30); + + /// The verbatim prod failure the cache branch injects at its 60 s request budget. + private static TimeoutException OwnAddressSubscribeTimeout() => new( + "No response received in hub cache/tYwK_RNWZUSCQGvEPNvvzg within 00:01:00 for request " + + "SubscribeRequest (id=Hxehbnok-kG7064Sy_Ga9g) → target Edu. The request may have been " + + "undeliverable or the target hub was not found."); + + private static MeshNode Node(string path, string? nodeType = null) => + new(path) { NodeType = nodeType }; + + /// + /// Asserts the activation did not fault, and NAMES the exception when it did — a bare + /// Assert.Empty reports only "Collection was not empty", which hides the very signature + /// this suite exists to pin. + /// + private static void AssertActivationDidNotFault(List errors) => + Assert.True(errors.Count == 0, + errors.Count == 0 + ? string.Empty + : $"Activation faulted, but no branch of it had anything to fault ON. " + + $"{errors[0].GetType().Name}: {errors[0].Message}"); + + /// + /// Runs the grain's real activation chain in virtual time and reports what the subscriber saw. + /// Mirrors OnActivateAsync: compose the source, bound the first emission, enrich, Take(1). + /// + private static (List Nodes, List Errors, int Completions) RunActivation( + TestScheduler scheduler, + IObservable pathResolverStream, + IObservable ownAddressCacheStream, + Func> enrich, + List? loggedCacheFaults = null) + { + var nodes = new List(); + var errors = new List(); + var completions = 0; + + var source = MessageHubGrain.ComposeActivationSource( + pathResolverStream, + ownAddressCacheStream, + ex => loggedCacheFaults?.Add(ex)); + + using var _ = MessageHubGrain + .BuildActivationChain(source, "Edu", FirstNodeBudget, enrich, scheduler) + .Subscribe(nodes.Add, errors.Add, () => completions++); + + scheduler.Start(); + return (nodes, errors, completions); + } + + /// + /// 🚨 THE REPRO. The path resolver has already handed over a perfectly good node, and enrichment + /// is legitimately still running (a NodeType compile in flight — the case + /// WaitForCompileSettled deliberately does NOT bound). At 60 s the self-referential cache + /// read times out. The activation must survive that and complete on the enriched node. + /// + /// Before the fix (Observable.Merge forwarding the branch's terminal) this test + /// fails with the TimeoutException surfacing as the activation's error at 60 s — the exact prod + /// signature. + /// + [Fact] + public void OwnAddressCacheTimeout_DoesNotFaultActivation_WhileEnrichmentIsStillRunning() + { + var scheduler = new TestScheduler(); + var resolved = Node("Edu", "Store/Plugin"); + var enriched = Node("Edu", "Store/Plugin"); + var loggedFaults = new List(); + + // Path resolver answers at 2 s and completes. Cache self-loop errors at its 60 s request + // budget. Enrichment (compile in flight) settles only at 90 s — past the cache's budget. + var (nodes, errors, completions) = RunActivation( + scheduler, + pathResolverStream: Observable.Return(resolved) + .Delay(TimeSpan.FromSeconds(2), scheduler), + ownAddressCacheStream: Observable.Throw(OwnAddressSubscribeTimeout()) + .Delay(TimeSpan.FromSeconds(60), scheduler), + enrich: _ => Observable.Return(enriched).Delay(TimeSpan.FromSeconds(90), scheduler), + loggedCacheFaults: loggedFaults); + + AssertActivationDidNotFault(errors); + Assert.Same(enriched, Assert.Single(nodes)); + Assert.Equal(1, completions); + + // Not swallowed: the operator still gets the exception, in full. + Assert.Contains("SubscribeRequest", Assert.Single(loggedFaults).Message); + } + + /// + /// The instant-replay variant of the same defect. Once the first activation faulted, the cache's + /// transient-streak breaker replays the cached TimeoutException to the NEXT subscriber without + /// re-opening an upstream — so every Orleans retry faulted in milliseconds (the 0 s/1 s/2 s/3 s + /// burst measured at 03:57Z). A branch that fails before the path resolver has even answered + /// must still not decide the activation. + /// + [Fact] + public void OwnAddressCacheReplaysCachedFault_ActivationStillResolvesFromPathResolver() + { + var scheduler = new TestScheduler(); + var resolved = Node("Edu", "Store/Plugin"); + + var (nodes, errors, _) = RunActivation( + scheduler, + // Path resolver is slower than the breaker's instant replay. + pathResolverStream: Observable.Return(resolved).Delay(TimeSpan.FromSeconds(5), scheduler), + ownAddressCacheStream: Observable.Throw(OwnAddressSubscribeTimeout()), + enrich: Observable.Return); + + AssertActivationDidNotFault(errors); + Assert.Same(resolved, Assert.Single(nodes)); + } + + /// + /// The accelerator still works: a warm cache entry that replays the node before the path + /// resolver reaches storage drives the activation, so a reactivation skips the storage read. + /// + [Fact] + public void WarmOwnAddressCacheValue_DrivesActivation() + { + var scheduler = new TestScheduler(); + var warm = Node("Edu", "Store/Plugin"); + var fromStorage = Node("Edu", "Store/Plugin"); + + var (nodes, errors, _) = RunActivation( + scheduler, + pathResolverStream: Observable.Return(fromStorage).Delay(TimeSpan.FromSeconds(3), scheduler), + ownAddressCacheStream: Observable.Return(warm), + enrich: Observable.Return); + + AssertActivationDidNotFault(errors); + Assert.Same(warm, Assert.Single(nodes)); + } + + /// + /// A genuinely missing node must still be reported PROMPTLY. Collapsing the faulted cache branch + /// to Empty (not Never) lets the merged source complete as soon as both branches + /// are done, so OnActivateAsync's "source completed with no usable node" handler fires at + /// once instead of waiting out the 30 s first-emission budget. + /// + [Fact] + public void NoNodeAnywhere_CompletesImmediately_RatherThanBurningTheBudget() + { + var scheduler = new TestScheduler(); + + var (nodes, errors, completions) = RunActivation( + scheduler, + pathResolverStream: Observable.Empty(), + ownAddressCacheStream: Observable.Throw(OwnAddressSubscribeTimeout()), + enrich: Observable.Return); + + Assert.Empty(nodes); + AssertActivationDidNotFault(errors); + Assert.Equal(1, completions); + } + + /// + /// Guard against over-reach: only the SELF-REFERENTIAL branch is neutralised. The path resolver + /// reads storage — its failure is real news about the node and must still fault the activation + /// (the caller gets a deterministic NACK and the grain deactivates for retry-on-next-access). + /// + [Fact] + public void PathResolverFailure_StillFaultsActivation() + { + var scheduler = new TestScheduler(); + var storageFailure = new InvalidOperationException("storage adapter unavailable"); + + var (nodes, errors, _) = RunActivation( + scheduler, + pathResolverStream: Observable.Throw(storageFailure), + ownAddressCacheStream: Observable.Never(), + enrich: Observable.Return); + + Assert.Empty(nodes); + Assert.Same(storageFailure, Assert.Single(errors)); + } + + /// + /// The first-emission budget is intact: when NEITHER branch produces a node the activation still + /// faults with the precise, actionable diagnostic — never a silent park. + /// + [Fact] + public void NeitherBranchEmits_FaultsWithTheFirstNodeResolutionDiagnostic() + { + var scheduler = new TestScheduler(); + + var (nodes, errors, _) = RunActivation( + scheduler, + pathResolverStream: Observable.Never(), + ownAddressCacheStream: Observable.Never(), + enrich: Observable.Return); + + Assert.Empty(nodes); + var error = Assert.Single(errors); + Assert.IsType(error); + Assert.Contains("No MeshNode emitted for 'Edu'", error.Message); + } + + /// + /// And the budget bounds ONLY the first emission — once a node arrives, Amb commits to the + /// source and a legitimately slow enrichment (cold compile) runs past the budget unharmed. + /// + [Fact] + public void SlowEnrichment_IsNotCutShortByTheFirstNodeBudget() + { + var scheduler = new TestScheduler(); + var enriched = Node("Edu", "Store/Plugin"); + + var (nodes, errors, _) = RunActivation( + scheduler, + pathResolverStream: Observable.Return(Node("Edu", "Store/Plugin")) + .Delay(TimeSpan.FromSeconds(1), scheduler), + ownAddressCacheStream: Observable.Never(), + enrich: _ => Observable.Return(enriched).Delay(TimeSpan.FromMinutes(4), scheduler)); + + AssertActivationDidNotFault(errors); + Assert.Same(enriched, Assert.Single(nodes)); + } +}