The self-hosted log-events live test drives its own events, so a log rotation cannot hide them

[erikdarlingdata]

Fixes a flake in PgLogEventsLivePostgresTests.TheSelfHostedCollector_ReadsTheTargetsOwnLog_EndToEnd. Test code only. The product gap behind it is #4699 and is not touched here.

Why

The test failed on the LockWait Assert.Contains (PgLogEventsPipelineTests.cs:2821, "Filter not matched in collection") in the job "Darling PG tests (1)" of run 36500483761.

• The test never made its own lock wait. It relied on a workflow step in build.yml (about lines 1088-1129) that runs the workload once, before the tests. That step ran from 23:59:16 to 23:59:33Z.
• PostgreSQL starts a new log file at every log_rotation_age boundary. The default is 1d and log_timezone is UTC, so it rotated at 00:00:00Z.
• The collector reads only the newest file's last 4 MB (PgServerLogTail.TailCteSql: ORDER BY modification DESC LIMIT 1). The lock wait sat in the old file, which the collector never reads.
• Error and Connection still passed in that run because the UTC test that ran just before had written a fresh ERROR and a fresh connection into the new file.
• Polling cannot fix this. After a rotation the event never appears in the file the collector reads. Self-hosted PostgreSQL log tail: events written after the last read and before a log rotation are never collected #4699 is the product side: lines written between the last read and a rotation are never collected.

What changes

All of it is in PgLogEventsLivePostgresTests.

• The test makes its own events after it starts, over Pooling=false connections. That is a caught SELECT 1/0 for the Error family, and a lock wait: one session holds pg_advisory_xact_lock(<random key>) in an open transaction and a second blocks on the same key. Every session is its own backend, so each writes its connection and disconnection lines.
• It waits until pg_locks shows the waiter with granted = false, keeps the lock past deadlock_timeout (read from the target), then releases it. The waiter then writes both lock-wait lines, "still waiting" and "acquired". A failed drive rolls back and never leaves the waiter blocked. That release is a catch that rethrows, not a finally, because LiveCleanupConversionRatchetTests sweeps every finally in a live class for store teardown.
• It then polls the shipped collector query (PgLogEventsCollector.BuildQuery and ReadAsync, not a private query) until each family has a row written by one of this run's backend pids. A row must also be stamped no earlier than the drive began, read from the target's own clock, because the pid alone would match an older backend that had the same pid and Windows recycles pids fast. Rows left by the workflow step or by other tests cannot satisfy the poll.
• If the newest log file (chosen the way TailCteSql chooses it) changes during the poll, the target is driven again, up to 3 drives in all.
• The deadline is deadlock_timeout plus 30 s, counted from the latest drive. On it, Assert.Fail names the missing families, the settings log_lock_waits, deadlock_timeout, log_rotation_age and log_timezone, the driven pids, and the newest log file at the start and now.
• The Error, Connection and LockWait Assert.Contains lines and the UTC Assert.All are unchanged.
• The lock_wait read at the end used a fixed limit of 5. A reused target keeps every run's lines in its log file, and each run adds 2 lock-wait lines ("still waiting" and "acquired"). The tool sets truncated when the window holds more rows than the limit, so "truncated": false would fail from the third run on the same file. The limit is now Math.Max(5, <lock_wait count>). Measured on a reused target over consecutive runs: lock_wait = 2, 4, 6, 8. The test passed at 6 and 8.
• build.yml is untouched. Its workload step is now redundant for this test and harmless.

Test plan

Rig: PostgreSQL with logging_collector = on, log_timezone = 'UTC', log_line_prefix = '%m %u@%d [%p] ', log_lock_waits = on, log_connections = on, log_disconnections = on and deadlock_timeout = 100ms (the same as CI's log-target cluster), plus a separate store.

• Class PgLogEventsLivePostgresTests: 3 of 3 passed, repeatedly (about 1.4 to 1.9 s).
• Rotation, unchanged test. Ran the workload, then SELECT pg_rotate_logfile(), then the class: the test failed with "Assert.Contains() Failure: Filter not matched in collection" at line 2819 (Error). In that run the UTC test had not run first. In the failed CI run it had, which is why only line 2821 failed there.
• Rotation, this change. Same steps: 3 of 3 passed. This test alone, straight after a rotation: passed.
• Planted product breaks, one at a time, each reverted afterwards. Each run below is this one test:
  • Broken lock-wait regex in PgLockWaitEventParser: failed after 30.1 s. "The target's log did not show this run's lock_wait event(s) within 30.1 s of the latest drive (1 drive(s)) ... Target settings: deadlock_timeout=100ms, log_lock_waits=on, log_rotation_age=1d, log_timezone=UTC. Newest log file at the start: ... now: ... The last read returned 31 event(s): checkpoint=2, connection=25, error=4."
  • PgErrorEventParser rejecting every severity: same message naming error. The last read returned checkpoint=2, connection=37, lock_wait=6.
  • Broken shape regex in PgConnectionEventParser: same message naming connection. The last read returned checkpoint=2, error=6, lock_wait=8.
  • OccurredAtUtc re-kinded as Unspecified in PgLogEntryAssembler: the poll passes (the families are there), and the kept Assert.All fails: "80 out of 80 items in the collection did not pass. Expected: Utc, Actual: Unspecified". This one fails on the kept assertion, not on the deadline message.
• Build: 0 warnings, 0 errors.
• Full Darling.Tests suite, once, against a fresh store database and both live targets, after merging origin/dev (already up to date): 16751 tests, 2 failed, 62 skipped.
  • LiveCleanupConversionRatchetTests.NoLiveTestCleansUpOnItsOwnBodysConnection failed on this change's first commit. It sweeps every finally in a live class for store teardown that skips LiveStoreCleanup, and it flagged the finally in the new drive helper, which releases a lock on the target and touches no store state. The release now runs in a catch that rethrows (the success path is unchanged). After the fix that class passes 15 of 15, and PgLogEventsLivePostgresTests passes 3 of 3 on a fresh store database. The full suite was not re-run after this fix.
  • TrendPayloadBudgetLiveTests.EveryDefaultAnswer_StaysNearTheBudget_AndTheLargestAnswerStaysUnderTheCap failed with "get_pg_io_trend over 72h answered a error instead of data ... Exception while reading from stream". It fails the same way when run alone on a freshly created store database (59 s). It reads only the store, and this diff touches one log-events test class. It fails the same way on the same rig with an unmodified origin/dev build, and it passes in dev's CI, so the failure comes from the rig.
• Not run: the CI job itself. Whether a real midnight rotation now passes on the runner is shown only by the rotation reproduction above.

Double-check

• Slack: a row counts as this run's if it is stamped within 1 s before the drive began, because the log truncates milliseconds and the clock read comes just before the first connection.
• A rig started in a non-UTC zone needs log_timezone = 'UTC' on the log target, as before. The UTC test asserts it.

CHANGELOG

None: test-only change.