One line stamped in another zone no longer blinds a UTC target's log events and deadlocks (#4046)

[erikdarlingdata]

Refs #4046.

Part 1 only (availability). Part 2 (read csvlog/jsonlog) keeps the issue open.

Why

PgLogEntryAssembler refused the whole read when any primary line's zone was not a zero-offset one. #4046 showed that %u and %d in log_line_prefix are filled from the startup packet before authentication and written unescaped. So one failed login from anyone who can reach the port can leave a line stamped in another zone in the tail. From then on, every pg_log_events and pg_deadlocks read of that target was refused as "log_timezone is not UTC" for as long as the line stayed in the window, even on a target whose log_timezone is UTC.

What changes

• The setting decides, not the line count. Both pg_read_file log readers (pg_log_events, pg_deadlocks) now read pg_catalog.current_setting('log_timezone') in the same statement that reads the tail (PgServerLogTail.LogTimezoneSql, a second column; the marker arms carry NULL).

• If the setting renders UTC (PgDeadlockLogParser.IsUtcLogTimezoneSetting): a line whose zone fails IsZeroOffsetLogZone cannot be the server's own. The assembler skips it, counts it, and ends the open entry, the way it handles an unrecognised line, so neither it nor the tab lines under it join a genuine entry. The read goes on.

  • The check is a name allowlist of the always-zero-offset zones: UTC, Etc/UTC, UCT, Universal, Zulu, GMT, GMT0, GMT+0, GMT-0, Greenwich, and their Etc/ forms. Case is ignored.
  • It is never "the offset now", because Europe/London writes genuine BST lines all summer.
  • Every allowlisted name renders UTC, GMT or UCT, which IsZeroOffsetLogZone accepts, so a genuine line is never the one skipped.

• Any other setting, or no setting (NULL), refuses exactly as PgDeadlockLogParser captures the log's timezone abbreviation and never reads it — occurred_at assumes UTC no matter what log_timezone says #2993 did. The assembler accepts nothing it didn't before.

• The count is surfaced without a migration. It lands on the run's collection_log row two ways:

  • the measurement foreign_zone_lines_skipped=N;
  • a host note naming log_timezone, %u/%d and A client can spell a pid and label into %u/%d and refuse or forge a target's log read, under any prefix with %u/%d before %p (the RDS default) #4046 (DarlingCollectorRunner.WithForeignZoneLinesNote, applied in the worker right after the raw_line_hash and statement_fingerprint are unkeyed hashes a store reader can use to guess the literals they hide #4004 rotation note).

  A count of zero records nothing, so ordinary rows keep a NULL note.

• Routes that keep today's behavior, because they cannot learn the setting in their own statement: RdsLogEventIngestor and RdsDeadlockIngestor. They get log text from the AWS API and run no SQL against the target. The managed default prefix %t:%r:%u@%d:[%p]: carries %u/%d, so the refusal half is still open on RDS/Aurora. There are two ways to close it; the coordinator needs to pick one:

  • read log_timezone over the target's SQL connection in the RDS runner each cycle (a separate round trip, not the same statement);
  • or part 2's csvlog/jsonlog read.

  I did not file an issue, because A client can spell a pid and label into %u/%d and refuse or forge a target's log read, under any prefix with %u/%d before %p (the RDS default) #4046 stays open for part 2.

• Plan capture was never blocked by this. PgPlanLogParser and PgPlanCaptureCollector match the header without reading the zone, so they never raised the refusal, and they are unchanged. The CHANGELOG entry therefore says log events and deadlocks, not plans.

• Lite runs no PostgreSQL collector. The shared parser tests run in Lite.Tests.

Test plan

• Lite.Tests PgDeadlockLogParserTests:
  • with a UTC setting, another zone's report is skipped, its 3 prefix lines are counted, and the UTC report is stored (foreign_zone_lines_skipped=3);
  • America/New_York, Europe/London and NULL still refuse;
  • an allowlist theory for IsUtcLogTimezoneSetting.
