Run the Darling bootstrap's first CREATE DATABASE once, on its own deadline (#4352)

Darling/Darling.Tests/ComposeStoreRolesLiveTests.cs

@@ -777,15 +777,96 @@ private static string RequireRuntime()
     }
 
     /// <summary>Boots the cluster (its <c>darling</c> login is the bootstrap superuser, as on the compose store)
-    /// and migrates it, since provisioning names migrated tables.</summary>
+    /// and migrates it, since provisioning names migrated tables. A boot failure carries the cluster's own
+    /// server log tail (#4352): the CI failure artifact does not collect it, and a bare exception message
+    /// ("connection open timed out", "CREATE DATABASE timed out") does not say what the server was doing.</summary>
     private static async Task<string> BootMigratedAsync(DarlingManagedPostgres cluster, CancellationToken ct)
     {
-        var owner = new NpgsqlConnectionStringBuilder(await cluster.EnsureRunningAsync(ct)) { Pooling = false }.ConnectionString;
+        string connectionString;
+        try
+        {
+            connectionString = await cluster.EnsureRunningAsync(ct);
+        }
+        catch (OperationCanceledException)
+        {
+            throw;
+        }
+        catch (Exception ex)
+        {
+            throw new InvalidOperationException(
+                $"The test cluster at {cluster.DataDirectory} did not boot: {ex.Message}{Environment.NewLine}{ServerLogTail(cluster.DataDirectory)}",
+                ex);
+        }
+
+        var owner = new NpgsqlConnectionStringBuilder(connectionString) { Pooling = false }.ConnectionString;
         await using var connection = await OpenAsync(owner, ct);
         await PgMigrations.MigrateAsync(connection, ct);
         return owner;
     }
 
+    /// <summary>The last ~200 lines of every log the cluster writes: pg_ctl's start log (one file, next to the
+    /// data directory) and the logging collector's output (one or more files under <c>&lt;data directory&gt;/log</c>).
+    /// A missing or unreadable file adds a one-line note instead of throwing, since this runs from a catch block.</summary>
+    private static string ServerLogTail(string dataDirectory)
+    {
+        const int TailLines = 200;
+        var builder = new System.Text.StringBuilder();
+
+        var startLog = Path.Combine(Path.GetDirectoryName(dataDirectory) ?? dataDirectory, DarlingManagedPostgres.ServerLogFileName);
+        AppendLogTail(builder, startLog, TailLines);
+
+        var collectorDirectory = Path.Combine(dataDirectory, "log");
+        try
+        {
+            if (Directory.Exists(collectorDirectory))
+            {
+                foreach (var path in Directory.EnumerateFiles(collectorDirectory).OrderBy(p => p, StringComparer.Ordinal))
+                {
+                    AppendLogTail(builder, path, TailLines);
+                }
+            }
+            else
+            {
+                builder.AppendLine($"--- {collectorDirectory} ---").AppendLine("(no logging-collector directory)");
+            }
+        }
+        catch (Exception ex)
+        {
+            builder.AppendLine($"--- {collectorDirectory} ---").AppendLine($"(could not list: {ex.Message})");
+        }
+
+        return builder.ToString();
+    }
+
+    private static void AppendLogTail(System.Text.StringBuilder builder, string path, int tailLines)
+    {
+        builder.AppendLine($"--- {path} ---");
+        try
+        {
+            using var stream = new FileStream(path, FileMode.Open, FileAccess.Read, FileShare.ReadWrite | FileShare.Delete);
+            using var reader = new StreamReader(stream);
+            var lines = new List<string>();
+            string? line;
+            while ((line = reader.ReadLine()) is not null)
+            {
+                lines.Add(line);
+                if (lines.Count > tailLines)
+                {
+                    lines.RemoveAt(0);
+                }
+            }
+
+            foreach (var kept in lines)
+            {
+                builder.AppendLine(kept);
+            }
+        }
+        catch (Exception ex)
+        {
+            builder.AppendLine($"(could not read: {ex.Message})");
+        }
+    }
+
     /// <summary>The login connects as <paramref name="role"/>, carries the statement_timeout backstop, and is
     /// denied a secret column.</summary>
     private static async Task AssertLeastPrivilegeAsync(string login, string role, CancellationToken ct)

Darling/Darling.Tests/StartupCommandTimeoutTests.cs

@@ -29,7 +29,7 @@ namespace Darling.Tests;
 /// <para><b>Three constants, because the failure modes differ rather than the magnitudes.</b>
 /// <see cref="ServiceCommandDeadlines.BootstrapSeconds"/> covers the un-retried bootstrap sites
 /// (<see cref="ExpectedBootstrapSites"/> of them); <see cref="ServiceCommandDeadlines.BootstrapConnectProbeSeconds"/>
