Darling keeps retrying the store at start instead of never collecting after the retry budget (#4508)

Darling/Darling.Tests/CollectorRuntimeStateTests.cs

@@ -401,9 +401,10 @@ public void EveryRetryPublish_ReportsTheTriagesOwnAttemptCap()
 
         var calls = Regex.Matches(code, @"_collectorState\.PublishRetrying\((?<args>[^)]*)\)").ToList();
         Assert.True(
-            calls.Count == 3,
+            calls.Count == 4,
             $"expected a retry publish on each of the three collection-blocking startup steps (config load, "
-            + $"managed-Postgres bootstrap, store connect/migrate); found {calls.Count}.");
+            + $"managed-Postgres bootstrap, store connect/migrate) plus the store site's #4508 sustained-retry "
+            + $"arm (fast budget spent, still retryable); found {calls.Count}.");
 
         foreach (var call in calls)
         {

Darling/Darling.Tests/StartupFailureTriageTests.cs

@@ -585,7 +585,12 @@ bare Stopwatch.StartNew(): every retry budget here is a stopwatch, but not every
            DarlingWorker - #2997 added a per-run clock to the collector fault arms, hundreds of lines and
            one concern away - which tells nobody whether a fourth retry site appeared. Suffixed, the pin
            measures the thing its own sentence claims. */
-        Assert.Equal(3, CountOf(source, "StartupFailureTriage.IsRetryable(ex)"));
+        /* Four IsRetryable(ex) sites, not three, since #4508: the store site's sustained-retry arm (fast
+           budget spent, still retryable) re-checks the classifier rather than assuming the fast arm's
+           filter already proved it — see TheStoreSustainedRetryArm_LogsCriticalOnceThenWarningPerRetry.
+           Still exactly three stopwatches: the sustained arm reuses storeRetryBudget rather than starting
+           a fourth. */
+        Assert.Equal(4, CountOf(source, "StartupFailureTriage.IsRetryable(ex)"));
         Assert.Equal(3, CountOf(source, "RetryBudget = System.Diagnostics.Stopwatch.StartNew();"));
     }
 
@@ -633,6 +638,121 @@ that DOES mention the classifier proves an absent mention is a real absence. */
         Assert.DoesNotContain("StartupFailureTriage", guardArm, StringComparison.Ordinal);
     }
 
+    /// <summary>
+    /// #4508: within the fast budget, a retryable failure gets <see cref="StartupRetryDecision.RetryFast"/>
+    /// at <see cref="StartupFailureTriage.RetryDelay"/> — the decision the loop's own inline filter used to
+    /// make without a name.
+    /// </summary>
+    [Fact]
+    public void NextAction_WithinBudget_IsRetryFast()
+    {
+        var next = StartupFailureTriage.NextAction(
+            attempt: 1, elapsed: TimeSpan.FromSeconds(1), new NpgsqlException("connection went away"));
+
+        Assert.Equal(StartupRetryDecision.RetryFast, next.Decision);
+        Assert.Equal(StartupFailureTriage.RetryDelay, next.Delay);
+    }
+
+    /// <summary>
+    /// #4508, the defect itself. Before this PR the loop had no arm for "fast budget spent, still
+    /// retryable" — it fell through to the terminal catch, stood down, and never collected again. This is
+    /// the pin RED against dev: <see cref="StartupFailureTriage.NextAction"/> and
+    /// <see cref="StartupRetryDecision.RetrySustained"/> do not exist on dev at all, so this is a compile
+    /// failure there rather than a runtime assertion failure — see the PR body for the RED transcript.
+    /// </summary>
+    [Fact]
+    public void NextAction_BudgetSpentButStillRetryable_IsRetrySustained()
+    {
+        var next = StartupFailureTriage.NextAction(
+            attempt: StartupFailureTriage.Attempts,
+            elapsed: StartupFailureTriage.RetryBudget,
+            new NpgsqlException("connection went away"));
+
+        Assert.Equal(StartupRetryDecision.RetrySustained, next.Decision);
+        Assert.Equal(StartupFailureTriage.SustainedRetryDelay, next.Delay);
+
+        /* Either cap alone reaching its edge is enough — not just both together. */
+        var attemptCapOnly = StartupFailureTriage.NextAction(
+            attempt: StartupFailureTriage.Attempts,
+            elapsed: TimeSpan.FromSeconds(1),
+            new NpgsqlException("connection went away"));
+        Assert.Equal(StartupRetryDecision.RetrySustained, attemptCapOnly.Decision);
+
+        var wallClockCapOnly = StartupFailureTriage.NextAction(
+            attempt: 2,
+            elapsed: StartupFailureTriage.RetryBudget,
+            new NpgsqlException("connection went away"));
+        Assert.Equal(StartupRetryDecision.RetrySustained, wallClockCapOnly.Decision);
+    }
+
+    /// <summary>
+    /// #4508: a non-retryable failure is <see cref="StartupRetryDecision.Stop"/> at ANY attempt and ANY
+    /// elapsed time — including attempt 1, before either cap has moved at all. The budget running out
+    /// changes nothing about a rung that can never apply; #4508 must not blur that boundary while fixing
+    /// the retryable side of it.
+    /// </summary>
+    [Theory]
+    [InlineData(1, 0)]
+    [InlineData(25, 120)]
+    public void NextAction_NonRetryableFailure_IsAlwaysStop(int attempt, int elapsedSeconds)
+    {
+        var terminal = new PostgresException("relation does not exist", "ERROR", "ERROR", "42P01");
+
+        var next = StartupFailureTriage.NextAction(attempt, TimeSpan.FromSeconds(elapsedSeconds), terminal);
+
+        Assert.Equal(StartupRetryDecision.Stop, next.Decision);
+        Assert.Equal(TimeSpan.Zero, next.Delay);
+    }
+
+    /// <summary>
+    /// #4508: the store loop's sustained arm logs CRITICAL exactly once — the moment the fast budget
+    /// first runs out — and WARNING on every later attempt on the same still-down store, mirroring the
+    /// once/per-retry split the fast arm already has between its own single warning template and the
+    /// terminal catch's single critical line. Read off the shipped source, the same way the fast arm's own
+    /// pins are: <c>storeSustainedRetryCriticalLogged</c> gates the critical line and only the critical
+    /// line, and the sustained arm's own catch delays on <c>SustainedRetryDelay</c> rather than the fast
+    /// arm's <c>RetryDelay</c>.
+    /// </summary>
+    [Fact]
+    public void TheStoreSustainedRetryArm_LogsCriticalOnceThenWarningPerRetry()
+    {
+        var source = ReadWorkerSource();
+        var sustainedArm = Slice(
+            source,
+            "catch (Exception ex) when (ex is not OperationCanceledException\n                && StartupFailureTriage.IsRetryable(ex))",
+            "await Task.Delay(next.Delay, stoppingToken);");
+
+        Assert.Contains("storeSustainedRetryCriticalLogged", sustainedArm, StringComparison.Ordinal);
+        Assert.Contains("_logger.LogCritical(", sustainedArm, StringComparison.Ordinal);
+        Assert.Contains("_logger.LogWarning(", sustainedArm, StringComparison.Ordinal);
+        Assert.Contains("StartupFailureTriage.NextAction(attempt, storeRetryBudget.Elapsed, ex)", sustainedArm, StringComparison.Ordinal);
+
+        /* The flag is set to true exactly once, inside the critical branch — not reset per attempt, or
+           every attempt would re-log critical. */
+        Assert.Equal(1, CountOf(sustainedArm, "storeSustainedRetryCriticalLogged = true;"));
+        Assert.Equal(0, CountOf(sustainedArm, "storeSustainedRetryCriticalLogged = false;"));
+    }
+
+    /// <summary>
+    /// #4508: the sustained arm still publishes <see cref="CollectorRuntimeState.CollectorPhase.Retrying"/>,
+    /// not <see cref="CollectorRuntimeState.CollectorPhase.Stopped"/> — the published state has to keep
+    /// saying "retrying" for as long as the loop keeps retrying, or <c>/api/ping</c> would report the
+    /// service stopped while it is, in fact, still trying every minute.
+    /// </summary>
+    [Fact]
+    public void TheStoreSustainedRetryArm_PublishesRetryingNotStopped()
+    {
+        var source = ReadWorkerSource();
+        var sustainedArm = Slice(
+            source,
+            "catch (Exception ex) when (ex is not OperationCanceledException\n                && StartupFailureTriage.IsRetryable(ex))",
+            "await Task.Delay(next.Delay, stoppingToken);");
+
+        Assert.Contains("_collectorState.PublishRetrying(", sustainedArm, StringComparison.Ordinal);
+        Assert.DoesNotContain("_collectorState.PublishStopped(", sustainedArm, StringComparison.Ordinal);
+        Assert.DoesNotContain("return;", sustainedArm, StringComparison.Ordinal);
+    }
+
     private static int CountOf(string haystack, string needle)
     {
         var n = 0;

Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs

@@ -1870,6 +1870,12 @@ so a retry resumes at the rung that failed instead of redoing the ladder. That r
            job and no reloptions. No rung uses CREATE INDEX CONCURRENTLY or any other statement that
            cannot be transacted. */
         var storeRetryBudget = System.Diagnostics.Stopwatch.StartNew();
+        /* #4508: set once, the first time the fast budget above runs out on a failure that is still
+           retryable — see the arm below. Gates CRITICAL-once/WARNING-per-retry the same way the config
+           and bootstrap sites' single terminal LogCritical already is "once": this is the sustained arm's
+           one moment where the diagnosis is new, and every later attempt on the same still-down store is
+           not. */
+        var storeSustainedRetryCriticalLogged = false;
         for (var attempt = 1; ; attempt++)
         {
             try
@@ -1898,14 +1904,52 @@ kills the service harder than the failure it was retrying. */
                     ex,
                     "Cannot reach or migrate the Postgres store yet ({Message}) — attempt {Attempt} of " +
                     "{Total}, retrying in {Delay}s. A store that is restarting, failing over or still " +
-                    "coming up recovers on its own; after the last attempt this becomes a critical line " +
-                    "and collection does not start.",
+                    "coming up recovers on its own; after the last attempt this keeps retrying more slowly " +
+                    "instead of giving up.",
                     ex.Message, attempt, StartupFailureTriage.Attempts,
                     (int)StartupFailureTriage.RetryDelay.TotalSeconds);
                 _collectorState.PublishRetrying(
                     CollectorRuntimeState.StartupStep.Store, attempt, StartupFailureTriage.Attempts);
                 await Task.Delay(StartupFailureTriage.RetryDelay, stoppingToken);
             }
+            catch (Exception ex) when (ex is not OperationCanceledException
+                && StartupFailureTriage.IsRetryable(ex))
+            {
+                /* #4508: reached only once the fast arm above has stopped matching — its own attempt/budget
+                   conjuncts are false, so this is a store outage that has already outlasted the two-minute
+                   fast budget while still being a failure StartupFailureTriage.IsRetryable accepts. The old
+                   code had no third arm here: the fast filter going false let this fall straight through to
+                   the terminal catch below, so a store still coming back got the identical CRITICAL /
+                   PublishStopped / return a rung that can never apply gets, and collection never started
+                   again for the life of the process. NextAction is the SAME decision the fast arm's filter
+                   re-derives inline (attempt/budget/classifier) — calling it here, rather than reaching for
+                   SustainedRetryDelay directly, is what routes this arm's delay through the seam instead of
+                   beside it. */
+                var next = StartupFailureTriage.NextAction(attempt, storeRetryBudget.Elapsed, ex);
+                if (!storeSustainedRetryCriticalLogged)
+                {
+                    _logger.LogCritical(
+                        ex,
+                        "Cannot reach or migrate the Postgres store within the {Budget}s retry budget " +
+                        "({Message}); this is still a recoverable failure, so it keeps retrying every " +
+                        "{Delay}s instead of standing down. Collection will not start until it succeeds.",
+                        (int)StartupFailureTriage.RetryBudget.TotalSeconds, ex.Message,
+                        (int)StartupFailureTriage.SustainedRetryDelay.TotalSeconds);
+                    storeSustainedRetryCriticalLogged = true;
+                }
+                else
+                {
+                    _logger.LogWarning(
+                        ex,
+                        "Still cannot reach or migrate the Postgres store ({Message}) — attempt {Attempt}, " +
+                        "retrying in {Delay}s.",
+                        ex.Message, attempt, (int)StartupFailureTriage.SustainedRetryDelay.TotalSeconds);
+                }
+
+                _collectorState.PublishRetrying(
+                    CollectorRuntimeState.StartupStep.Store, attempt, StartupFailureTriage.Attempts);
+                await Task.Delay(next.Delay, stoppingToken);
+            }
             catch (Exception ex) when (ex is not OperationCanceledException)
             {
                 _logger.LogCritical(ex, "Cannot reach or migrate the Postgres store: {Message}", ex.Message);

Darling/PerformanceMonitor.Darling.Service/StartupFailureTriage.cs

@@ -233,6 +233,22 @@ internal static class StartupFailureTriage
     /// </summary>
     internal static readonly TimeSpan RetryBudget = TimeSpan.FromSeconds(120);
 
+    /// <summary>
+    /// Pause between attempts once <see cref="RetryBudget"/> has already run out on a <see cref="IsRetryable"/>
+    /// failure (#4508). The fast budget above answers "is this an ordinary blip"; once it is spent the
+    /// question has already been answered NO for that meaning, and what is left is a store outage nobody
+    /// has fixed yet. Retrying forever, but slower, is right here for the same reason <see cref="Attempts"/>'s
+    /// own remarks give for NOT making the fast path a supervisor loop: the caller is a straight-line
+    /// startup step that must eventually succeed, not a tick with nothing else to do — except that
+    /// "eventually" for a two-minute store outage is provably wrong, because the old behaviour after the
+    /// fast budget was to give up and never collect again for the life of the process, silently, with the
+    /// host staying up and reporting healthy. A minute is slow enough that a store still down does not get
+    /// hammered by a service that is, by construction, no longer in a hurry, and fast enough that a store
+    /// that comes back is noticed within the span an operator paged for the outage would already be
+    /// watching.
+    /// </summary>
+    internal static readonly TimeSpan SustainedRetryDelay = TimeSpan.FromSeconds(60);
+
     /// <summary>
     /// <c>SqlState</c>s that mean "not yet" rather than "no" — see the class remarks for what each one was
     /// observed doing. An allowlist: a state absent from it is terminal, which is what keeps a rung that
@@ -318,4 +334,70 @@ moments to wait out. See the class remarks. */
 
         return exception is NpgsqlException;
     }
