Self-hosted PostgreSQL log tail: resume from a per-consumer marker so lines written before a rotation are collected

[erikdarlingdata]

Fixes #4699.

Summary

The stderr log tail read only the last 4 MB of the newest file, so a rotation between two reads dropped whatever the old file received after the previous read. pg_log_events now keeps a resume marker per (target, consumer) in collector_state (key log_resume, value <offset>|<file>). The next read finishes the marked file from the offset, then reads the newest one. Gaps are disclosed on the collection-log row.

Design

• One statement, one round trip: listing (materialized, same gates as before) feeds newest, marked, ranges, tail (up to two rows) and resume. The path text || '/' || n.name is unchanged. Text and binary twins are independent literals.

• Offset rule (R1): read from the offset to EOF; a backlog over 4 MB reads the last 4 MB and counts the skipped bytes.

• Next offset (R2): the first line start inside the last 1 MB read; a read of 1 MB or less, or with no newline in that span, keeps the offset. The overlap is deduped at read time by the existing hashes.

• Recycled (file smaller than the offset) and missing (name gone) fall back to the newest file's last 4 MB and are disclosed.

• Skipped files (rotations between two reads) and skipped bytes are counted and disclosed.

• The resume row is the first UNION arm; C# recognises it only when the fill column is NULL and the text has the prefix, so a planted body cannot pass as one.

• Persist order (R3): the runner saves PendingState after the COPY returns. A throw before that keeps the old marker.

• Leftover window: the COPY commits, then the state save fails. The next cycle re-reads and the hashes dedupe it.

• Known limits: a recycled file regrown past the offset within one interval is not detected (size only); the skipped-file count can over-count on mtime ties within a second.

• csvlog and jsonlog: the four csv/json tail twins carry the same params/listing/marked/ranges/tail/resume shape as the stderr twins, differing only in the csvlog/jsonlog destination test and the .csv/.json name filter (each still an independent literal). Their query texts in pg_log_events (both formats), and in deadlocks and plan capture (csv), open with the resume row, and pg_log_events binds and consumes it on every route.

• Per-format keys: log_resume (stderr), log_resume_csv, log_resume_json, chosen by each collector's RouteKey; ResumeStateKeys lists all three. A target that switches log_destination never reads another format's file name as a missing file, so it raises no false "missing" disclosure.

• csv boundary rule: the same "byte after the first newline in the last 1 MB" offset. It is safe because PgServerLogCsvParser never trusts the start of its body: it anchors quote parity at the END of the body and walks backward, treats the head as a fragment when it lies inside quotes, and shape-checks and discards the first segment (its type header, "The tail starts mid-file"). The collectors already start at an arbitrary size - 4 MB byte today. A resume offset that lands inside a quoted field at worst drops the partial first record, which the previous read's overlap already delivered whole. jsonlog is one record per line, so the offset is a record start.

• Pins: PgServerLogTailCsvJsonRotationLiveTests (rotation per format and route, no duplicates in a cycle, one identity across cycles, a stderr marker on a csv/json route gives no "missing" disclosure, the format's own key does) and PgServerLogTailResumeTests (the four twins byte-for-byte against the stderr twins with only the format test and name filter swapped, per-format keys, bound parameters). RED: with the csv/json routes' key changed so the marker is never found, 6 of 8 live pins fail (rotation x4, missing-file disclosure x2).

• Deadlocks and plans (stderr, text and binary routes): each carries the resume row as its first arm and declares StateKeys. ReadAsync recognises the row before its marker checks (log_timezone NULL for deadlocks, line_prefix NULL for plans) and stages the marker on EVERY read, including a read the row cap cut (see "Row cap" below). The csv/json routes of these two collectors consume the resume row under the csv key (log_resume_csv).

• Key rule: each collector has one route-to-key function, RouteKey, used by both BuildQuery and every staging site. Deadlocks and plans return the stderr or csv key only (they never take the json key, even with the jsonlog flag set, which the runner does set for all three collectors); log events keeps json, then csv, then stderr, the same order as its BuildQuery. PgServerLogTail.ResumeStateKeyFor is removed.

Row cap

• The deadlock and plan-capture stderr queries cap their regex matches at 500 and 2,000. Their regex arm now numbers matches WITH ORDINALITY, orders them newest first (ORDER BY tail.part DESC, ord DESC: the newest file, then the latest match) and fetches RowLimit + 1 inside the arm; ReadAsync drops the extra row and, when it was there, records log_matches_limited = 1 with a note. The resume and marker arms never count toward the cap, and next_offset comes from the newest file's range only, so the marker advances on every read and can never stall on a file with more matches than the cap.
• The csv routes have no row cap.
• Known limit: a single read that holds more than 500 deadlock or 2,000 plan matches keeps the newest and records log_matches_limited = 1; the older matches in that read are not collected. (Before this change the cap kept the oldest matches of the newest file, silently.)

CI

• The rotation pins run on dedicated clusters so no other log test sees a surprise rotation: 5546 (stderr, log_line_prefix = '%m [%p] %Q '), 5547 (csvlog) and 5548 (jsonlog), each with logging_collector = on, log_timezone = 'UTC' and log_lock_waits = on, through Start-LogFormatCluster. DARLING_TEST_PG_LOGROTATE, _CSV and _JSON are set on every shard, and the rotation classes share one serial xunit collection (pg-log-rotation). The plan pins load auto_explain per session.
• Live pins (PgLogBurstAndRotationLiveTests, 8 cases): 540 real deadlocks across a rotation, then one in the new file: the marker advances, the cap note is present, 500 rows are kept and the new file's report is collected by the second cycle (RED with the marker held back on a capped read: the new file's report is never collected); a single-file burst keeps the newest and discloses (RED: the marker does not advance); a read under the cap records no note; two rotations in one interval; a plan written before a rotation on stderr and csv is collected with the marker and missed without it; a deadlock before a csv rotation is collected; a csv quoted multi-line record of about 2 MB, which puts the offset inside the quoted field, is collected exactly once across two cycles.
• Existing live tests that executed a log collector's query text now bind its parameters through the product's command builder.