-/// the two inside the bootstrap's six-attempt first-connection retry, where the deadline MULTIPLIES; and
+/// the one inside the bootstrap's six-attempt first-connection retry, where the deadline MULTIPLIES; and
 /// <see cref="ServiceCommandDeadlines.SerialLoopSeconds"/> the ten on the collection loop's serial
 /// thread, where ten sequential commands have to fit inside one watchdog window.</para>
 ///
@@ -113,7 +113,9 @@ public sealed class StartupCommandTimeoutTests
     /// </summary>
     private static readonly (string File, string Member, int Bootstrap, int ConnectProbe, int SerialLoop, int Other)[] s_startupMembers =
     {
-        ("DarlingManagedPostgres.cs", "EnsureDatabaseOnceAsync", 0, 2, 0, 0),
+        /* #4352: the probe retries with the connect; CREATE DATABASE runs once, after it, un-retried. */
+        ("DarlingManagedPostgres.cs", "OpenProbedMaintenanceConnectionAsync", 0, 1, 0, 0),
+        ("DarlingManagedPostgres.cs", "EnsureDatabaseAsync", 1, 0, 0, 0),
         ("DarlingManagedPostgres.cs", "VerifyPgHbaAsync", 3, 0, 0, 0),
         ("DarlingManagedPostgres.cs", "GuardAdoptedListenAsync", 1, 0, 0, 0),
         ("DarlingStoreUpgrade.cs", "ReadClusterIdentityAsync", 1, 0, 0, 0),
@@ -179,9 +181,9 @@ hold. It is a single-row INSERT into the same collect.collection_log #2928 bound
     };
 
     /// <summary>The group's own totals, so a member that stops creating commands fails loudly.</summary>
-    private const int ExpectedBootstrapSites = 33;
+    private const int ExpectedBootstrapSites = 34;
 
-    private const int ExpectedConnectProbeSites = 2;
+    private const int ExpectedConnectProbeSites = 1;
 
     internal const int ExpectedSerialLoopSites = 10;
 
@@ -437,9 +439,32 @@ public void TheBootstrapDeadline_StaysInsideItsJustifiedBand()
             seconds < MigrationRungBudgetSeconds(),
             $"bootstrap deadline {seconds}s reaches the {MigrationRungBudgetSeconds()}s that "
             + "PgMigrations gives ONE migration rung. That budget bounds data-MOVING DDL on a cold busy "
-            + "store; these sites are catalog reads, single-row config seeds, one count(*) and one "
-            + "idempotent grant batch, so taking the rung's number would be borrowing rather than "
-            + "deriving");
+            + "store; these sites are catalog reads, single-row config seeds, one count(*), one "
+            + "idempotent grant batch and one CREATE DATABASE of the few-megabyte template1, so taking "
+            + "the rung's number would be borrowing rather than deriving");
+    }
+
+    /// <summary>
+    /// #4352: <c>CREATE DATABASE</c> runs once, outside the connect-and-probe retry. A timeout on it means
+    /// the template copy is slow, and a retry cannot help: the timeout cancels the statement, the server
+    /// rolls the partial copy back, and the next attempt starts the copy over under the same deadline, so a
+    /// copy slower than the deadline never finishes. Pinned at the source because the failing case needs a
+    /// Windows store whose disk is slow on demand.
+    /// </summary>
+    [Fact]
+    public void TheCreateDatabase_RunsOnce_OutsideTheFirstConnectionRetry()
+    {
+        var path = SourcePath("DarlingManagedPostgres.cs");
+        var text = File.ReadAllText(path);
+        var create = CSharpSourceWalker.StripCommentsAndStrings(MemberBody(text, "EnsureDatabaseAsync", path));
+        var probe = CSharpSourceWalker.StripCommentsAndStrings(MemberBody(text, "OpenProbedMaintenanceConnectionAsync", path));
+        var loop = new Regex(@"\b(?:for|foreach|while)\s*\(|\bdo\s*\{", RegexOptions.CultureInvariant);
+
+        Assert.False(loop.IsMatch(create), "EnsureDatabaseAsync loops: CREATE DATABASE must run once, not inside a retry");
+        Assert.DoesNotContain("IsTransientConnectionFault", create, StringComparison.Ordinal);
+        Assert.True(loop.IsMatch(probe), "OpenProbedMaintenanceConnectionAsync no longer loops, so the post-start race has no retry");
+        Assert.Contains("IsTransientConnectionFault", probe, StringComparison.Ordinal);
+        Assert.Contains("OpenProbedMaintenanceConnectionAsync(", create, StringComparison.Ordinal);
     }
 
     /// <summary>
