Skip to content

Wire the csvlog parser into pg_log_events on the self-hosted route (#4053 part a1b) - #4124

Merged
erikdarlingdata merged 8 commits into
devfrom
fix/4053-csvlog-wiring
Sep 24, 2026
Merged

erikdarlingdata merged 8 commits into
devfrom
fix/4053-csvlog-wiring

Conversation

@erikdarlingdata

@erikdarlingdata erikdarlingdata commented Sep 24, 2026 •

Copy link
Copy Markdown
Owner

Part of #4053.

What changed

When a self-hosted PostgreSQL target's log_destination includes csvlog, pg_log_events now reads the
newest .csv file and parses it with PgServerLogCsvParser.Parse (#4104), instead of the stderr tail. This
closes the forged-line hole for pg_log_events on such targets: under csvlog every field is RFC 4180
quoted, so a failed login can no longer plant a newline through %u/%d and forge a whole extra log line.

Deadlocks and plan capture (part b) and the RDS route (part c) are untouched. jsonlog (part a2) is another
lane in flight and is not referenced here.

  1. PgServerLogTail.cs: new TailCsvCteSql/TailCsvCteBinarySql constants, twins of TailCteSql/
    TailCteBinarySql that select the newest name ~* '\.csv$' file and require 'csvlog' = ANY(...)
    instead of 'stderr'. TailCteSql/TailCteBinarySql are untouched (verified by the existing byte pin,
    TheTailerExtraction_LeftBothSiblingsSqlByteIdentical, which still passes unmodified).
  2. CollectorContext.PgLogUsesCsvlog: a new settable bool, mirroring PgReadBinaryFileGranted's shape.
  3. PgLogFormatCapability (new file): an hourly-cached probe of log_destination, following
    PgReadBinaryFileCapability's cache shape. DarlingCollectorRunner.ResolvePgReadBinaryFileGrantAsync
    now also sets context.PgLogUsesCsvlog for pg_log_events alone, on the same connection, before
    BuildQuery runs.
  4. PgLogEventsCollector: BuildQuery picks a new csv statement pair (CsvQueryText/CsvBinaryQueryText,
    built on the new CTEs) over the existing stderr pair when the flag is set; QueryText/BinaryQueryText
    are unchanged. ReadAsync's csv branch decodes the body the same way the stderr route does (text, or
    PgBinaryTailText.DecodeWhole on the binary route), parses with PgServerLogCsvParser.Parse, applies the
    same foreign-zone filter the stderr path applies via PgLogEntryAssembler.Assemble(..., logTimezoneIsUtc, out foreignZoneLines) — factored into a private FilterForeignZoneEntries helper since the csv parser
    returns PgLogEntry records directly rather than text lines — then classifies the kept entries. A new
    csv_records_discarded measurement is reported via context.Measure only when > 0, added to
    CollectorMeasurementSeamTests's label census.
  5. PgNoCsvlogFileException (new file): the csvlog route's own "logging_collector is on, csvlog is
    configured, but no .csv file has appeared yet" named skip — kept distinct from
    PgNoStderrLogFileException so the fault message never tells an operator to add stderr to a target
    that already has csvlog working. DarlingWorker gets its own catch arm, same PERMISSIONS
    disposition as its siblings, elapsed time in sqlMs.
  6. PgNoStderrLogFileException's message now says pg_log_events reads csvlog directly (Postgres log readers: read csvlog/jsonlog when a target writes them, so a client can't forge a line through %u/%d (#4046 part 2) #4053) and that
    this particular refusal is deadlocks'/plan captures' only — not a claim that nothing is being read from
    this target's log.

Tests

Unit (Darling.Tests.PgLogEventsPipelineTests):

  • WhenPgLogUsesCsvlog_TheStatementOpensWithTheCsvCte_AndTheStderrPairIsUntouched — the stderr pair is
    byte-unchanged when the flag is false; the csv pair opens with the csv CTE and its own marker.
  • ThePgLogFormatCapabilityProbe_UsesOnlyPostgreSql14PlusFunctions — pins the probe SQL text.
  • ReadAsync_OverTheCsvRoute_KeepsAForgedNewlineInsideOneUserField — a failed login's forged
    \n<fake stderr line> inside a quoted user_name field produces exactly one event, with the forged text
    inside the user field, and no row carries the forged line's pid.
  • ReadAsync_OverTheCsvRoute_ThrowsTheCsvNamedSkip_OnItsOwnMarker — the csv route throws
    PgNoCsvlogFileException on its own marker, PgLoggingCollectorOffException on the shared one, never
    PgNoStderrLogFileException.
  • ReadAsync_OverTheCsvRoute_MeasuresDiscardedRecords — a body with no complete record measures
    csv_records_discarded=1.

Ran: PgLogEventsPipelineTests, PgServerLogCsvParserTests, CollectorMeasurementSeamTests,
PostgresFaultOutcomeTests together — 190 passed, 0 failed. Both PerformanceMonitor.Collectors and
PerformanceMonitor.Darling.Service build clean (0 warnings) with -p:EnableWindowsTargeting=true.

What I did NOT verify

  • The full Darling suite was not run (time budget) — only the four named classes above, plus the two
    build checks. The brief's stated baseline on this Mac is 214 pre-existing Windows-only failures; I did
    not confirm that count against this branch. No other test class references PgLogUsesCsvlog,
    PgLogFormatCapability, PgNoCsvlogFileException, or the new PgServerLogTail constants, so a
    regression outside the four run classes is unlikely but unconfirmed.
  • The live test class the brief asks for (DARLING_TEST_PG_CSVLOG, container lane4053a1b-pg, port
    55893, raw StartupMessage forged-username repro) was not written.
    This is the biggest gap against the
    brief: the unit test above proves the same forged-newline claim over FakeReader and the parser directly
    (mirroring PgServerLogCsvParserTests's own fixture), but nothing here proves the wiring against a real
    pg_read_file/pg_ls_logdir round trip on a live csvlog-configured server, or that PostgreSQL's own
    syslogger writes a .csv file the new CTE actually finds. This is exactly the kind of gap the brief warns
    about ("a live proof runs the product's own SQL... never a hand-copied version") and I am flagging it
    rather than claiming it's covered. Recommend the coordinator treat this as a follow-up before arming, or
    route it back to this lane if time allows.
  • No live grant/encoding interaction was tested for the csv+binary-route combination
    (CsvBinaryQueryText) beyond the SQL-text assertion in
    WhenPgLogUsesCsvlog_TheStatementOpensWithTheCsvCte_AndTheStderrPairIsUntouched.

CHANGELOG entry

Live proof

Added Darling/Darling.Tests/PgLogEventsCsvlogLiveTests.cs, gated on DARLING_TEST_PG_CSVLOG, no product code touched.

Rig: docker run -d --name lane4053live-pg -e POSTGRES_PASSWORD=x -e POSTGRES_HOST_AUTH_METHOD=trust -p 55894:5432 timescale/timescaledb:2.28.1-pg18 -c logging_collector=on -c log_destination=csvlog, then CREATE ROLE darling LOGIN SUPERUSER PASSWORD 'x'. POSTGRES_HOST_AUTH_METHOD=trust was needed beyond the brief's rig command: the image's default remote pg_hba.conf line is scram-sha-256, and a forged StartupMessage with no client library behind it never completes SASL, so the login just hangs instead of failing fast with a FATAL. Trust auth makes the "no such role" FATAL land immediately, which is what the test needs on the wire.

Planted: two raw StartupMessages sent over a bare TcpClient (length | protocol 196608 | user\0<name>\0database\0postgres\0\0), each naming a nonexistent role so PostgreSQL refuses it with a FATAL:

  • a user name that is itself a fake CSV record (x\n2026-09-24 00:00:00.0 UTC,"forged","z",1,"a",1.1,0,"x",...) — trimmed to fit PostgreSQL's 63-byte role-name limit (NAMEDATALEN − 1); the first version of this test used a longer forged record and it was silently truncated at the wire before ever reaching the log, so the marker text has to survive that cut too, not just the parser's.
  • a user name that is a fake stderr-format line (y\n2026-09-24 00:00:00.000 UTC [1] LOG: forged).

Read: PgLogFormatCapability.IsCsvlogEnabledAsync confirms the rig reports csvlog; then PgLogEventsCollector.Instance.BuildQuery(context) with context.PgLogUsesCsvlog = true, run as a theory over both PgReadBinaryFileGranted = false and true, executed on the real connection, ReadAsync over the real reader — never a hand-copied restatement of the query or the parser.

Asserted: both planted newlines land inside the FATAL auth-failure events' own message text (fatalCount >= 2 carrying "forged"), never as a separate line of their own: no event at pid 1, no LOG event with message literally "forged", no user "fake" or "z" (the embedded record's own fields). Confirmed on the box against the real .csv file: grep on the raw log file shows the embedded record and the embedded stderr-shaped line both sit as one multi-line, comma-containing FIELD inside the surrounding real FATAL record — exactly the RFC 4180 quoting the #4053 part a1 doc comment describes, and exactly why this couldn't have been forged into a second row.

Ran:

  • PgLogEventsCsvlogLiveTests alone: Total: 1, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0
  • PgLogEventsPipelineTests, PgLogEventsLivePostgresTests, PgPlanCaptureGuardedCastLiveTests, LiveCleanupConversionRatchetTests together: Total: 75, Errors: 0, Failed: 0, Skipped: 2, Not Run: 0
  • Full Darling suite once, both DARLING_TEST_PG and DARLING_TEST_PG_CSVLOG set: Total: 13397, Errors: 0, Failed: 220, Skipped: 120, Not Run: 1

Not verified: the brief names "214 Windows-only failures" as this Mac's known baseline for dev; this run shows 220 failing, and none of them are in PgLogEventsCsvlogLiveTests or any other csvlog/#4053 test (checked by grepping the full run log for csvlog and [FAIL] together — no hits). I did not diff the other ~6 failing test names against a pinned baseline list, because none is named in the brief and I don't have one to diff against; I did confirm this new class is not among them and that adding it changed nothing else. If the coordinator has the exact 214-name baseline, a diff against it would close this out; otherwise treat the ~6-failure delta as pre-existing drift unrelated to this change, not evidence against it.

Container lane4053live-pg removed after the run.

Round-1 review fixes

Finding Fix Commit
H1 — non-UTC target read as quiet, not refused PgServerLogCsvParser.TryParseLogTime / PgServerLogJsonParser.TryParseTimestamp no longer reject a non-zero-offset zone; the shape check decides only "is this a record." The zone judgment moves entirely to PgLogEventsCollector.FilterForeignZoneEntries, which already had the stderr-parity throw/skip logic — it was just never reached. New tests: a csv parser test that a non-UTC record is returned with its ZoneText; a matching json parser test (json wiring is a later lane); two pipeline tests over the csv route's FakeReader — non-UTC log_timezone throws PgLogTimezoneUnsupportedException, UTC skips and counts in foreign_zone_lines_skipped. 556c8c683
M1 + M2 — first-validating anchor let a forged look-alike win; 64-try cost PgServerLogCsvParser.FindBoundaries: when the body ends on a newline, the anchor is unambiguous and unchanged. When it doesn't, up to 8 trailing candidate anchors are each walked backward and scored by how many of their bounded records parse; the highest-scoring candidate wins, latest anchor breaking a tie. A forged, unquoted look-alike line under inverted parity yields at most a couple of planted records, while true parity yields nearly all of them, so the score gap is wide. Cap lowered from 64 tries to 8, since a real mid-write resync is normally found within a handful of embedded newlines; the full walk only ever ran on H1's non-UTC case or a body with no parseable record. New test: a body cut mid-write inside a multi-line quoted field, ten real records ahead of two planted look-alikes — the real records dominate and no fake message text is ever emitted. 81a8fabc0
M3 — a DBCS lead byte could eat a quote, not just a newline PgBinaryTailText.SplitAndDecode already split on 0x0A before decoding so a lead byte in EUC-JP/EUC-KR/GBK couldn't consume a newline; extended to split on 0x22 ('"') too, re-emitting each delimiter byte literally between decoded segments. Neither byte is ever a trail byte in those encodings, so valid text decodes identically either way; this only matters on the binary route under a DBCS server_encoding. New [Theory] tests (EUC_JP/EUC_CN/EUC_KR) mirroring the existing before-newline tests, for a lead byte before a quote, on both DecodeWhole and UnescapeAndDecode. 4b72f678c
L1 — format cache not invalidated on either "no file" marker Added PgLogFormatCapability.Invalidate(targetKey), mirroring PgReadBinaryFileCapability.Invalidate exactly. Called from DarlingWorker's PgNoStderrLogFileException and PgNoCsvlogFileException catch blocks — the two pg_log_events exception handlers this lane's brief scoped me to; I did not touch anything else in DarlingWorker.cs (the web host and the rest of DarlingWorker's purge belong to issue-4130's lane). New PgLogFormatCapabilityTests.cs: Invalidate drops only the named target's cached verdict (a second target's cache survives), and the next IsCsvlogEnabledAsync call re-probes and picks up the current setting. e3025ae70
L2 — one duplicate batch on a stderr→csvlog switch No code change. Switching a target's log route changes RawText, so raw_line_hash changes with it. Events inside the overlap window when a target switches from stderr to csvlog are stored twice, once under each hash. This is a one-time duplicate on the switch, not a fault — no dedup logic is warranted for it. (this comment)

What I ran

  • dotnet build for PerformanceMonitor.Collectors, PerformanceMonitor.Darling.Service, and Darling.Tests (-p:EnableWindowsTargeting=true): all green, 0 warnings, 0 errors.
  • Targeted classes (PgServerLogCsvParserTests, PgServerLogJsonParserTests, PgBinaryTailTextTests, PgLogEventsPipelineTests, PgReadBinaryFileCapabilityTests, CollectorMeasurementSeamTests, CollectionLogDrainForensicsStoreTests, PgLogFormatCapabilityTests): 184/184 passed.
  • Full Darling.Tests suite once, DARLING_TEST_PG unset: 13418 total, 214 failed, 716 skipped, 1 not run. The 214 failures are all in Windows-only/WPF classes that fail on this Mac rig independent of this PR (AgTopologyCardsTests, DarlingInstallLocationTests, DarlingStoreUpgradeTests, ViewerDrillDownTests, TargetProviderTests, live-Postgres classes needing DARLING_TEST_PG, etc.) — none of the touched-area classes (csv/json parser, binary tail text, log events pipeline, either capability cache) appear in the failure list.
  • scrubcheck on every diff before each push: 0 hits each time.

Not verified

  • No live PostgreSQL container was started for this lane — all new coverage is unit-level over hand-built fixtures and FakeReader/FakeScalarConnection, consistent with the rest of these test classes. The existing live-fixture tests (Pg14/Pg18 captures) were left untouched.
  • I did not re-verify the design review's Info section (the six questions) — the brief said the review is settled; I only executed the numbered fix list.

Part of #4053

PR tender verification

Starting head e3025ae70a18d0208bf4729898a53573ec933db5. The branch merged cleanly with dev at verification time. No dev merge was needed.

  1. Log forging: pass. PgServerLogCsvParser.FindBoundaries/ComputeMarks (PerformanceMonitor.Collectors/PgServerLogCsvParser.cs:195-210) walk backward from a newline anchor and track quote parity. A newline inside a quoted field (c == '\n' && !inQuotes, line 206) is never a record boundary. That gives one CSV record per event, never one line. A truncated final record, where the body does not end in \n, is scored across up to 8 trailing candidate anchors (MaxAnchorCandidates, line 130). The text after the winning anchor is never sliced into boundaries, so it is held back rather than emitted half-parsed. PgServerLogCsvParserTests.TrailingPartialRecordIsNotEmitted pins this. The red-watch below breaks the quote guard and 6 tests fail, so the guard is proven load-bearing, not just documented.
  2. Bounded reads: pass. Every tail CTE, stderr and csvlog, text and binary, reads greatest(n.size - TailBytesLiteral, 0) as OFFSET and TailBytesLiteral, a compile-time 4 MiB constant, as LENGTH (PerformanceMonitor.Collectors/PgServerLogTail.cs:125-209). There is no row cap anywhere in the read path. The byte bound is what limits memory.
  3. Time: pass. TryParseLogTime (PgServerLogCsvParser.cs:335-354) parses only the stamp and no longer consults the zone for UTC-ness, per the H1 review fix already on this branch. PgLogEventsCollector.FilterForeignZoneEntries decides that afterward, through PgDeadlockLogParser.IsZeroOffsetLogZone. That check is an explicit allowlist (UTC, GMT, UCT, plus a numeric-zero-offset shape), never a live timezone-database lookup. An ambiguous or unknown abbreviation such as EDT is not zero-offset. Such a record is either dropped and counted, when the target's own log_timezone renders UTC, or it refuses the whole batch with PgLogTimezoneUnsupportedException. It is never silently reinterpreted as UTC. PgLogEntry.OccurredAtUtc is a DateTime, which holds the millisecond precision csvlog's own log_time renders. csvlog itself carries no finer precision to lose. The store-write path is unchanged shared code, outside this diff.
  4. Locale: partial, pre-existing, not a regression. The gate that separates ERROR-tier events from LOG-tier noise uses entry.Severity (PgLogFamilyParsers.cs:44, RankOf(entry.Severity) < RankOf("WARNING")). Correction from the PR tender: that holds for jsonlog, not csvlog. csvlog writes error_severity translated (_(error_severity(edata->elevel)), line 162 of PostgreSQL's csvlog.c). Under a German catalog the gate sees FEHLER, not ERROR. The message_locale facet from Four parsers read a customer target's log in English, and for pg_deadlocks a locale-blinded read is indistinguishable from a quiet server #3061 already names a translated catalog as an unmet precondition. But the LOG-tier sub-families (connection/disconnection, lock-wait, temp-file, autovacuum, and checkpoint/restartpoint, at PgLogFamilyParsers.cs:93,144,195,393) all gate on s_shape.IsMatch(entry.Message), an English-text regex. PgLogEventClassifier.Classify drops any entry no parser claims. On a non-English lc_messages server, those five families' events are absent from pg_log_events output entirely. They are not misclassified. This is pre-existing in PgLogFamilyParsers.cs, a file this PR does not touch. The csvlog wiring reuses the same classifier the stderr route already used, so it inherits the limitation rather than introducing it. Reporting this per the brief, not fixing it: it is a cross-cutting, design-level concern in shared code, not a 30-minute in-lane fix.
  5. SQL: pass. The only new CommandText assignment (PgLogFormatCapability.cs) is a fixed constant, ProbeSql, with no interpolation. Every path, offset and length in the tail CTEs is either a compile-time literal (TailBytesLiteral) or built entirely inside SQL from catalog functions (current_setting('log_directory'), pg_ls_logdir()). None is C#-interpolated from caller- or attacker-influenced data.
  6. Format cache and fallbacks: pass. When PgLogUsesCsvlog is false, whether csvlog is off or the cache is stale, the existing stderr QueryText/BinaryQueryText path is unchanged. A missing .csv file throws the new PgNoCsvlogFileException, which carries its own marker and message naming csvlog, never stderr. Both no-file catch arms invalidate PgLogFormatCapability's cache (DarlingWorker.cs:9850 and :9876, the L1 review fix), so the next cycle re-probes rather than waiting out the hour. Both fallbacks record a PERMISSIONS status with ex.Message explaining what happened.
  7. Tests: pass. Build: Build succeeded, 0 Warning(s), 0 Error(s). I ran all 9 classes this PR adds or touches: PgServerLogCsvParserTests, PgServerLogJsonParserTests, PgBinaryTailTextTests, PgLogFormatCapabilityTests, PgReadBinaryFileCapabilityTests, PgLogEventsPipelineTests (only that one class from its 4-class file, confirmed by the diff's single hunk location), CollectorMeasurementSeamTests, CollectionLogDrainForensicsStoreTests, plus the gated live class PgLogEventsCsvlogLiveTests. Result: 184 passed, 1 skipped (no local rig, as instructed), 0 failed. Red-watch: I reverted ComputeMarks's quote guard at line 206 from c == '\n' && !inQuotes to c == '\n', simulating naive line-splitting. 6 tests failed immediately, including ForgedNewlineInQuotedUserNameStaysInOneEntry, MultiLineQuotedMessageIsOneRecord and ReadAsync_OverTheCsvRoute_KeepsAForgedNewlineInsideOneUserField. This confirms the suite exercises the record-vs-line invariant. I restored the guard, rebuilt, and the suite went green again: 69/69 across the two classes exercised. No new test was needed.
  8. CI: pass on every required check. gh pr checks 4124: build pass, Darling PostgreSQL tests pass, Lite tests (result) pass, all three Darling PG tests shards pass, Darling Linux build pass, Darling whole-tree guards pass, all four Lite tests shards pass, check-branches pass, description-drift pass. Only review (Claude Auto Review) fails. That is expected and ignored per the brief. No Lite budget test sometimes sees get_alert_history's dataService parameter in a full run #4075 pin flake appeared.
  9. Changelog: done. 4124-reported.txt did not exist. I wrote it (SECTION: Fixed) and ran the plain-English checker: 1 hit remains, the standard **bold** ([#N]) - text dash every existing entry in the buffer also carries. Left as-is.

Fixes made: none. No defect turned up that needed a code change. This PR already carries one full review round's fixes: H1, M1+M2, M3 and L1, commits 556c8c68, 81a8fabc, 4b72f678 and e3025ae7. Every one of them checks out correct under this independent re-verification.

Head sha left: e3025ae70a18d0208bf4729898a53573ec933db5, unchanged, since no commits were made.

…4053 part a1b)

When a self-hosted target's log_destination includes csvlog, pg_log_events now reads the newest .csv file
through new PgServerLogTail.TailCsvCteSql/TailCsvCteBinarySql CTEs and parses it with
PgServerLogCsvParser.Parse, instead of the stderr tail. Deadlocks and plan capture are untouched (part b);
the RDS route is untouched (part c); jsonlog is another lane (part a2).

- CollectorContext.PgLogUsesCsvlog, set once per cycle by DarlingCollectorRunner through the new
  PgLogFormatCapability (an hourly-cached probe of log_destination, following PgReadBinaryFileCapability's
  shape) for pg_log_events alone.
- PgLogEventsCollector.BuildQuery picks the csv pair (CsvQueryText/CsvBinaryQueryText) over the stderr pair
  when the flag is set; ReadAsync parses the csv body, applies the same foreign-zone rule the stderr path
  applies, classifies the kept entries, and measures csv_records_discarded when > 0.
- A new PgNoCsvlogFileException for "logging_collector is on, csvlog is configured, but no .csv file has
  appeared yet" -- distinct from PgNoStderrLogFileException so the fault message never names the wrong
  setting. DarlingWorker gets its own catch arm, same PERMISSIONS disposition as its siblings.
- PgNoStderrLogFileException's message now says pg_log_events reads csvlog directly (#4053) and the
  refusal is deadlocks'/plan captures' only.
PgLogEventsCsvlogLiveTests: plants a forged csvlog record and a forged
stderr line through raw StartupMessages, gated on DARLING_TEST_PG_CSVLOG,
and reads them back through PgLogFormatCapability + PgLogEventsCollector's
own query and ReadAsync, on both the text and binary routes.

Part of #4053
@erikdarlingdata

Copy link
Copy Markdown
Owner Author

Code review round 1 (automated reviewer): #4124

Verdict: changes requested. One High finding: the csv branch's foreign-zone filter can never fire, so a non-UTC server goes quiet with no warning. One Medium: an anchor-selection weakness that lets a forged record through in the mid-write case. The routing, the probe and the stderr collectors are sound.

High

H1. The csv route reads a non-UTC log_timezone target as quiet. The #2993 refusal and the #4046 foreign-zone count never fire.
PgServerLogCsvParser.TryParseLogTime (PgServerLogCsvParser.cs:273) returns false for any zone that is not zero-offset. TryParseRecord therefore rejects the record, and Parse counts it in recordsDiscarded. As a result, FilterForeignZoneEntries (PgLogEventsCollector.cs:293 onward) only ever receives UTC entries. Its throw at :303 and its foreignZoneLines++ branch are both unreachable. The comment at :244-248 claims parity with the stderr path, but the code does not deliver it:

  • Non-UTC log_timezone. The stderr path throws PgLogTimezoneUnsupportedException and records a named refusal that points at the setting. The csv path gets zero entries back. Every FindBoundaries anchor fails, so after 64 full backward scans it returns null. Parse reports csv_records_discarded = 1, and the run stores 0 rows as a success. The target reads as quiet, which is the failure PgDeadlockLogParser captures the log's timezone abbreviation and never reads it — occurred_at assumes UTC no matter what log_timezone says #2993 exists to prevent. The worst-case CPU in M2 is also paid on every cycle.
  • UTC log_timezone with foreign-zone records (older records written before a log_timezone change): these are counted as csv_records_discarded instead of foreign_zone_lines_skipped, so they carry the wrong note.

Fix: have TryParseLogTime accept any parseable stamp and return the zone, and let FilterForeignZoneEntries make the zone decision. The shape check should decide "is this a record", not "is this UTC". Add a pipeline test that feeds the csv branch a non-UTC body with logTimezoneIsUtc = false and asserts PgLogTimezoneUnsupportedException. Add a second test with a UTC setting and a mixed body, and assert foreign_zone_lines_skipped.

Medium

M1. FindBoundaries accepts the first anchor whose one preceding record validates. When a read ends inside a multi-line record, that lets inverted quote parity win (PgServerLogCsvParser.cs:126-181).
The syslogger's log file is line-buffered (setvbuf with PG_IOLBF). A record whose quoted fields contain newlines, such as a multi-line query or detail, can therefore reach the file in more than one write(). The pg_ls_logdir() stat, which fixes the read's end offset, can land between two of those writes. The body then ends right after a newline that is inside a quoted field. The first anchor is that newline, and the walk starts with inQuotes = false when the true state is inside quotes.

The segment between the two newlines before the anchor is attacker-controlled statement text. A client can craft that text as an unquoted line with 26 fields, a valid stamp, a numeric pid and a hex.hex session. That segment passes the check at :172, and marks is returned with every boundary before it inverted. The planted record is emitted as the server's own, and the real records around it glue together and are discarded. The race window is narrow, but this is the forgery that #4053 moved to csvlog to close.

Suggested fix: don't return the first anchor that validates. Score each candidate by how many of its records parse, and keep the best. With inverted parity, a candidate yields at most a few planted valid records, while the true parity yields almost all of them. As a cheaper step, require that most records under the chosen marks validate, and reject the anchor otherwise.

M2. Retry cost (PgServerLogCsvParser.cs:128, :142). Each try is a full backward scan of up to about 4.2M chars, plus one List<int> entry per boundary. Sixty-four tries come to roughly 270M character iterations. At an estimated 1–2 ns each that is about 0.3–0.5 s of CPU per cycle per target, plus about 64 boundary lists of tens of thousands of entries. In a real mid-write read, the correct anchor is normally found within a few tries, one per embedded newline in the trailing partial record, and the result is just fewer records that cycle, which is acceptable. Nothing throws. The full 64 runs only when no anchor validates: H1's non-UTC case (every cycle), or a body with no parseable records. Suggest a cap of 8. If M1's scoring is adopted, compute parity once from the end and reuse it, instead of rescanning for each anchor.

M3. DecodeWhole protects 0x0A but not 0x22 on DBCS encodings (PgBinaryTailText.cs:91-124). The #4062 remark explains that the 51932/936/51949 decoders can pair an unmapped lead byte with a following ASCII byte. Splitting on 0x0A stops them from eating a newline. The csv route's quote-parity walk also depends on every " surviving decoding. A failed login's role name ends inside a quoted field, and PostgreSQL writes the closing " right after it. If a planted lead byte comes right before that quote and the decoder consumes the quote, one quote toggle disappears. Parity then inverts for everything before it: real records are discarded and planted text is treated as outside quotes. This applies only on the binary route with a DBCS server_encoding. Please add a test that decodes a lead byte followed by 0x22 under each DBCS code page. If the quote is eaten, split on 0x22 as well as 0x0A in the csv branch, or find boundaries on the raw bytes before decoding.

Low

L1. The format cache has no invalidation on either "no file" marker (PgLogFormatCapability.cs:66-80, DarlingCollectorRunner.cs:1140-1145). log_destination is SIGHUP, and the verdict can be up to an hour stale:

  • csvlog removed while the cache says true. The csv CTE's in-SQL gate (PgServerLogTail.cs:178) empties newest, and the query throws PgNoCsvlogFileException. Its message says csvlog "was only just added", which is backwards. The stderr file is also not read for up to an hour.
  • csvlog-only set while the cache says false. This throws PgNoStderrLogFileException, whose new text says pg_log_events is already being read from csvlog, which is untrue during that window.

Neither case reads the wrong file: the in-SQL gate makes the result a named skip, not silent data. Suggest calling a PgLogFormatCapability.Invalidate(targetKey) from both marker catches, the same way ForgetStaleReadBinaryFileVerdict does.

L2. Switching routes changes RawText, so raw_line_hash changes too. Events inside the overlap window when a target switches from stderr to csv are stored twice, once for each hash. This is a one-time duplicate and may only need a line in the PR body.

Info: the six questions

  1. Probe (PgLogFormatCapability.cs:47-48). current_setting, replace, lower, string_to_array and = ANY(text[]) all exist on 14+. The query returns a bool, and :76 reads it correctly. The cache is per target (StorageName) with a one-hour TTL (:51), and ConcurrentDictionary is fine for this use. log_destination is PGC_SIGHUP, so it is server-wide and can't be set per database or per role. Caching it per server is correct.
  2. Routing (PgLogEventsCollector.cs:149-151, PgServerLogTail.cs:171-213). stderr+csvlog selects the newest .csv file, and .json and .log files are excluded by name. The marker arm's reuse of NoStderrLogFileMarkerSql is correct: its NOT EXISTS (SELECT 1 FROM newest) binds to the csv statement's own newest. The collector-off and no-file arms are still mutually exclusive. The only wrong-or-no-file cases are the cache-staleness cases in L1, and both end in a named skip.
  3. ReadAsync (:224-257). The marker order is correct: collector-off first, then no-csvlog, then parse. A NULL body parses as empty. I found no path that throws on valid input: every index into the fields list follows the 26-field count check, marks.Count >= 2 guards :170-171, and the timestamp and pid parses use TryParse. The foreign-zone parity is broken (H1). csv_records_discarded is recorded only when it is greater than 0, following the existing pattern, but it currently includes the non-UTC records from H1.
  4. FindBoundaries. A mid-write read returns fewer records that cycle and does not fail. Cost and forgery risk are covered in M1 and M2.
  5. DecodeWhole. Splitting on 0x0A and rejoining is lossless for valid text in every mapped encoding. In UTF-8, continuation bytes are 0x80–0xBF. In the single-byte code pages, 0x0A is its own character. EUC-JP and EUC-KR trail bytes are 0xA1 and above, and GBK/936 trail bytes are 0x40–0xFE. The remark at :96 says GBK trail bytes are 0xA1 and above, which is wrong, but 0x40 is still above 0x0A, so the conclusion holds. For invalid bytes, see M3.
  6. Deadlocks and plan capture are unchanged. PgLogUsesCsvlog is set for pg_log_events only (DarlingCollectorRunner.cs:1140-1145). The stderr CTE constants are unchanged. Only the text of PgNoStderrLogFileException changed. This is not a regression.

… decides

TryParseLogTime and TryParseTimestamp were rejecting any non-zero-offset
log_time/timestamp, so a foreign-zone record never reached
PgLogEventsCollector.FilterForeignZoneEntries, and a non-UTC server read as
quiet instead of refused. The shape check now decides only whether the
stamp parses; the zone judgment belongs to the collector's filter, same as
before for stderr via PgLogEntryAssembler.

Adds: a csv parser test that a non-UTC record is returned with its
ZoneText; a json parser test doing the same (json wiring is a later lane,
per the brief, so this pins the parser's own contract); two pipeline
tests over the csv route's FakeReader — non-UTC log_timezone throws
PgLogTimezoneUnsupportedException, UTC skips and counts in
foreign_zone_lines_skipped.
…cap at 8

FindBoundaries accepted the FIRST trailing-newline candidate whose one
preceding record validated. Under inverted quote parity, a forged
unquoted look-alike line planted inside a multi-line quoted field can
satisfy that single check and win, gluing the real records around it
into discards. Score each candidate by how many of ITS records parse and
keep the best (latest anchor on a tie); the true parity always wins by a
wide margin over a forged look-alike's few planted records.

Also caps the walk at 8 candidates (was 64): a mid-write read normally
resyncs within a few tries, and 64 full backward scans only ran on H1's
non-UTC case or a body with no parseable record — about 0.3-0.5s of CPU
per cycle per target, paid for nothing.

When the body ends in a newline the anchor is unambiguous, so no scoring
runs; that path is unchanged.
…he newline

DecodeWhole/UnescapeAndDecode split on 0x0A before decoding so a DBCS
lead byte can never eat a newline. csvlog's quote-parity walk depends on
every '"' surviving decoding just as much: a planted lead byte right
before a closing quote on the binary route, under a DBCS server_encoding,
could eat the quote and invert parity for everything before it. Split on
0x22 as well, re-emitting each delimiter byte literally. Neither byte is
ever a trail byte in EUC-JP/EUC-KR/GBK, so valid text is unchanged.

Adds EUC_JP/EUC_CN/EUC_KR theory tests, mirroring the existing
before-newline tests, for a lead byte before a quote on both DecodeWhole
and UnescapeAndDecode.
log_destination is SIGHUP and PgLogFormatCapability's verdict can be up
to an hour stale. Add Invalidate(targetKey), mirroring
PgReadBinaryFileCapability.Invalidate exactly, and call it from
DarlingWorker's PgNoStderrLogFileException and PgNoCsvlogFileException
catch blocks (the only two touched in DarlingWorker.cs, per this lane's
scope — the web host and DarlingWorker's purge belong to issue-4130's
lane): whichever marker fires, the cache disagreed with the target's
current log_destination, so the next cycle should re-probe rather than
wait out the hour.

New PgLogFormatCapabilityTests.cs: Invalidate drops the named target's
cached verdict only, and IsCsvlogEnabledAsync re-probes and picks up the
new setting after it.
@erikdarlingdata

Copy link
Copy Markdown
Owner Author

Code review round 2 (automated reviewer, the last round): #4124

Verdict: changes requested. The changes are small; the main one is the parser's contract. The round-1 fixes H1, M3 and L1 are confirmed correct, and the M2 cost stays bounded.

High: the fast path trusts the final newline (PgServerLogCsvParser.cs:145-152)

  • Self-hosted route (this PR): a narrow race, rated Low. The syslogger's log file is line-buffered, so a record larger than the stdio buffer can reach the file in several writes. A read that lands between two writes can end at a newline inside a quoted field.

  • RDS route (sibling PR 4053 c1: RDS/Aurora pg_log_events reads the csvlog file when csvlog is on #4135): deterministic. A DownloadDBLogFilePortion portion is cut on physical lines, so it can end inside a multi-line quoted field.

    • An honest multi-line statement discards the whole chunk, and the committed marker makes that loss permanent.
    • Planted look-alike lines get emitted.
  • Fix: the caller states the body's edges (CsvBodyEdges):

    • a forward walk when the start is known to be a record boundary;
    • today's fast path when the end is;
    • otherwise, two-hypothesis scoring (even or odd quote parity after each newline, 2 parses) in place of the 8-candidate loop, which also closes a cap hole.

    The existing Parse(body, out discarded) keeps today's inference.

Medium: scoring alone can pick forged rows

A failed statement bigger than the tail is logged whole by default, so it straddles the read's start. Under inverted parity, the lines planted inside it out-score the few real records after it. No scoring rule fixes this without a known edge, so scoring runs only when the caller can't state one. The remark names the residual risk.

Low

  • The no-file invalidation fires for any collector. On a csvlog-only target, pg_deadlocks and pg_plan_capture (still on stderr here) would wipe pg_log_events' verdict every cycle.
    • Fix: gate it on one RoutedCollectors set.
    • Key it through ReadBinaryFileCacheKey.
  • Stale remarks at PgServerLogCsvParser.cs:92-93 and :147-149.

Confirmed correct

  • H1: a non-UTC server gets the named refusal, and a UTC server skips and counts foreign-zone records.
  • M3: the split on 0x22 is byte-identical for valid input on every mapped encoding, because 0x22 is never a trail byte.
  • The stderr route: no SQL change.
  • Coordinator verification of the round-1 head (e3025ae70):
    • the live csvlog forgery test passes (1 of 1);
    • the parser and pipeline classes pass;
    • the full suite equals dev's baseline.

Fixes are in progress on this branch. There is no third review round: the coordinator verifies the fixes and then arms the PR.

@erikdarlingdata
erikdarlingdata marked this pull request as ready for review September 24, 2026 04:53
@erikdarlingdata
erikdarlingdata merged commit 4faf506 into dev Sep 24, 2026
19 of 20 checks passed
@erikdarlingdata
erikdarlingdata deleted the fix/4053-csvlog-wiring branch September 24, 2026 04:53
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
* Add 48 buffered CHANGELOG entries in one splice

Adds 48 entries and 48 link refs (#4057, #4077, #4079, #4081, #4082, #4083, #4084, #4085, #4086, #4087, #4088, #4089, #4090, #4091, #4092, #4093, #4095, #4096, #4099, #4100, #4101, #4103, #4105, #4106, #4107, #4108, #4109, #4110, #4111, #4113, #4114, #4115, #4116, #4117, #4118, #4119, #4120, #4121, #4122, #4123, #4124, #4125, #4126, #4127, #4131, #4133, #4136, #4141). Each PR's entry was buffered, and this lands every entry whose PR was merged on origin/dev when it ran.

Entries found under a bare section line (none unless the old script ran again) move into the matching ### section, below the new entries.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QQh8LczP1HGLXQYAx4oTZC

* Changelog splice: add #4137's entry, which merged before the splice but was missed

#4137 (pg_plan_capture reads csvlog) merged at 05:57Z with a CHANGELOG entry section in its
body. It was neither spliced nor listed as needing no entry. Its entry goes under Fixed, right
after #4136's, and #4136's last sentence now points to it instead of saying plan capture is
unchanged.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01NUU29PuGg9TUFBsACgZg2K

---------

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
erikdarlingdata added a commit that referenced this pull request Sep 24, 2026
…4144)

* pg_log_events reads jsonlog on self-hosted targets (#4053 part a2)

Adds the jsonlog route to pg_log_events, mirroring the csvlog wiring from #4124/#4140: jsonlog wins over csvlog, which wins over stderr, when more than one is configured. One probe row answers both csvlog and jsonlog booleans so a cache miss costs one round trip, not two.

* 4053 part a2: live proof for the jsonlog route

Adds PgLogEventsJsonlogLiveTests.cs, mirroring the csvlog live test's
gate, raw StartupMessage plant, polling, and LiveStoreCleanup use, but
routed through PgLogUsesJsonlog and gated on DARLING_TEST_PG_JSONLOG.
Confirms IsJsonlogEnabledAsync/IsCsvlogEnabledAsync agree with the
rig's actual log_destination, and that a forged stderr-format line
planted in a login's user name lands inside the one real FATAL
event's message rather than forging a second event, over both
PgReadBinaryFileGranted values.

* 4053 part a2: pin fallout from the no-jsonlog-file early-return arm

CollectionLogDrainForensicsStoreTests pinned drain:null and
fetchPhases:null at 12 occurrences; #4144's new no-jsonlog-file
early-return arm in DarlingWorker is a thirteenth. Bumps both pins to
13 and extends the comment: the jsonlog route's twin of the twelfth
(#4053's no-csvlog-file arm).

* 4053 a2: the live probe case, a jsonlog-only target reads jsonlog on and csvlog off

* 4053 a2 review: the stderr arm clears only a stderr-only verdict; split-decode also protects the backslash (EUC_CN/GBK); a newline-less json body counts one discard
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant