From 792acf0dce6007c1254a36fdd567f040011f188f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20B=C3=BCrgi?= <6334612+rbuergi@users.noreply.github.com> Date: Tue, 1 Sep 2026 09:06:23 +0200 Subject: [PATCH] fix(self-update): establishing the policy is not the same as re-establishing it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit memex-cloud served memex.meshweaver.cloud from rc8.ci.6829 while ACR had reached rc9.ci.7231 — about 400 builds behind, its pinned module set advanced past the image (modules 'contributing nothing'), memory at 89%, boot churn, and satellite CI gates failing on its bundle endpoints. Every trigger — startup, build completion, policy change, AND the safety net that exists to bound a dead event channel — is gated on the first emission of the live Admin/UpdatePolicy read. That gate is right: #2731/#2797 removed the synthetic default emission precisely because deciding under a guessed policy rolled pinned installs on every pod start. The cadence behind the gate was wrong. A faulted first read was paced by RetryInterval — six hours, documented for RE-establishing a watch that has already produced. Before the first read nothing is retained and no check can run, so that value does not pace anything: it takes the whole feature out, and the safety net cannot bound it because the safety net is behind the same gate. On a heavy instance whose boot-time SubscribeRequest exceeds its minute, that is six hours of an install that looks healthy and has stopped asking. Two pods of the SAME build proved the mechanism rather than suggesting it: the one logging 'policy stream faulted; re-establishing in 06:00:00' had run ZERO checks; its sibling, whose read succeeded, had run two. So the two states get two cadences, chosen in one place (SelfUpdateOptions.PolicyRetryDelay): PolicyEstablishRetryInterval (30 s) while no policy has ever been read, RetryInterval once one has — where the value is retained, checks continue, and a fault costs freshness rather than the feature. The warning now names which state it is in. 🚨 The pre-existing first-read test could not see this: it set RetryInterval itself to 500 ms, so it proved recovery HAPPENS while saying nothing about recovery happening usefully — the config-shaped guard that cannot observe the outcome. It now sets the establishing interval and leaves RetryInterval at its production default, and a second test pins the same fault shape with the real six-hour value, so the only thing that can make it pass is the fix. Mutation-proven: with PolicyRetryDelay reverted to RetryInterval behind a runtime-false condition, 3 tests fail (both new ones and the corrected pre-existing one); restored, 31/31 green. Verified: Release -warnaserror clean on MeshWeaver.Hosting and MeshWeaver.Hosting.Monolith.Test; SelfUpdate suite 31/31. Co-Authored-By: Claude Opus 5 (1M context) --- .../SelfUpdate/SelfUpdateHostedService.cs | 28 +++++- ...-update-policy-no-longer-stops-updating.md | 37 ++++++++ .../SelfUpdate/SelfUpdateOptions.cs | 37 ++++++++ .../SelfUpdatePollerResilienceTest.cs | 87 +++++++++++++++++-- 4 files changed, 181 insertions(+), 8 deletions(-) create mode 100644 src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-01-an-install-that-cannot-read-its-update-policy-no-longer-stops-updating.md diff --git a/memex/Memex.Portal.Shared/SelfUpdate/SelfUpdateHostedService.cs b/memex/Memex.Portal.Shared/SelfUpdate/SelfUpdateHostedService.cs index 0466c2199f..f6d105867d 100644 --- a/memex/Memex.Portal.Shared/SelfUpdate/SelfUpdateHostedService.cs +++ b/memex/Memex.Portal.Shared/SelfUpdate/SelfUpdateHostedService.cs @@ -55,6 +55,15 @@ public class SelfUpdateHostedService : IHostedService /// private int _buildEventsSeen; + /// + /// 1 once the live policy read has produced a value — i.e. once the gate every trigger waits on + /// has opened. Chooses the retry cadence for a faulted watch (see + /// ): before it, the poller is inert and a fault + /// must be retried quickly; after it, the long interval paces re-establishment. An instance + /// field — its lifetime is this service's — never static. + /// + private int _policyEstablished; + public SelfUpdateHostedService( IMessageHub hub, IAcrTagLister acr, @@ -307,6 +316,8 @@ private IObservable CreatePolicySource() .Take(1) .SelectMany(_ => Observable .Defer(ReadPolicyStream) + // The gate has opened: from here a fault costs freshness, not the feature. + .Do(_ => Interlocked.Exchange(ref _policyEstablished, 1)) .RetryWhen(ResubscribeAfterRetryInterval("policy stream"))) .DistinctUntilChanged(c => (c.Policy, c.RequireCiGreen)); // <-- re-switch only on a REAL policy change } @@ -414,9 +425,22 @@ public static IObservable NewBuildEventsAcross(IObservable, IObservable> ResubscribeAfterRetryInterval(string stage) => faults => faults.SelectMany(ex => { + // 🚨 The cadence depends on whether a policy has EVER been read, because the two states + // cost completely different things. Before the first read the poller is INERT — every + // trigger, the safety net included, is gated on that first emission — so a fault there + // takes the whole feature out; after it, the last policy is retained and checks keep + // running, so a fault costs only freshness and the long interval is right. Pacing both + // at RetryInterval is what left memex-cloud ~400 builds behind (see + // SelfUpdateOptions.PolicyEstablishRetryInterval for the measurement). + var established = Volatile.Read(ref _policyEstablished) == 1; + var delay = _options.PolicyRetryDelay(established); _logger?.LogWarning(ex, - "[SelfUpdate] {Stage} faulted; re-establishing in {Interval}.", stage, _options.RetryInterval); - return Observable.Timer(_options.RetryInterval); + "[SelfUpdate] {Stage} faulted; re-establishing in {Interval} ({State}).", + stage, delay, + established + ? "a policy has been read — checks continue against it meanwhile" + : "NO policy read yet — every check is gated on it, so this install is inert until it succeeds"); + return Observable.Timer(delay); }); /// One evaluation: list tags → pick target per policy → gate target > current → diff --git a/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-01-an-install-that-cannot-read-its-update-policy-no-longer-stops-updating.md b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-01-an-install-that-cannot-read-its-update-policy-no-longer-stops-updating.md new file mode 100644 index 0000000000..ef760eba9b --- /dev/null +++ b/src/MeshWeaver.Documentation/Data/WhatsNew/2026-09-01-an-install-that-cannot-read-its-update-policy-no-longer-stops-updating.md @@ -0,0 +1,37 @@ +--- +Name: An install that cannot read its update policy no longer stops updating for six hours +Category: Fix +Description: A slow first read of Admin/UpdatePolicy used to leave a portal with no update checks at all until the six-hour retry came round; it now retries in seconds, because until that read lands the install is not slow, it is inert. +Icon: ArrowSync +Order: -20260901 +--- + +# An install that cannot read its update policy no longer stops updating for six hours + +Every self-update trigger — the startup pass, a build completion, an admin changing the policy, and +the safety net that exists to bound a dead event channel — waits for the install to have actually +**read** its `Admin/UpdatePolicy` node. That gate is deliberate: a portal must never decide to roll +itself under a policy it only guessed at, which is how a pinned install once rolled on every pod +start. + +The gate was right; the cadence behind it was not. When that first read faulted — on a busy portal +the boot-time `SubscribeRequest` can exceed its minute — the retry was paced by `RetryInterval`, +the six-hour value meant for re-establishing a watch that has already produced a value. But before +the first read there is nothing to re-establish and nothing retained: the install performs **no +checks at all**, and the safety net cannot help, because it is behind the same gate. One slow read +therefore bought six hours of an install that looked perfectly healthy and had quietly stopped +asking whether a newer release existed. + +That is not a hypothesis. On 1 September a portal was found serving `rc8.ci.6829` while the +registry had reached `rc9.ci.7231` — roughly four hundred builds — with its pinned module set +advanced past its image, so modules reported themselves as "contributing nothing", memory sat at +89%, and other repositories' CI gates failed against its bundle endpoints. Two pods of the *same* +build settled it: the one that logged `policy stream faulted; re-establishing in 06:00:00` had run +zero checks, while its sibling, whose read succeeded, had run two. + +Establishing the policy now has its own cadence (`SelfUpdate__PolicyEstablishRetryInterval`, +30 seconds by default). Once the policy **has** been read, a later fault keeps the six-hour +interval exactly as before — the last value is retained and checks keep running, so that fault +costs freshness rather than the feature. The log line now says which of the two states it is in, +so the difference between "this install is pacing itself" and "this install is inert" is readable +rather than inferred. diff --git a/src/MeshWeaver.Hosting/SelfUpdate/SelfUpdateOptions.cs b/src/MeshWeaver.Hosting/SelfUpdate/SelfUpdateOptions.cs index 8202f28d06..d3f5295e15 100644 --- a/src/MeshWeaver.Hosting/SelfUpdate/SelfUpdateOptions.cs +++ b/src/MeshWeaver.Hosting/SelfUpdate/SelfUpdateOptions.cs @@ -44,6 +44,43 @@ public record SelfUpdateOptions /// public TimeSpan RetryInterval { get; init; } = TimeSpan.FromHours(6); + /// + /// 🚨 The retry cadence while the update policy has NEVER been read — the ESTABLISHING case, + /// which is the wrong value for. + /// + /// Every trigger — startup, build completion, policy change, AND the + /// safety net — is gated on the first policy emission, + /// deliberately: the poller must never decide under a policy it has not read (#2731/#2797). + /// So until that first read succeeds self-update is not slow, it is entirely INERT, and the + /// safety net that exists to bound a dead channel sits BEHIND that same gate and cannot bound + /// this one. Pacing the first attempt at the 6 h therefore turns a + /// single slow boot-time SubscribeRequest into six hours with no checks at all. + /// + /// Measured, not hypothetical: on 2026-09-01 memex-cloud served + /// memex.meshweaver.cloud from rc8.ci.6829 while ACR had reached + /// rc9.ci.7231 — roughly 400 builds behind, its pinned module set advanced past the + /// image, modules "contributing nothing", and satellite CI gates failing on the bundle + /// endpoints. Two pods of the SAME build told the whole story: the one whose policy read + /// faulted (policy stream faulted; re-establishing in 06:00:00) had run ZERO checks, + /// while its sibling, which read the policy cleanly, had run two. + /// + /// Once the policy HAS been read a later fault keeps the long + /// : the last value is retained, checks keep running, and the + /// pacing intent is untouched. is that decision, and it is the + /// only place the two cadences are chosen between. + /// + public TimeSpan PolicyEstablishRetryInterval { get; init; } = TimeSpan.FromSeconds(30); + + /// + /// How long a faulted watch waits before re-establishing: + /// while the poller has never read a policy (it is inert until it has, so a fault in that state + /// costs the whole feature), once it has (the value is retained and + /// checks continue, so the fault costs only freshness). Pure — pinned by + /// SelfUpdatePollerResilienceTest in both directions. + /// + public TimeSpan PolicyRetryDelay(bool policyEstablished) => + policyEstablished ? RetryInterval : PolicyEstablishRetryInterval; + /// /// The minimum time between two automatic rolls of this install. /// diff --git a/test/MeshWeaver.Hosting.Monolith.Test/SelfUpdatePollerResilienceTest.cs b/test/MeshWeaver.Hosting.Monolith.Test/SelfUpdatePollerResilienceTest.cs index 971f73fca9..5055aa195f 100644 --- a/test/MeshWeaver.Hosting.Monolith.Test/SelfUpdatePollerResilienceTest.cs +++ b/test/MeshWeaver.Hosting.Monolith.Test/SelfUpdatePollerResilienceTest.cs @@ -196,9 +196,10 @@ public async Task Poller_survives_faulted_first_read_and_processes_a_policy_chan var updater = new RecordingUpdater(); var options = new SelfUpdateOptions { - // The poll interval doubles as the fault-resubscribe delay — short so the test observes - // the recovery promptly. - RetryInterval = TimeSpan.FromMilliseconds(500), + // A first-read fault is the ESTABLISHING case, so this is the interval that paces the + // recovery — short here so the test observes it promptly. RetryInterval is deliberately + // left at its production default: it must not be what gets this install moving again. + PolicyEstablishRetryInterval = TimeSpan.FromMilliseconds(500), DefaultPolicy = UpdatePolicyKind.Continuous, }; var service = new FaultingFirstReadService( @@ -209,9 +210,11 @@ public async Task Poller_survives_faulted_first_read_and_processes_a_policy_chan try { // 1. The first live read FAULTS (TimeoutException — the prod shape) right after the seed. - // The startup default (Continuous) still drives the first poll, and the faulted read - // must retry silently in the background. Pre-fix the fault terminated the whole - // subscription permanently. + // Nothing can proceed on a guessed policy (#2731/#2797 removed the synthetic default + // emission), so EVERY trigger waits on the re-read: the roll below is proof the + // faulted read came back on its own. Pre-fix the fault terminated the whole + // subscription permanently; pre-#PolicyEstablishRetryInterval it came back only after + // the 6 h RetryInterval, which is the same outage with a longer name. var firstTag = await updater.Patched .FirstAsync() .Timeout(TimeSpan.FromSeconds(30)) @@ -344,4 +347,76 @@ await updater.Patched await service.StopAsync(CancellationToken.None); } } + + /// + /// 🚨 The memex-cloud defect, at production cadence (2026-09-01). A first policy read that + /// faults must NOT park this install on : every + /// trigger — startup, build completion, policy change and the safety net — is gated on that + /// first emission, so until it lands the install performs no checks AT ALL and the safety net + /// cannot bound it, because the safety net is behind the same gate. + /// + /// What it cost: memex.meshweaver.cloud served rc8.ci.6829 while ACR had reached + /// rc9.ci.7231 — about 400 builds — with its pinned module set advanced past the image + /// (modules "contributing nothing"), memory at 89% and satellite CI gates failing on its bundle + /// endpoints. Two pods of the same build proved the mechanism: the one that logged policy + /// stream faulted; re-establishing in 06:00:00 had run ZERO checks, its sibling two. + /// + /// 🚨 The pre-existing first-read test cannot see this, and that is the point of adding a + /// second one: it sets RetryInterval itself to 500 ms, so it proves recovery HAPPENS + /// while saying nothing about recovery happening usefully. Here RetryInterval keeps its + /// production default, so the only thing that can make this test pass is the establishing + /// cadence. + /// + [Fact(Timeout = 60000)] + public async Task A_faulted_FIRST_policy_read_recovers_at_the_establish_cadence_not_the_six_hour_one() + { + var ct = TestContext.Current.CancellationToken; + var acr = new FakeAcrTagLister(); + var updater = new RecordingUpdater(); + var options = new SelfUpdateOptions + { + // PRODUCTION value, deliberately: if the fix regresses, this is the wait, and the test + // fails by timeout rather than by passing for the wrong reason. + RetryInterval = TimeSpan.FromHours(6), + PolicyEstablishRetryInterval = TimeSpan.FromMilliseconds(200), + DefaultPolicy = UpdatePolicyKind.Continuous, + }; + var service = new FaultingFirstReadService( + Mesh, acr, updater, options, + Mesh.ServiceProvider.GetService>()); + + await service.StartAsync(CancellationToken.None); + try + { + // The positive signal is a ROLL: it can only happen after a policy has actually been + // read, which can only happen after the faulted first read was re-established. + var applied = await updater.Patched + .FirstAsync() + .Timeout(TimeSpan.FromSeconds(30)) + .Await(ct); + applied.Should().Be(FakeAcrTagLister.CiTag); + service.ReadSubscriptions.Should().BeGreaterThanOrEqualTo(2, + "the recovery must have gone through the injected fault and a re-subscription"); + } + finally + { + await service.StopAsync(CancellationToken.None); + } + } + + /// + /// The decision itself, both directions and in the right order: fast while no policy has been + /// read (the install is inert), paced once one has (the value is retained and checks continue). + /// Pure, so it pins the intent without waiting on a mesh. + /// + [Fact] + public void PolicyRetryDelay_is_fast_while_establishing_and_paced_once_established() + { + var options = new SelfUpdateOptions(); + + options.PolicyRetryDelay(policyEstablished: false).Should().Be(options.PolicyEstablishRetryInterval); + options.PolicyRetryDelay(policyEstablished: true).Should().Be(options.RetryInterval); + options.PolicyEstablishRetryInterval.Should().BeLessThan(options.RetryInterval, + "an install with no policy yet is INERT — it must not wait a re-establishment interval"); + } }