• Darling.Tests PgLogEventsPipelineTests:
  • the log-events collector under UTC reads all 15 fixture events and counts 1;
  • other settings refuse;
  • the note helper puts (#4046) beside foreign_zone_lines_skipped=1, and a quiet run keeps a NULL note;
  • a pin that the worker applies the note.
• New live test AgainstAUtcTarget_TheLogQueriesReadTheSettingWithTheTail_AndStoreWhatTheServerWrote, gated on the new DARLING_TEST_PG_UTC_LOG_TARGET.
  • Run against a second 18.6 cluster on the rig: logging_collector = on, log_timezone = 'UTC', log_line_prefix = '%m %u@%d [%p] '.
  • The production queries returned events=7 deadlocks=0 foreign_zone_lines_skipped=1, with no refusal, and the events went through COPY into the store and were read back.
• Each new test fails on the old behavior (the skip disabled):
  • the Lite and Darling UTC tests fail;
  • the live test throws PgLogTimezoneUnsupportedException ("timestamped 'EST' ... log_timezone is not UTC") on a target whose log_timezone IS UTC.
• Pins updated deliberately:
  • the deadlock SQL pin gets the second column and the NULL marker arms, merged with Log events and deadlocks drop every line under a log_line_prefix with fields between the zone and the pid ('%m %u@%d [%p] '); plan capture accepts that shape since #4016 #4041's new prefix clause;
  • the log-events SQL is now pinned byte for byte;
  • PgDeadlockLogTimezoneTests;
  • the CollectorMeasurementSeamTests label census.
• Both test projects build with 0 warnings.
• Full suites once, after git merge origin/dev, on a freshly created darlingtest: Darling 13,082 total, 0 failed, 36 skipped. Lite 5,206 total, 0 failed.
• The live test does not create the foreign-zone line itself. It asserts only what holds either way: no refusal, the server's own events are stored, and any measurement carries this label. On the rig, the tail already held one such line.

For the coordinator to double-check

• The allowlist boundary. A POSIX spec like UTC0 and always-GMT zones like Africa/Abidjan keep the refusal on purpose.
• A skipped companion line ends the open entry. This assumes a message's lines are written together, which the assembler already relies on for unrecognised lines.
• Lines from before a change to log_timezone (for example America/New_York, then UTC) are now skipped and counted instead of refusing the read. The note says so.
• RDS/Aurora still refuse on such a line (see above).

🤖 Generated with Claude Code

https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv

Round-1 security review (Opus) and the coordinator's disposition

The full report is in the review comment.

• Clean:
  • the zone skip, and "hide, never forge" (the skip flushes the open entry);
  • the allowlist: all 18 names render UTC or GMT on a live server, and the conservative misses keep the refusal;
  • LogTimezoneIsUtc's guards;
  • the note, which is a constant;
  • forgery is no worse than on dev.
• High, pre-existing, not introduced here: moved to A client can spell a pid and label into %u/%d and refuse or forge a target's log read, under any prefix with %u/%d before %p (the RDS default) #4046 part 1c.
  • A failed login whose role name carries a byte that isn't valid UTF-8 (0xFF) puts that byte in the FATAL message, under ANY prefix.
  • pg_read_file returns text, so the whole tail read throws invalid byte sequence before any C# runs. Both collectors are blinded while the byte stays in the window.
  • The fix needs pg_read_binary_file and a lenient client-side decode. The documented target grants cover pg_read_file only, so it needs a capability check and a fallback, and its own PR and review.
  • This PR's claim is scoped to the zone route: the title of the CHANGELOG entry now says "in another time zone" and names the byte route.

[erikdarlingdata]

Security review, round 1 — PR #4049 (#4046 part 1: foreign-zone line no longer refuses a UTC target's log read)

Reviewer: Opus security lane. Scope per brief: availability only; forgery (part 2) reported only where this PR makes it worse. Verified against a real PostgreSQL 18.4 throwaway cluster (logging_collector = on, log_timezone = 'UTC', prefixes %m %u@%d [%p] and default %m [%p]) and the PR's own deterministic tests.

Verdict

The zone-skip logic itself is sound and does exactly what it claims: a non-zero-offset line under a UTC log_timezone is skipped, counted, and ends the open entry, while the same line under any non-UTC setting (or a NULL/marker row) keeps the #2993 refusal. The allowlist is correct, the reader guards are safe, and the note/measurement carry no client text. One High finding: the PR's headline availability claim, that a planted line "no longer refuses every read of the target", is not achieved for a trivially plantable, unauthenticated input that this PR's C# skip never reaches, because the read fails one layer lower, in pg_read_file.

---

HIGH — an invalid-UTF-8 byte in a role name still refuses the WHOLE read, on the exact UTC targets this PR protects, and needs no %u/%d

Location: PerformanceMonitor.Collectors/PgServerLogTail.cs:125 (the tail CTE's pg_catalog.pg_read_file(...)), reached by both PgLogEventsCollector.cs:188 and PgDeadlocksCollector.cs:222.

Threat. Any client that can reach the port (the PR's own adversary model) sends one failed login whose role name contains an invalid UTF-8 byte, e.g. a single 0xFF. PostgreSQL writes the role name into the FATAL message text — FATAL: role "...0xFF..." does not exist — so the invalid byte lands in the stderr log regardless of log_line_prefix (it does NOT depend on %u/%d; it works under the default %m [%p]). The collector's tail CTE reads the file with pg_read_file(...), which returns text and validates the database encoding, so the whole read throws ERROR: invalid byte sequence for encoding "UTF8": 0xff before a single row — and therefore before this PR's LogTimezoneIsUtc/skip code — ever runs. Both the log-events and deadlock collectors are blinded for the whole 4 MB tail window, every cycle, until the poisoned bytes age out; an attacker re-poisons every few minutes for a persistent, unauthenticated DoS. This is the exact "one planted line blinds the target" failure the PR sets out to close, by a route the skip cannot see.

Repro (verified on the rig, production query shape):

• Default prefix %m [%p] (no %u/%d). Trigger a failed login with a role name containing byte 0xFF.
• Log now contains: 2026-09-23 16:06:33.588 UTC [71836] FATAL: role "evil?user" does not exist (raw 0xFF confirmed via od).
• Running the collector's own tail CTE (SELECT ... FROM tail) returns ERROR: invalid byte sequence for encoding "UTF8": 0xff — the whole read, not one line. log_timezone = 'UTC' throughout.

Why this PR should address or scope-down. The change advertises (code + PR body) that a planted line "no longer refuses every read of the target." That is now false for the invalid-byte planted line, which is easier to plant than the newline forgery the PR does handle (no prefix requirement). This exception is also not one of the named non-fatal skips, so it surfaces as a raw collector error each cycle.

Fix (SQL layer, since C# is downstream of the throw): read the tail as bytes and decode leniently. Read pg_read_binary_file(path, off, len) into a C# byte[] and decode with a replacing UTF8Encoding(false, throwOnInvalidBytes:false) (or Encoding.UTF8.GetString with the replacement fallback), so an invalid byte becomes U+FFFD in one line rather than refusing the slab. If that is intended for a later part, scope the PR's "no longer refuses every read" wording to the zone case and file/reference an issue for the residual invalid-byte hole (matching how #3009/#4019 are tracked from the type header).

---

Answers to the six questions

1. Can a planted line still force the refusal / a whole-read failure by another route? Yes — the invalid-UTF-8 route above (HIGH). For the routes the skip DOES reach: a planted primary line with an unclassifiable or malformed zone under a UTC setting is skipped or dropped (no refusal); a malformed stamp fails s_prefixLine and is dropped as a non-prefix line (no refusal); the deadlock DB-side regexp_matches never throws on content. The Builder-ctor throw (PgLogEntryAssembler.cs:329) is unreachable under logTimezoneIsUtc = true because the walk skips a non-zero zone at line 243 first. So among lines the C# sees, no residual refusal — only the SQL-layer decode failure.

2. Can the skip HIDE a real server line/entry? No — "hide, never forge" holds. The skip flushes the open entry (entries.Add(current.Build()); current = null;, PgLogEntryAssembler.cs:247-251) rather than dropping it, and tab-continuations after a skipped line hit current == null and are harmlessly dropped. The one way to hide a genuine entry would be to interleave a planted primary line between a real primary and its DETAIL; PostgreSQL's logging collector reassembles each backend's message atomically (chunk protocol), so a separate FATAL cannot land inside another message. That atomicity is the load-bearing assumption — worth a line in the header, but it holds. %u/%d before %m: the line then starts with client text, ^(?<stamp>\d{4}...) fails, the line is dropped as non-prefix and cannot reach or influence the zone group; the client only ever controls a whole new physical line via a newline (the known forgery), never the zone token of a genuine line.

3. Allowlist soundness (s_utcLogTimezoneSettings, PgDeadlockLogParser.cs:444). Verified all 18 names on a live 18.4: every one renders UTC or GMT as the line's zone token, both accepted by IsZeroOffsetLogZone — so a genuine line under any allowlisted setting is never wrongly skipped, and none of the 18 is ever a non-zero offset (no DST members). current_setting('log_timezone') echoes the set name; the OrdinalIgnoreCase + Trim match handles it. Conservative misses that render UTC but are absent (they keep the old refusal — safe, not a bug): UTC0, posix/UTC, posix/GMT, Factory, and the posix/Etc/* spellings. Fine per the brief; worth listing in the summary only.

4. LogTimezoneIsUtc(reader, ordinal) safety (PgServerLogTail.cs). Safe. reader.FieldCount > ordinal guards a short reader (returns false -> refusal), NULL marker rows return false, and both stderr queries always project log_timezone as column 1 in the SAME statement as the tail (log-events SELECT body, log_timezone FROM tail; deadlocks SELECT m[1], log_timezone FROM tail, regexp_matches). Marker arms carry NULL. Plan capture selects no zone and never calls it. RDS route passes false (keeps refusal) — the known next-PR case.

5. Client-controlled text in the note/measurement? No. ForeignZoneLinesNote is a fixed constant; the measurement is an int count (foreign_zone_lines_skipped, <=40 chars, legal label — confirmed by EveryMeasurementLabelInTheCollectorsIsLegal). An attacker can inflate the count by flooding failed logins, but it only appends a bounded sentence + integer to the host note; no injection.

6. Does anything here make forgery worse than dev? No. A UTC-stamped forged line was already parseable on dev (IsZeroOffsetLogZone("UTC") == true); this PR does not touch that path. Non-UTC forged lines went refuse->skip, and are stored in neither case. The misconfiguration alarm is preserved on genuinely non-UTC targets (IsUtcLogTimezoneSetting false -> old refusal).

---

Clean (checked, sound)

• Zone-skip flush/ends-entry logic and the unreachability of the Builder throw under UTC (PgLogEntryAssembler.cs:243-254, 329).
• Overload delegation keeps the old signatures behavior-identical (Assemble, Classify, FromReport one-arg forms pass logTimezoneIsUtc:false).
• Both production SQL queries: 2-column shape, NULL on both marker arms, log_timezone read in the same statement; pinned exactly by PgLogEventsPipelineTests.
• Reader-index/marker-row/short-reader guards in LogTimezoneIsUtc.
• WithForeignZoneLinesNote gates on Value > 0, merges the host note (not the composed note), applied after the raw_line_hash and statement_fingerprint are unkeyed hashes a store reader can use to guess the literals they hide #4004 rotation note; quiet runs unchanged.
• Allowlist rendering verified live for all 18 names.
• The 6 new deterministic tests pass against the built binary (Total: 6, Failed: 0).

Static + live review; no source edited. Rig removed.