Four Darling live tests wait for the state they assert

[erikdarlingdata]

Four Darling live tests failed intermittently on CI because they read state before it existed. Each one now waits for the state it asserts. A second change makes the test drops of scratch databases wait for their TimescaleDB jobs first, and makes CI warn when a PostgreSQL worker crashes. Nothing in the product changes. Every assertion each test had is still there.

SECTION: none

Details

Run against a local test PostgreSQL 18.6 with TimescaleDB, timezone UTC, from one worktree. Every class in parts 1 to 4 was run 5 times, all green.

1. QueryStoreTopLiteralEndStraddleLiveTests (QueryStoreTopLiteralEndStraddleLiveTests.cs)

The diagnosis is confirmed: a late statistics flush, not an extra scan. Every read in the test runs on its own unpooled connection. A backend flushes its scan counters in pg_stat_user_tables as it exits. That happens after the client closes the connection. A snapshot taken straight after a read missed that read's scans. The next snapshot saw them (Expected (2,5) Actual (2,6)).

Fix: WideTableScanCountsAsync first calls the new QuiesceScanStatisticsAsync. It waits up to 30 s until no other client backend is left in the scratch database. A backend leaves pg_stat_activity only after its exit flush. Then it runs pg_stat_force_next_flush() on the measuring connection.

Assertions before and after: all kept (positive control afterOpenEnd > beforeOpenEnd, before == after, the row-count checks, the clause 4 premises).

Forced RED of the flake: a scratch backend scans the wide table twice in quick succession, so the second flush is deferred. It exits 3 s later. With the old no-wait snapshot that gives Expected (2,6) Actual (4,6) and Expected (2,5) Actual (4,5). The same injection with the fix passes 3 of 3.

Regression guard still RED: a scratch extra read of the wide table gives Expected (2,6) Actual (3,6) in 2 of 2 runs with the fix in place.

Without the injection the old test passed 15 of 15 on this idle machine, so the flake was not reproduced unforced.

2. PlanSync4512CancellationTests.ParseAsyncCancelledDuringTheWalkThrowsOperationCanceledException

cts.CancelAfter(50) raced a 35,000-statement walk. The test now cancels from ShowPlanParser.OnStatementParsedForTest at statement 3 of 50, like the synchronous sibling. It also asserts the walk stopped at or just past statement 3.

Assertions before: ThrowsAnyAsync<OperationCanceledException>. After: the same, plus highestStatementSeen <= 4.

Forced RED of the flake: the old timer shape on a 50-statement plan (the walk ends before the timer) fails with "No exception was thrown". Regression guard RED: removing every cancellationToken.ThrowIfCancellationRequested() call from ShowPlanParser.cs (scratch, restored) fails the new test, the sync sibling and both pre-cancelled tests.

3. PgServerLogTailRotationLiveTests (PgServerLogTailRotationLiveTests.cs)

The rotation and burst tests asserted Assert.Equal(1, Count(...)). They now go through a new AssertReadOnce(rows, wait). It is the same idea as PgLogBurstAndRotationLiveTests.AssertReadOnce from dc1ae94. The wait's lines must be present and distinct by (timestamp, text). A re-read fails, and PostgreSQL 18's repeated "still waiting" line passes.

