The log-rotation live test expects every "still waiting" line a lock wait writes, each once, and pins a wait that logs twice

[erikdarlingdata]

What failed

On dev d36306e41 (Build run, attempt 1, a Windows PG shard), PgServerLogTailCsvJsonRotationLiveTests.ARotationBetweenReads_DoesNotLoseTheLinesWrittenBeforeIt(json: True, binary: True) failed with Assert.Equal() Failure: Expected: 1, Actual: 2. The same tree had passed all four PG shards at the PR head, so the failure was intermittent. Nothing was lost; the wait was counted twice.

Why: the test's identity, not the tail

The test identified "its" lock wait as rows with the waiter's pid, occurred at or after a floor, and containing "still waiting", and required exactly one.

PostgreSQL 18 can write more than one such line for ONE wait. In src/backend/storage/lmgr/proc.c (REL_18_STABLE), ProcSleep's wait loop runs if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) on every latch wakeup, and logs process %d still waiting for %s on %s after %ld.%03d ms while the backend is still waiting. After logging, it resets deadlock_state = DS_NO_DEADLOCK, which still passes that test. So every latch wakeup between deadlock_timeout (100 ms here) and the end of the wait writes another line, with a larger "after N ms" and so a different raw_line_hash.

Reproduced deterministically on a local PostgreSQL 18.6 jsonlog cluster configured like the CI cluster:

• The setup: a holder takes a row lock; a waiter blocks on it with lock_timeout = 800ms.
• The poke: about 400 ms in, a third session runs pg_log_backend_memory_contexts(<waiter pid>), which sets the waiter's latch through a procsignal.
• With the poke, 3 of 3 runs logged two lines for the one wait (e.g. after 104.946 ms and after 458.799 ms).
• Without it, 2 of 2 runs logged one line.
• The plain test: looped 192 times per format on Linux without the poke, it never failed, which fits a wakeup that is rare there. On the Windows runner something sets the latch inside the window; I didn't prove what.

The tail itself is not implicated, from reading PgServerLogTail.cs:

• the resumed read covers either the marked file from its offset plus the newest file (two different names), or one file;
• the .log companion is excluded by the \.json$/\.csv$ filter;
• the parser emits one event per record.

What changed (tests only)

• The expected set comes from the files themselves. ExpectedWaitLinesAsync reads each of the route's log files once, from byte 0 (pg_ls_logdir() + pg_read_file), and parses them with the product's own PgServerLogJsonParser / PgServerLogCsvParser. It collects the messages of every entry with the wait's pid, at or after the floor, starting process <pid> still waiting for .

• The resumed read must equal that set exactly:

  • the same messages, each once, with distinct hashes;
  • the expected set non-empty and free of repeats;
  • the read without state still holds 0 matching rows;
  • no raw_line_hash repeats within the cycle;
  • across both cycles, each expected message has exactly one hash.

  Nothing is loosened. A lost line, a duplicated line (the same hash twice) or a stranger line still fails.

• New permanent pin, ALockWaitThatLogsTwice_IsReadAsTwoLinesEachOnce (json/csv × binary/text): it forces the second line with pg_log_backend_memory_contexts 350 ms into the wait, asserts the files hold exactly two lines, and runs the same exact checks.

  • Its third connection is opened before the wait begins. The forced wait uses lock_timeout = 3000ms (the unpoked path keeps 800 ms), so the poke lands inside the wait even on a slow runner.

• Every count check is self-describing on failure (PgLogRotationEvidence). It prints:

  • each matching row (hash, occurred_at, pid, severity, family, message, detail and context, clipped);
  • every row with the wait's pid;
  • the carried and resulting resume state;
  • the target's pg_ls_logdir() listing at failure time.

  A passing run never builds it.

Verification

• RED: the old Count(...) == 1 check in the new pin reported 2 in 4 of 4 variants. GREEN: the new checks pass.
• The class: 12/12 on local jsonlog and csvlog clusters, three runs before and three runs after the poke-timing change.
• Other suites: DocCommentHygieneTests 77/77 and PgLogRotationEvidenceTests 2/2.
• The build: a clean --no-incremental Release build, 0 warnings and 0 errors.
• Not run locally: CI's Windows shards are the real target and run this class.

Findings: 0 substantial, 1 hygiene fixed in this PR (the test identity), 0 polish dropped.

CHANGELOG

None: test-only; the log-rotation live test's identity for a lock wait's "still waiting" lines, and no product code changes.