Notes added (verbatim)

• Lost: "The log file this collector had read up to is gone from log_directory, or is now smaller than the offset already read (recycled under the same name), so this read fell back to the newest file's last 4 MB and whatever the old file received after the previous read was not collected (Self-hosted PostgreSQL log tail: events written after the last read and before a log rotation are never collected #4699)"
• Files: "More than one log rotation happened between two reads: this read finished the file the previous read stopped in and read the newest one, and log_files_skipped_by_rotation counts the files between them that no read opened (Self-hosted PostgreSQL log tail: events written after the last read and before a log rotation are never collected #4699)"
• Bytes: "The log grew by more than the 4 MB read window since the previous read, so this read took the last 4 MB and log_bytes_skipped counts the bytes before it that no read covered (Self-hosted PostgreSQL log tail: events written after the last read and before a log rotation are never collected #4699)"

Changes

PgServerLogTail (SQL, resume C#, labels, notes, header), PgLogEventsCollector (resume arm, StateKeys, read), Deadlocks/PlanCapture BuildQuery (bind only), DarlingCollectorRunner.WithLogResumeNotes and one DarlingWorker call. Existing live tests now bind the parameters through LiveTailQuery.

Pins

• Byte pins updated: PgLogEventsPipelineTests, PgServerLogTailBinaryRouteTests; measurement seam list extended.

• New: PgServerLogTailResumeTests (17 unit + source-order pin), PgServerLogTailRotationLiveTests (7 live; they run in CI on a dedicated cluster, see "CI" below).

• REDs (mutate, run, revert): fillColumnIsNull dropped -> TryConsumeResumeRow_LeavesAPlantedBodyAlone fails; part 1 reading nw.name -> rotation live test fails; save moved before the write -> source-order pin fails; missing measurement stubbed -> AMissingMarkedFile live test fails (both routes); (a) cycle 2 with no state finds 0 lines in-test.

• (c) commit order: covered by the source-order pin plus a context-level test (PendingState staged, State unchanged); no runner COPY-fault seam was used.

• Deadlocks/plans pins (PgDeadlocksPlanCaptureResumeTests; PgDeadlocksResumeLiveTests, 2 live, text and binary): a deadlock report written before a rotation is collected with the carried marker and missed without it; a read of exactly RowLimit matches records no cap note and a read of RowLimit + 1 records one, and both stage the marker; the bound key equals the staged key per collector and route with the jsonlog flag set; a planted prefix with a non-null fill column is not consumed. The no-state live cycle finds 0 reports, the carried-state cycle finds 1.

• Lite pins checked: PgPlanCaptureCollectorDefinitionTests.TheLogReadIsBounded asserted greatest(n.size -, now greatest(nw.size - (updated); PgLoggingCollectorGateTests (gate text is still in the shipped SQL, now in the listing CTE that calls pg_ls_logdir()), PgServerLogPathPinTests (|| '/' || n.name kept) and LogTailOverlapThresholdPinTests (reads source for TailBytesLiteral, TailCteSql) hold unchanged. PgLogEventsPipelineTests byte pin and the guarded-cast live proof updated for the new first arm.

• Key-rule pins (PgDeadlocksPlanCaptureResumeTests): the csv route of deadlocks and of plans stages log_resume_csv and never log_resume; log events stages log_resume, log_resume_csv and log_resume_json on their own routes, each alone. RED: with the staging writes hard-coded to ResumeStateKey, 4 of these pins fail; restored, all 15 in the class pass.

Lite

• No behavior change: Lite does not monitor PostgreSQL targets, so these collectors run only in Darling. Lite's tests of the shared collector definitions (the state-declaring set and the log-directory pin) are updated.

CHANGELOG

SECTION: Fixed
ENTRY: - Self-hosted PostgreSQL targets no longer lose the log lines written just before a log rotation ([#4704]) - The log tail keeps a resume marker per target, finishes the previous log file before reading the newest, and says so on the collection log when a file is gone or the log outgrew the read window. When one read holds more deadlock reports or captured plans than the collector's row limit, the newest are now kept, and the collection log says the limit was hit.
REF: [#4704]: #4704