A second assertion in ARotationBetweenReads_DoesNotLoseTheLinesWrittenBeforeIt made the same one-line assumption (Assert.Single over the distinct hashes of the wait's lines across both reads). It now requires the lines to be present, and each (timestamp, text) line to have one hash across both reads. Only the forced doubled line found it, because it failed there next.

Other classes that count PG log lines were checked with grep "Assert.Equal(1, Count" over Darling.Tests, and by looking at the "still waiting" users. PgServerLogTailCsvJsonRotationLiveTests already compares against the log files' own lines. PgLogBurstAndRotationLiveTests was fixed in dc1ae94. The pipeline and blocking tests use planted fixtures. No other class needed a change.

Assertions kept: Assert.Equal(0, ...) for the no-state read, unique raw_line_hash within a cycle, bytes-skipped measurement.

Forced RED of the flake: pg_log_backend_memory_contexts(pid) sent to the waiter sets its latch, and PostgreSQL 18 then repeats the line. The old assertion gave Expected 1 Actual 2 in the burst and both rotation theories. With the fix, 3 of 3 runs pass with the same injection. Regression guards RED: duplicating the wait's rows fails the distinct check (Expected 4 Actual 2), and dropping them fails NotEmpty.

4. PgLogEventsCsvlogLiveTests.TheCsvlogRoute_KeepsAPlantedNewlineInsideItsOwnField_AndNeverForgesALine

The old wait only looked for the csv file to grow. It read after the logins were sent, so it missed both entries when they came late. It also returned on the first of the two.

The test now takes a floor (clock_timestamp() on the target) before planting. WaitForBothForgedEventsAsync then reads the log until both of THIS run's FATAL "forged" entries at or after the floor are readable (30 s). The final count uses the same floor, so it counts only this run's two entries and not earlier runs' identical ones.

Assertions kept: fatalCount >= 2, no pid 1, no LOG "forged", no user "fake"/"z", NotEmpty, usesCsvlog. The read body moved into ReadRowsAsync with unchanged logic.

Forced RED of the flake: the old growth wait with the second planted login delayed 3 s gives "expected at least the two forged FATAL events this run planted; got 1". The same delay with the fix passes 2 of 2. Guards RED: a forged pid 1 row fails DoesNotContain, and a floor set in the future fails the count with "got 0".

5. Test drops of scratch databases wait for their TimescaleDB jobs first

Why: in two CI runs (09-26 and 10-03) a TimescaleDB job worker died with 0xC0000005, an access violation on Windows. Both runs still read "success", because PostgreSQL restarts itself and the tests retry. Both crashes happened while a scratch database was being dropped WITH (FORCE). A test installs the product's TimescaleDB policies, and those jobs fire as soon as they are created. So a worker is often mid-run when the test's cleanup drops the database, and FORCE ends it with a kill signal.

No stack trace exists, and a local run did not reproduce the crash. So this part removes the kill from the tests. It does not claim a proven root cause. The product never drops a database, so only the test harness is known to hit this.

What changes:

• New ScratchPostgres.QuiesceTimescaleJobsAsync(adminConnectionString, databaseName) in ScratchPostgres.cs. It connects to the scratch database, and if the TimescaleDB job catalog exists it unschedules every job (alter_job(job_id, scheduled => false)). Then it polls pg_stat_activity every 100 ms. It stops when two polls in a row show no job worker left in that database. Job workers show as, for example, "Retention Policy [1038]". The whole helper is capped at 10 s.
• It is best-effort. It never throws and never fails a test. It never skips the drop, so every existing WITH (FORCE), retry, cleanup step, and the exit drain stay as they were. A database without the extension, one that is already gone, or one on a cluster that does not answer returns without throwing, inside the cap.
• It does not call _timescaledb_functions.stop_background_workers(), because that sends the same kill signal to running jobs.
• Called before every WITH (FORCE) drop in the test project: ScratchPostgres.DropAsync and the process-exit drain (ScratchPostgres.cs), MigrationUpgradeLadderLiveTests, RollupFloorCacheLiveTests, ScratchDatabaseSweepLiveTests (two sites), PgReadBinaryFileCapabilityLiveTests and PostgresDatabaseListScreenLivePostgresTests. The last two helpers now take the connection string so they can reach the database.
• A census test (ScratchPostgresQuiesceCensusTests) requires that every DROP DATABASE ... WITH (FORCE) string literal in Darling.Tests has the helper call within the 12 lines above it. The scan also checks that it found at least 7 sites, so an empty match cannot pass.
• build.yml (every shard) and nightly.yml get a step "Warn if a PostgreSQL worker crashed". It runs if: always(), before the step that stops the server. It looks in darling-pg.log for terminated by exception and raises a ::warning for the first five lines. It always exits 0, so it never fails a job. A pin test (TheWorkflow_WarnsOnAWorkerCrashInThePostgresLog_AlwaysAndOnlyAsAWarning) checks both files.

How it was seen RED:

• Census: removing the helper call in RollupFloorCacheLiveTests (scratch, restored) fails with "These WITH (FORCE) drops are not preceded by ScratchPostgres.QuiesceTimescaleJobsAsync ... RollupFloorCacheLiveTests.cs:470".
• Live helper: replacing the unschedule statement with SELECT 1 (scratch, restored) fails the live test with Expected: 0 Actual: 2 scheduled jobs left.
• The live helper test installs the product policies with TimescaleSupport.ConvertToHypertablesAsync and makes every job due now. It then runs the helper and asserts no scheduled job and no job worker in the database.

Test results

Parts 1 to 4 (5 runs each, all green):

Class	Total per run	Failed
QueryStoreTopLiteralEndStraddleLiveTests	1	0
PlanSync4512CancellationTests	8	0
PgServerLogTailRotationLiveTests	7	0
PgLogBurstAndRotationLiveTests (not changed, same log lines)	8 (3 skipped: no csv/json targets)	0
PgLogEventsCsvlogLiveTests	1	0

Part 5, one run on the local test PostgreSQL:

• ScratchPostgresQuiesceLiveTests and ScratchPostgresQuiesceCensusTests: Total 7 together, Failed 0 (3 live, 2 census, 2 workflow pin).
• Drop-site and helper classes: Total 33, Failed 0, Skipped 0. They are the classes whose drop sites changed (MigrationUpgradeLadderLiveTests, PgReadBinaryFileCapabilityLiveTests, PostgresDatabaseListScreenLivePostgresTests, RollupFloorCacheLiveTests, ScratchDatabaseSweepLiveTests). Also ScratchPostgresExitDrainTests and the Quiesce classes. Also three classes that use ScratchPostgres: DurationTrendDatabaseFilterHourlyLiveTests, AnomalyObjectStatsLatestSnapshotsLiveTests and BlockingWaitsWebDispatchLiveTests.
• Wildcards in Darling.Tests, one run each (Total / Failed): *Census* 444 / 0, *Ratchet* 15 / 0, *Hygiene* 90 / 0, *Scrub* 120 / 0, *Guard* 244 / 0.
• *CiCluster* and *CiShard*: 12 / 0, 1 skipped (a live check that did not apply to this local server).
• Build: 0 warnings, 0 errors.

Not run: the full Darling and Lite suites (CI runs them). The rotation tests were not run on a separate csv/json cluster. The local server is one cluster, reconfigured between stderr and csvlog, not CI's several. The CI warning step ran only as a pasted PowerShell snippet against a fake log, not on a runner. TimescaleDB 2.30.2 (a newer release than the pinned 2.30.1) is a separate runtime-currency item and is not changed here.

• The census in ScratchPostgresQuiesceTests.cs now blanks comments with CSharpSourceWalker instead of skipping lines that start with //, /* or *, so the file no longer needs an entry in CommentFilterAdoptionTests. CommentFilterAdoptionTests failed 1 of 4 before this change (collections differ at index 8) and is Total 4 / Failed 0 after. ScratchPostgresQuiesce* Total 7 / Failed 0 (3 skipped, live); the Census, Ratchet, Hygiene, Scrub and Guard totals below were re-run after it, all Failed 0.