Skip to content

Darling tests: the nightly's PostgreSQL step no longer fails after every test passes - #5546

Merged
erikdarlingdata merged 2 commits into
devfrom
fix/nightly-foreground-thread
Oct 8, 2026
Merged

erikdarlingdata merged 2 commits into
devfrom
fix/nightly-foreground-thread

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Oct 8, 2026 •

Copy link
Copy Markdown
Owner

The nightly build's "Darling PostgreSQL tests" step was failing with exit code 1 after every test had passed, so the nightly was never published (the 2026-10-08 nightly, and two branch runs before it). The cause was that seven live test classes left their scratch databases for a clean-up that runs when the test process exits, and that clean-up had grown slower than the 10 seconds the test runner allows. Those classes now drop their own database when each test ends, and the exit clean-up now drops in parallel and returns within one 6-second deadline, even with a drop still running, so a future leak cannot fail a run.

Refs #5480.

No changelog entry (test infrastructure).

Details

What was observed (CI logs)

  • Failing run 37737551739 (dev 2186662, job "Darling PostgreSQL tests"): Darling.Tests Total: 28763, Errors: 0, Failed: 0, Skipped: 102, Not Run: 1, Time: 2450.661s at 07:18:35.7. Then 29 lines Scratch database ... outlived its test (...); dropped at process exit. between 07:18:36.1 and 07:18:46.9, Waiting 10 seconds for foreground threads to exit... at 07:18:36.7, [FATAL ERROR] Foreground threads were left running, forcing process exit at 07:18:46.7, exit code 1, publish skipped.
  • The same pair is in branch runs 37723838729 and 37728953153 (29 and 29 databases dropped at exit, FATAL line present).
  • Last green dev nightly, 37581130191 (dev 12e435b, 2026-10-07 06:22Z): the same 28 databases dropped at exit, from 07:04:08.2 to 07:04:12.8, which is 4.8 s (about 0.17 s each). No FATAL line.
  • Failing runs: 29 databases in 11.1 to 11.6 s (about 0.39 s each).
  • Not Run: 1 is not the cause. It is in the green runs too (37581130191, 37423416866).
  • The job runs on a Windows runner (D:\a\..., pwsh), not Ubuntu.

Cause (the first two points are observed, the rest follows from them)

  • The "foreground thread" is not a thread of a test. xunit.v3 under Microsoft.Testing.Platform (TestPlatformTestFramework) starts a timer when the run returns: after 1 s it prints "Waiting 10 seconds...", and 10 s later it prints the FATAL line and calls Environment.Exit(1) if the process has not exited. Whatever holds the exit past that point fails the step, whatever the tests did.
  • What held the exit was ScratchPostgres's process-exit drain (DropEverythingRemembered), which drops every scratch database a test did not dispose. Its lines are the ones printed between the summary and the FATAL line.
  • Seven classes (27 test methods) minted a database with ScratchPostgres.CreateAsync and disposed only their connection: RawPurgeTriggerLiveTests, RawPurgeTriggerGateErrorTests, RawPurgeConvergeLiveTests, RawRepairEpochTriggerLiveTests, RawTablesLeaveCatalogSweepLiveTests, RawGatePerSlotSourceFloorLiveTests, RetentionHoldAndCadenceRawRedirectLiveTests. That is the 28 to 29 databases at exit.
  • Between the green run and the failing runs, Four Darling live tests wait for the state they assert #5480 (483bb7d, "Four Darling live tests wait for the state they assert") added QuiesceTimescaleJobsAsync to every drop, including each drop in the exit drain: two extra connections, alter_job on every job, and at least two polls 100 ms apart. That matches the move from about 0.17 s to about 0.39 s per database, which put 29 databases past the 10 s window. I did not reproduce the timing here (no test PostgreSQL), so that last link is inferred from the log timestamps and the diff.
  • The same leak was harmless before Four Darling live tests wait for the state they assert #5480 only because the drain finished inside the window with about 5 s to spare.