@@ -460,8 +485,7 @@ public void TheConnectProbeDeadline_SurvivesItsOwnRetryMultiplier()
         Assert.True(
             seconds >= 5,
             $"connect-probe deadline {seconds}s leaves too little over the measured worst case — a 12-14 ms "
-            + "pg_database probe and a 19-68 ms CREATE DATABASE, on a Windows box where antivirus scans "
-            + "every file the template copy creates");
+            + "pg_database probe, on a Windows box whose store is at its least warm just after start");
 
         Assert.True(
             seconds < ServiceCommandDeadlines.BootstrapSeconds,

Darling/Darling.Tests/StartupFailureTriageTests.cs

@@ -313,8 +313,8 @@ public void TheTerminalArmStillLogsCriticalAndStandsDown()
 
     /// <summary>
     /// Every attempt opens a FRESH connection, because a connector that died on a transport failure cannot
-    /// carry the next attempt — the same reason <c>DarlingManagedPostgres.EnsureDatabaseAsync</c> retries
-    /// the whole unit rather than just the open.
+    /// carry the next attempt — the same reason <c>DarlingManagedPostgres.OpenProbedMaintenanceConnectionAsync</c>
+    /// retries the connect and its first query as one unit rather than just the open.
     ///
     /// <para>Asserted by OFFSET, not by occurrence count. Hoisting the open above the loop is a
     /// RELOCATION: it leaves every count in this file invariant (one loop, one open, one migrate call), so

Darling/PerformanceMonitor.Darling.Service/DarlingManagedPostgres.cs

@@ -3945,52 +3945,69 @@ void Consider(string path)
     /// </summary>
     private async Task EnsureDatabaseAsync(string connectionString, CancellationToken cancellationToken)
     {
-        /* The whole unit retries, not just the connect. A backend that loses the post-start race dies
+        await using var connection = await OpenProbedMaintenanceConnectionAsync(connectionString, cancellationToken);
+        if (connection is null)
+        {
+            return;
+        }
+
+        _logger.LogInformation("Creating the '{Database}' database", DatabaseName);
+
+        /* Once, on the connection whose backend just answered the probe, and outside the retry (#4352).
+           The retry is for the post-start race, and that race kills a backend on its FIRST query, which is
+           the probe; this backend has already survived it. A CREATE DATABASE timeout means the template
+           copy is slow, and retrying cannot help: the timeout cancels the statement, the server rolls the
+           partial copy back, and a new attempt copies template1 from the start under the same deadline, so
+           a copy slower than the deadline never finishes. Un-retried, it takes the bootstrap group's
+           deadline; if that fires too, the bootstrap throws and the worker's startup triage retries the
+           whole start.
+           Identifier from the class constant, never from input — same interpolation reasoning
+           as TimescaleSupport/DarlingRetention. CREATE DATABASE cannot run in a transaction;
+           plain ExecuteNonQuery is the correct shape. */
+        using var create = new NpgsqlCommand($"CREATE DATABASE {DatabaseName}", connection) { CommandTimeout = ServiceCommandDeadlines.BootstrapSeconds };
+        await create.ExecuteNonQueryAsync(cancellationToken);
+    }
+
+    /// <summary>
+    /// Opens the maintenance database and asks whether the store's database exists. Returns null when it
+    /// does, and otherwise the open connection, whose backend has answered its first query.
+    /// </summary>
+    private async Task<NpgsqlConnection?> OpenProbedMaintenanceConnectionAsync(string connectionString, CancellationToken cancellationToken)
+    {
+        /* The connect and the first query retry as one unit. A backend that loses the post-start race dies
            AFTER authenticating, so the Open succeeds and the first QUERY is what fails — retrying only the
            Open would never have helped. Each attempt gets a fresh connection because the old one's
            connector is dead. */
+        var builder = new NpgsqlConnectionStringBuilder(connectionString) { Database = "postgres" };
         for (var attempt = 1; ; attempt++)
         {
+            var connection = new NpgsqlConnection(DarlingStoreConnection.PinSessionTimeZoneUtc(builder.ConnectionString));
             try
             {
-                await EnsureDatabaseOnceAsync(connectionString, cancellationToken);
-                return;
-            }
-            catch (OperationCanceledException)
-            {
-                throw;
+                await connection.OpenAsync(cancellationToken);
+                using var exists = new NpgsqlCommand($"SELECT 1 FROM pg_database WHERE datname = '{DatabaseName}'", connection) { CommandTimeout = ServiceCommandDeadlines.BootstrapConnectProbeSeconds };
+                if (await exists.ExecuteScalarAsync(cancellationToken) is not null)
+                {
+                    await connection.DisposeAsync();
+                    return null;
+                }
+
+                return connection;
             }
-            catch (Exception ex) when (attempt < FirstConnectionAttempts && IsTransientConnectionFault(ex))
+            catch (Exception ex) when (ex is not OperationCanceledException && attempt < FirstConnectionAttempts && IsTransientConnectionFault(ex))
             {
+                await connection.DisposeAsync();
                 _logger.LogWarning(
                     "The store dropped the first connection after start ({Message}) — attempt {Attempt} of {Total}. A backend that loses the shared-memory reservation race just after start does this; retrying.",
                     ex.Message, attempt, FirstConnectionAttempts);
                 await Task.Delay(s_firstConnectionRetryDelay, cancellationToken);
             }
-        }
-    }
-
-    private async Task EnsureDatabaseOnceAsync(string connectionString, CancellationToken cancellationToken)
-    {
-        var builder = new NpgsqlConnectionStringBuilder(connectionString) { Database = "postgres" };
-        await using var connection = new NpgsqlConnection(DarlingStoreConnection.PinSessionTimeZoneUtc(builder.ConnectionString));
-        await connection.OpenAsync(cancellationToken);
-
-        using (var exists = new NpgsqlCommand($"SELECT 1 FROM pg_database WHERE datname = '{DatabaseName}'", connection) { CommandTimeout = ServiceCommandDeadlines.BootstrapConnectProbeSeconds })
-        {
-            if (await exists.ExecuteScalarAsync(cancellationToken) is not null)
+            catch
             {
-                return;
+                await connection.DisposeAsync();
+                throw;
             }
         }
-
-        _logger.LogInformation("Creating the '{Database}' database", DatabaseName);
-
-        /* Identifier from the class constant, never from input — same interpolation reasoning
-           as TimescaleSupport/DarlingRetention. CREATE DATABASE cannot run in a transaction;
-           plain ExecuteNonQuery is the correct shape. */
-        using var create = new NpgsqlCommand($"CREATE DATABASE {DatabaseName}", connection) { CommandTimeout = ServiceCommandDeadlines.BootstrapConnectProbeSeconds };
-        await create.ExecuteNonQueryAsync(cancellationToken);
     }
 
     /// <summary>

Darling/PerformanceMonitor.Darling.Service/DarlingStoreUpgrade.cs

@@ -2180,7 +2180,7 @@ private async Task<IReadOnlyList<string>> ListConnectableDatabasesAsync(string o
 
     /// <summary>
     /// Retries <paramref name="action"/> on a TRANSPORT fault only (a backend that lost the post-start
-    /// shared-memory race, #2185), the same classification <c>EnsureDatabaseAsync</c> uses. Every caller wraps a
+    /// shared-memory race, #2185), the same classification <c>OpenProbedMaintenanceConnectionAsync</c> uses. Every caller wraps a
     /// connection OPEN in it and nothing else, so what a retry repeats is a connection attempt, never a
     /// statement. Any PostgreSQL error is an answer, not a transient, and propagates at once.
     /// </summary>

Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs

@@ -1385,7 +1385,7 @@ every ordinary start. */
 
             managedPostgres = new DarlingManagedPostgres(config.Postgres, _logger);
             /* #2936: the sharpest of the three sites, because the judgment already existed and was being
-               thrown away. EnsureDatabaseAsync inside this bootstrap classifies transient connection
+               thrown away. OpenProbedMaintenanceConnectionAsync inside this bootstrap classifies transient connection
                faults and retries 6 times 2 s apart — and when that runs out it throws, and this catch
                discarded the fact that the failure had been RULED transient. Re-classifying here is what
                makes that verdict mean something.
@@ -1759,8 +1759,8 @@ stays terminal. This is the LAST of the three startup steps that can kill collec
            spend MigrationLockWaitTimeoutSeconds — so the wall-clock budget is what stops 25 attempts from
            becoming ten hours, and the attempt count is what the warning line reports.
            A FRESH connection per attempt, not a reuse of the old one — its connector is dead after a
-           transport failure, the same reason DarlingManagedPostgres.EnsureDatabaseAsync retries the whole
-           unit rather than just the open. Re-entering MigrateAsync is safe because the applier commits
+           transport failure, the same reason DarlingManagedPostgres.OpenProbedMaintenanceConnectionAsync retries
+           the connect and its first query as one unit rather than just the open. Re-entering MigrateAsync is safe because the applier commits
            each rung's DDL and its darling_schema_version stamp in ONE transaction: a rung that failed
            part-way left nothing applied and nothing stamped, and rungs at or below the stamp are skipped,
            so a retry resumes at the rung that failed instead of redoing the ladder. That rests on the