+
+    /// <summary>
+    /// What one of the three collection-blocking startup steps' loops does about a caught
+    /// <paramref name="exception"/> on <paramref name="attempt"/>, having already run <paramref name="elapsed"/>
+    /// since its first attempt (#4508). The whole retry DECISION lives here, pulled out of the loop, so it can
+    /// be pinned without a store, a config file or a migration to fail: given the same three inputs the loop
+    /// itself would have seen, this returns exactly what the loop should do next.
+    ///
+    /// <para><b>The defect this replaces.</b> Before #4508, once <see cref="Attempts"/> or
+    /// <see cref="RetryBudget"/> ran out on a failure <see cref="IsRetryable"/> still accepted, the loop fell
+    /// through to the bare terminal catch — the same <c>LogCritical</c> / <c>PublishStopped</c> / <c>return</c>
+    /// a NON-retryable failure gets, byte for byte. A store outage that outlasted two minutes and a rung that
+    /// can never apply became indistinguishable again, one layer up from the distinction
+    /// <see cref="IsRetryable"/> exists to draw: the process stayed up, reporting healthy, and never collected
+    /// again until a human restarted it.</para>
+    ///
+    /// <para><see cref="RetrySustained"/> is the new third outcome: the fast budget is spent, but the failure
+    /// is still one <see cref="IsRetryable"/> accepts, so the loop keeps going on <see cref="SustainedRetryDelay"/>
+    /// instead of stopping. <paramref name="attempt"/> and <paramref name="elapsed"/> only distinguish
+    /// <see cref="RetryFast"/> from <see cref="RetrySustained"/> for a retryable failure; a NON-retryable one is
+    /// always <see cref="Stop"/>, at any attempt, on any elapsed time — the caller does not need to spend the
+    /// fast budget to learn that a rung that cannot apply will not start applying.</para>
+    /// </summary>
+    /// <param name="attempt">The 1-based attempt that just failed.</param>
+    /// <param name="elapsed">Wall clock since the loop's first attempt.</param>
+    /// <param name="exception">The failure the attempt caught. <see cref="OperationCanceledException"/> is the
+    /// caller's to filter out first — it means shutdown, and this method is never reached for it.</param>
+    internal static NextStartupAction NextAction(int attempt, TimeSpan elapsed, Exception? exception)
+    {
+        if (!IsRetryable(exception))
+        {
+            return new NextStartupAction(StartupRetryDecision.Stop, TimeSpan.Zero);
+        }
+
+        if (attempt < Attempts && elapsed < RetryBudget)
+        {
+            return new NextStartupAction(StartupRetryDecision.RetryFast, RetryDelay);
+        }
+
+        return new NextStartupAction(StartupRetryDecision.RetrySustained, SustainedRetryDelay);
+    }
 }
+
+/// <summary>
+/// What a collection-blocking startup loop should do next, decided by <see cref="StartupFailureTriage.NextAction"/>
+/// (#4508).
+/// </summary>
+internal enum StartupRetryDecision
+{
+    /// <summary>Retry inside the fast budget, after <see cref="StartupFailureTriage.RetryDelay"/>.</summary>
+    RetryFast,
+
+    /// <summary>The fast budget is spent, but the failure is still one <see cref="StartupFailureTriage.IsRetryable"/>
+    /// accepts — keep retrying, slower, after <see cref="StartupFailureTriage.SustainedRetryDelay"/>, rather than
+    /// standing down and never collecting.</summary>
+    RetrySustained,
+
+    /// <summary>The failure is terminal — stop, publish, and return, exactly as before #4508.</summary>
+    Stop,
+}
+
+/// <summary>
+/// One verdict from <see cref="StartupFailureTriage.NextAction"/>: what to do, and how long to wait first.
+/// <see cref="Delay"/> is <see cref="TimeSpan.Zero"/> for <see cref="StartupRetryDecision.Stop"/>, which never
+/// waits.
+/// </summary>
+internal readonly record struct NextStartupAction(StartupRetryDecision Decision, TimeSpan Delay);