What changed

  • RawGatePerSlotSourceFloorLiveTests, RawPurgeConvergeLiveTests, RawPurgeTriggerGateErrorTests, RawPurgeTriggerLiveTests, RawRepairEpochTriggerLiveTests, RawTablesLeaveCatalogSweepLiveTests, RetentionHoldAndCadenceRawRedirectLiveTests: every test's finally now ends with await scratch.DisposeAsync(), and each opener (OpenAsync / OpenTimescaleAsync) wraps its setup so a skip (no TimescaleDB) or a failed setup drops the database and connection before it rethrows. Before, a skip after minting also leaked.
  • ScratchPostgres.cs: the exit drain runs clusters side by side, and up to 16 drops at once within a cluster (ExitDrainParallelism), under one deadline (ExitDrainBudgetSeconds = 6). It returns at the deadline whatever is in flight. The deadline cancels connects and quiesces. A drop already sent is never cancelled, because an interrupted DROP DATABASE can leave an invalid database. Each database it did not finish is named on stderr and counted in ExitDrainOutcome.Unfinished, and is removed by the next run's start-of-run sweep or goes with the throwaway cluster. It keeps the dead-cluster probe (the first database on a cluster goes alone, so a dead cluster costs one connect) and the quiesce before each drop. QuiesceTimescaleJobsAsync takes an optional caller token, linked with its 10 s cap.
  • Why a start-only budget was not enough: a drop already started can still run its quiesce (up to 10 s) and its DROP DATABASE (up to 30 s). On a local rig one DROP DATABASE waited 26 to 30 s for its immediate checkpoint (pg.log: checkpoint complete: ... sync=16.786 s, total=26.405 s).
  • ScratchDatabaseDisposalCensusTests.cs (new, tagged Stage=Guard): scans Darling.Tests/*.cs method by method and fails for a method that mints a scratch database (directly or through a helper or handle type that returns one) and never disposes it, or for a helper that can skip after minting without disposing. Four detector tests pin the scan itself on small samples.
  • ScratchPostgresExitDrainTests.cs: tests for the deadline. A spent deadline attempts no connect and counts every database as unfinished (Unfinished == 3, Skipped == 0; Skipped now means only "its cluster did not answer"). Four hanging clusters finish inside the runner's window. A 1 s deadline returns in about 1 s. The mixed dead and live test gets a long deadline, because it pins the mix, not the deadline.

Evidence for the deadline

Check Base drain (dev) This drain
4 hanging clusters (TCP accepted, no answer, 3 s connect timeout) 12.0 s, RED (past the 11 s window) 3.01 s
1 hanging cluster, 3 databases, 1 s deadline n/a (no deadline) 1.04 s, Unfinished 3
Live rig, 6 to 10 leaked databases n/a returns by the deadline, every database counted

Proof

  • RED: with the seven classes put back to their old text, ScratchDatabaseDisposalCensusTests.NoTestLeavesAScratchDatabaseForTheExitDrain fails and names the 7 openers and 27 test methods in exactly those 7 files, nothing else. With the fix it passes. (The detector was first run over all 281 files that mint a database and flagged other shapes that are correct, such as handle types and await using helpers; the scan now accepts them, and flags nothing else in the tree.)
  • ScratchDatabaseDisposalCensusTests: Total 5, Failed 0 (RED run: Total 5, Failed 1).
  • ScratchPostgresExitDrainTests: Total 6, Failed 0, Skipped 1 (the one that needs a PostgreSQL).
  • Census, ratchet, hygiene, scrub, guard and scratch classes together (*Census*, *Ratchet*, *Hygiene*, *Scrub*, *Guard*, *ScratchPostgres*, *ScratchDatabase*, *RawPurge*, *RawRepair*, *RawTables*, *RawGate*, *RetentionHold*): Total 1038, Failed 0, Skipped 94. The skipped ones are the live tests, which need a test PostgreSQL; none was available on this machine, so the changed live classes did not run here. Build: 0 warnings, 0 errors.
  • Linux/Windows: the runner is Windows, and the drain and runner behaviour above is the same on any OS; no Linux reasoning is needed.
  • Local run against a test PostgreSQL: ScratchPostgresExitDrainTests (9, live ones included), ScratchDatabaseDisposalCensusTests, ScratchPostgresQuiesceCensusTests, LivePostgresCollectionHygieneTests, LiveCleanupConversionRatchetTests, DocCommentHygiene* and RawGatePerSlotSourceFloorLiveTests: Total 124, Failed 0, 0 build warnings.
  • Nightly with both commits, run 37746531776 (publish=false, test_map=false; publish is skipped when publish=false): every job green. Darling PostgreSQL tests: Total: 28773, Errors: 0, Failed: 0, Skipped: 102, Not Run: 1 (the Explicit MCP tool schemas exclude DI services by type, closing a reflection race that leaked them into tools/list (issue-4075) #4110 race test), no FATAL ERROR line. No database was left for the exit drain: the only outlived its test lines are the drain tests' own deliberate cases (20010101 names, "the leak test", "the live test"). The step moved on 6.2 s after the test summary, against 10.3 s on the passing Oct 7 nightly and a FATAL exit on Oct 8.
  • Nightly on the first commit alone (c1eba1e), run 37746048228, for comparison: green.

Not done

  • The seven live classes were not all run locally. The nightly run above is their run.

…in stays short

Seven live test classes (28 tests) minted a scratch database and closed only their connection, so every database waited for the process-exit drain. Since the quiesce step was added to each drop, that drain took about 11 seconds for 29 databases. The test runner forces the process out with exit code 1 ("Foreground threads were left running") 10 seconds after the run returns, so the nightly's Darling PostgreSQL step failed with every test passed and the publish job was skipped.

The seven classes now drop their database in the test's finally, and their openers drop it when a skip or a failed setup throws before the caller owns it. A new census test fails for any test method that mints a scratch database and never disposes it. The exit drain also stops starting new drops after 6 seconds and names the databases it leaves, so a future leak cannot push the exit past the runner's wait.
…in flight

The drain stopped starting drops after 6 seconds, but a drop already started
could still run its quiesce (up to 10 s) and its DROP DATABASE (up to 30 s),
and one DROP DATABASE waited 26 seconds for its immediate checkpoint on a
local rig, so the exit could still pass xUnit's 11-second window.

The drain now runs clusters side by side and up to 16 drops at once under one
deadline, returns when it passes whatever is in flight, cancels connects and
quiesces at the deadline (never a sent drop), and counts what it did not
finish as Unfinished. The one-connect probe of a dead cluster and the quiesce
before each drop are kept.

Tests: four hanging clusters drain in 3.0 s (12.0 s on the old drain, past the
window); a 1-second budget returns in 1.04 s with all three unfinished; a live
leak of six databases returns by the budget and accounts for each.

Refs #5480
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