Skip to content

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

Merged
erikdarlingdata merged 4 commits into
devfrom
fix/4352-create-database-deadline
Sep 25, 2026
Merged

erikdarlingdata merged 4 commits into
devfrom
fix/4352-create-database-deadline

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 25, 2026 •

Copy link
Copy Markdown
Owner

Refs #4352.

Leave #4352 open after merge: the stall's root cause is not established; the new diagnostics are meant to capture the next occurrence.

Why

ComposeStoreRolesLiveTests has failed in CI 4 times since 2026-09-23 06:06Z, out of 659 "Darling PG tests (1)" job runs of the class (it hashes to shard 1), always the same way:

No other class fails this way. The failure predates #4280 (2 of 653 runs failed without it, 2 of 6 with it; #4280's start-path additions are no-ops for a fresh cluster, so no mechanism ties it to that PR). All four times, the class runs alone at the end of shard 1, the failing test takes 1:59-2:27, and the next test in the class is slow (19-60s). The stall's root cause is not established: the cluster's own server log lives in the test's temp directory, which the CI failure artifact does not collect.

One mechanism was clear from the code: the old bootstrap retried the connection probe and CREATE DATABASE together on the same 10 s deadline. A CREATE DATABASE that times out is cancelled and rolled back, so every retry re-copies template1 from scratch under the same 10 s window, and a copy slower than 10 s fails all six attempts regardless of the underlying cause.

What changes

Product change (DarlingManagedPostgres.EnsureDatabaseAsync): the store's first-run CREATE DATABASE now runs once, on the connection that already answered the existence probe, under the 60 s ServiceCommandDeadlines.BootstrapSeconds deadline, instead of being retried up to 6 times inside the 10 s connect-probe deadline. The connect-and-probe step (new OpenProbedMaintenanceConnectionAsync) still retries as a unit on the 10 s deadline, since that covers a different, known race (a backend that loses the post-start shared-memory reservation race dies on its first query). This changes field installs: a first-run database create whose template copy takes longer than 10 s but under 60 s can now finish, instead of restarting the copy from zero on every retry and failing outright.

StartupCommandTimeoutTests' member census moves CREATE DATABASE into the bootstrap-deadline group (33 to 34 sites, connect-probe sites 2 to 1) and adds a source pin, TheCreateDatabase_RunsOnce_OutsideTheFirstConnectionRetry, that keeps it out of the retry. Doc comments in ServiceCommandDeadlines.cs, DarlingWorker.cs, StartupFailureTriage.cs, DarlingStoreUpgrade.cs, and StartupFailureTriageTests.cs were updated to match.

Test-only (Darling/Darling.Tests/ComposeStoreRolesLiveTests.cs): BootMigratedAsync now wraps EnsureRunningAsync. On any exception other than OperationCanceledException, it rethrows an InvalidOperationException carrying the cluster's own server log tail: pg_ctl's start log (pg.log, next to the data directory) plus every file under the data directory's log/ folder (logging-collector output), each under a --- <path> --- header, last ~200 lines, read with FileShare.ReadWrite | FileShare.Delete so a missing or locked file adds a one-line note instead of throwing from inside the catch block. This does not change what the tests exercise; it is meant to make the next occurrence of this stall attributable from the CI artifact alone.

Test plan

  • macOS build: dotnet build Darling/Darling.Tests/Darling.Tests.csproj -p:EnableWindowsTargeting=true - 0 errors, 0 warnings.
  • macOS build: dotnet build PerformanceMonitor.sln -m:1 - 0 errors, 0 warnings.
  • Local A/B timing proof against a bloated-template1 docker rig (old code fails at ~10s x 6 retries, new code passes on one 60s-budget create). Attempted and timeboxed to 12 minutes; dropped without numbers. The docker side worked (a timescale/timescaledb:2.30.1-pg18 container with template1 bloated to ~15M rows made a plain CREATE DATABASE take 22s, in the target 15-40s range), but the reflection harness against a ProjectReference to the service project kept losing sibling projects' ref/ assemblies mid-solution build (CS0006) even after full solution and per-project rebuilds; not resolved in the time box.
  • StartupCommandTimeoutTests (Windows-only, CI decides).
  • StartupFailureTriageTests (Windows-only, CI decides).
  • ComposeStoreRolesLiveTests (Windows-only, live-postgres bootstrap, CI decides; the next failure, if any, should now carry a server log tail).
  • Full Windows test suite (CI decides).

CHANGELOG entry

SECTION: Fixed
ENTRY:

For the coordinator

  • The A/B timing proof did not land numbers in the 12-minute box (see Test plan). The bloated-template1 docker approach worked on its own (22s CREATE DATABASE, in range); the blocker was purely build plumbing for the throwaway reflection harness (stale/missing ref/ assemblies across the solution's project graph when building outside the solution context), not anything about the fix itself. If this proof still matters, a lane with more time, or one that runs the harness via dotnet run from inside a project added temporarily to the solution, would likely get past it faster.
  • PR number is filled in as ComposeStoreRolesLiveTests times out on CREATE DATABASE in CI, twice since #4280 #4352 in the CHANGELOG entry link by convention; please correct to the actual PR number if different.

pm-pr lane report (census fix)

CI was red on this head (build, Darling PG tests (1), Darling PostgreSQL tests) for one reason,
confirmed the same test in every failing job's log:

Darling.Tests.StoreSessionTimeZonePinCensusTests.EveryStoreConnectionStringSourcePinsItsSessionTimeZoneToUtc

The census only accepts a DIRECT pin — PinSessionTimeZoneUtc(...) called inline on the same
new NpgsqlConnection(...) line. OpenProbedMaintenanceConnectionAsync's new retry loop called the pin once
into a local (pinned) before the loop and reused that local on every attempt, which the census's own
docs call out as the rejected indirect shape (round-1 review on #4285).

Before:

var builder = new NpgsqlConnectionStringBuilder(connectionString) { Database = "postgres" };
var pinned = DarlingStoreConnection.PinSessionTimeZoneUtc(builder.ConnectionString);
for (var attempt = 1; ; attempt++)
{
    var connection = new NpgsqlConnection(pinned);

After:

var builder = new NpgsqlConnectionStringBuilder(connectionString) { Database = "postgres" };
for (var attempt = 1; ; attempt++)
{
    var connection = new NpgsqlConnection(DarlingStoreConnection.PinSessionTimeZoneUtc(builder.ConnectionString));

No behaviour change: PinSessionTimeZoneUtc is a pure string transform of the same
builder.ConnectionString, now computed once per attempt instead of once before the loop. The retry count,
disposal on every failure path, and the deadlines are untouched.

New head: 8255dbb0 (merge of origin/dev on top of the pin fix; the merge carried no conflicts).

Ran locally (macOS, non-WPF classes only — Darling.Tests targets net10.0-windows with UseWPF, and this
host's runtime has no Microsoft.WindowsDesktop.App, so no test class in this project can execute locally;
this is a source-scan census, not a live-PG test, so it needs no PG rig either):

  • dotnet build Darling/Darling.Tests/Darling.Tests.csproj -p:EnableWindowsTargeting=true — build succeeded, 0 Warning(s), 0 Error(s), both before and after the dev merge.

CI must confirm the census, StartupCommandTimeoutTests, and StorageCommandTimeoutTests all pass at
8255dbb0 — none of that ran locally.

The bootstrap's first-connection retry covered the pg_database probe and
CREATE DATABASE together, both on the 10 s connect-probe deadline. A
CREATE DATABASE that times out is cancelled and rolled back, so each retry
copied template1 from the start under the same deadline, and a copy slower
than 10 s failed all six attempts.

The connect and the probe still retry as one unit on the 10 s deadline
(OpenProbedMaintenanceConnectionAsync). CREATE DATABASE now runs once, on
the probe's own connection, under ServiceCommandDeadlines.BootstrapSeconds.
StartupCommandTimeoutTests' member census moves the create into the
bootstrap group (34 sites, probe 1) and a source pin keeps it out of the
retry.

Checkpoint: not yet built; the boot-failure diagnostics for
ComposeStoreRolesLiveTests follow.
…4352)

BootMigratedAsync now wraps EnsureRunningAsync: any non-cancellation
exception is rethrown with the cluster's own server log tail attached
(pg_ctl's start log plus every file under the data directory's log/
folder, each under a header, last ~200 lines, read tolerantly). The CI
failure artifact for this class does not collect the cluster's temp
directory, so a bare 'connection open timed out' or 'CREATE DATABASE
timed out' message currently gives no way to see what the server was
doing during the stall.
The census (StoreSessionTimeZonePinCensusTests) only accepts a direct
PinSessionTimeZoneUtc call on the same constructor line; the retry loop
was calling it once into a local and reusing that local across
attempts. Move the call inline on the NpgsqlConnection constructor,
called once per attempt with the same connection string. No behaviour
change: PinSessionTimeZoneUtc is a pure string transform.
@erikdarlingdata
erikdarlingdata marked this pull request as ready for review September 25, 2026 23:48
@erikdarlingdata
erikdarlingdata merged commit 23ddb14 into dev Sep 25, 2026
16 of 18 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/4352-create-database-deadline branch September 25, 2026 23:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant