Log events and deadlocks read a log_line_prefix with fields between the zone and the pid (#4041)

[erikdarlingdata]

Closes #4041.

Why

Under a log_line_prefix with fields between the zone and the pid, such as '%m %u@%d [%p] ' (2026-... UTC app@db [5555] ERROR: ...), the shared log reader matched no line. The space family wanted the pid bracket right after the zone, and the managed family wanted a colon there. Both self-hosted families read through PgLogEntryAssembler, so a target with that prefix stored no log events and no deadlocks and looked like a quiet server.

Diagnosis confirmed on a rig, PostgreSQL from pg-runtime.zip, logging_collector = on, log_line_prefix = '%m %u@%d [%p] ', log_timezone = 'UTC', after a real workload (a division by zero, connections, a lock wait and a real deadlock):

• The shipped deadlock SQL pattern over the real log: 0 candidates before, 1 after.
• PgLogEventsLivePostgresTests.TheSelfHostedCollector_ReadsTheTargetsOwnLog_EndToEnd, pointed at that rig (DARLING_TEST_PG_LOG_TARGET): the collector's production query reads the real lines, and the Error, Connection and LockWait families all store. Before, the assembler read none of those lines.

While in the deadlock SQL I found a second gap in the same clause. It required the fraction (\.\d+) and carried only the space family. So on the self-hosted route, pgBadger's recommended '%t [%p]: user=%u,db=%d,...' and any colon-delimited prefix offered no candidate, even though the assembler reads both (the issue lists pgBadger's prefix as unaffected, but that is only true on the RDS route). #3037 left the SQL narrow because no PostgreSQL was available to test ARE against. PgDeadlockCandidatePatternLiveTests now tests it, so the SQL carries the C# prefix clause whole.

What changes

The assembler (PgLogEntryAssembler.s_prefixLine) gets a third alternative, tried after the two it extends:

(?<zone>[^ :\[\n]+) (?<mid>GAP)\[(?<pid>\d+)\]      GAP = (?:STEP[^\[\n])*?

STEP is s_prefixRun's per-character lookaheads, split out unchanged. s_prefixRun is now (?:STEP[^\n])*?, the same string as before. The gap is the same run with [ taken out of its class.

How the gap composes with s_prefixRun, and why no forged label or bracket is reachable:

1. The gap cannot cross a label. Each step passes the same three lookaheads as rest: no : , no unpadded catalogue label's colon, and no colon after a non-ASCII letter or three capitals that is followed by text. By Log messages show as PostgreSQL wrote them, the SQL in them stays normalized, and one statement's text never decides how another's is read (#3944) #3996's argument, those rules stop the run at the line's own label in every catalogue PostgreSQL 18 ships, and PgLogCatalogueShapeTests pins that. So the gap never leaves the prefix for the line's text, which is where a forged [pid] LABEL: has to live.
2. The gap cannot consume a bracket. The pid is therefore the first [ after the zone's space, and backtracking cannot move past it to a later one (Plan capture reads a plan block anywhere in a log line, so a statement's author can attach a forged plan to any query id #4008's rule).
3. rest after it is the unchanged run. From the zone to the label, the whole path crosses no label. The only thing it passes that the run would refuse is the [digits] pid itself, which holds no colon. So the label read is the line's first label, which is its own.
4. The zone is colon-free and bracket-free, and the alternative is tried last. With a colon allowed, the zone ran over a managed line's whole prefix. On UTC:...:[4503]:ANWEISUNG: SELECT 'x [1]:ERROR: ...' (a translated label) the zone ran to the first space, the gap found [1] inside the SQL, and the zone check refused every read of the target. The existing ATranslatedLabel_NeverOpensAnEventFromInsideItsSql caught that in my first cut. With the colon-free zone, this alternative only reads lines whose first token has no colon, and the managed family reads every other line. Tried last, it cannot change the reading of any line the old pattern matched, because the engine takes the first alternative that completes and the old space family is this one with an empty gap. One effect to know about: a numeric zone with a colon (+05:30) under the new prefix reads through the managed family, up to its first colon. The verdict is the same; that is the trade the deadlock parser's header already argues.

_prefixRest is now mid + " " + rest, so s_userAtDatabase finds %u@%d before the pid as well as after it, and the two halves never glue into one token. PrefixRest is in-process only: it is never stored or hashed.

The deadlock candidate patterns:

• C# s_deadlockBlock: the space family becomes [^ \n]+ (?:(?!: )[^\[\n])*\[\d+\]. It excludes [ and cannot contain a : , which is Deadlock capture's regexp_matches may accept a forged STATEMENT echo, same class as #4008 #4014's form of the label rule. Both conditions only narrow the candidate toward what the assembler reads, and the gap is never narrower than the assembler's, so no report the assembler accepts is missed.
• PgDeadlocksCollector SQL: the same prefix clause, both families, with the fraction optional. [^[\n] is the ARE spelling. The groups are non-capturing, so m[1] is unchanged.

The other spellings: plan capture's C# and SQL already take this shape (#4016). pg_log_events has no SQL candidate stage (its SQL returns the tail body whole), and StoreLogClassifier is prefix-agnostic.

Test plan

Every new test was proven to fail by a revert:

• Product code reverted to dev: 4 Darling tests fail (the two new assembler tests, the new live SQL test, the byte pin) and 2 Lite tests fail (the two new deadlock tests).
• Gap without the label rule ((?:[^\[\n])*?): UnderACustomPrefix_ABracketOrLabelInsideTheText_OpensNothing returns 6 events, where it should return 1 real one.
• The naive form (gap folded into the first alternative, zone allowing colons): AManagedLineWithASpaceBeforeItsPid_IsStillReadByTheManagedFamily and ATranslatedLabel_NeverOpensAnEventFromInsideItsSql fail.
• SQL gap without (?!: ), run in PostgreSQL: a logged statement's echo becomes 1 candidate; with the rule it is 0.

New tests:

• ACustomPrefixWithFieldsBeforeThePid_ReadsItsEntries_AndLiftsUserAndDatabase: pids, severities, DETAIL and STATEMENT folding, user and database from before the pid, stored events, the EST refusal, and +00:00/-03:30.
• UnderACustomPrefix_ABracketOrLabelInsideTheText_OpensNothing: a STATEMENT echo, a translated label, an unknown primary label, and lines with no bracket before an English, unpadded, Korean, : or three-capital label. None opens an event or leaks. A real bracket followed by a forged one binds the real one.
• AManagedLineWithASpaceBeforeItsPid_IsStillReadByTheManagedFamily.
• Lite: AReportUnderACustomPrefixWithFieldsBeforeThePid_StillReads (C# Extract), and AForgedHeaderUnderACustomPrefix_IsNotReadAsOne.
• Live: TheShippedPattern_OffersAReportUnderEveryPrefixTheAssemblerReads runs the shipped SQL through PostgreSQL's engine. Under the custom, pgBadger and managed prefixes there is one candidate each, and FromReport reads victim pid 1549. The forged cases give 0.

Pins updated deliberately: TheTailerExtraction_LeftBothSiblingsSqlByteIdentical (the deadlock SQL) and PgDeadlockLogTimezoneTests.The_Collector_Query_Returns_The_Prefix_Zone (the zone spelling, still [^ \n]+ and not \w+).

Runs:

• Targeted Darling classes, with DARLING_TEST_PG on the rig: PgLogEventsPipelineTests, PgLogEventsRungTests, PgLogEventsLivePostgresTests, PgDeadlockCandidatePatternLiveTests, PgLogCatalogueShapeTests, PgLogEventMetricsTests, PgLogHashKeyTests: 67/67, 3 skipped. The skipped ones then ran with DARLING_TEST_PGRUNTIME and DARLING_TEST_PG_LOG_TARGET: 9/9.
• Targeted Lite classes: PgDeadlockLogParserTests, PgPlanLogParserTests, PgPlanCaptureCollectorDefinitionTests: 74/74.
• Both test projects build with 0 warnings.
• Full Lite suite: 5190/5190.
• Full Darling suite, once, after merging origin/dev, with DARLING_TEST_PG on the rig: 13066 total, 2 failed, 36 skipped. Both failures are explained:
  1. PgDeadlockLogTimezoneTests.The_Collector_Query_Returns_The_Prefix_Zone: a source pin on the old SQL zone spelling ([^ \n]+ \[\d+\]). I updated it deliberately in fb65e5e, and the class passes.
  2. StoreSelfMetricsTickRecoveryLiveTests.AFailedStoreLogCapture_...: it assumes a fresh cluster's logging_collector = off, and my rig had it on for the live check above. With the collector off and the log directory moved aside, it passes alone on a fresh database (1/1). The rig was the cause, not the code.

Issue filed

• 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 (pre-existing, design-level, security): PostgreSQL renders %u and %d from the startup packet before authentication. Under any prefix that puts them before %p, including the RDS default %t:%r:%u@%d:[%p]:, a client that can reach the port can spell a pid bracket and a label into its own failed-login line. Depending on the spelling, that forges an ERROR event, or it gives the first alternative a garbage zone and the whole read is refused. On RDS, the refusal withholds the resume marker, so the same window is refused again on the next cycle. This PR's gap has the same exposure under the new shape, and the existing first alternative already did (user [1] ERROR: y). The fix needs the target's actual log_line_prefix.

For the coordinator to double-check

• The ordering and colon-free-zone argument in point 4 above. It is the part that differs from the plan-capture pattern.
• The SQL widening beyond the issue's shape (optional fraction, managed family): I made it because the brief says "never missed" and Read the log prefix a managed PostgreSQL target renders, and test both parsers on one (#3030) #3037's reason for staying narrow is gone. If you would rather keep the SQL to the space family, drop the |[^ :\n]+:[^[\n]*\[\d+\] arm; the pgBadger fix is the fraction alone.
• Under the new rule, a prefix with a non-pid bracket before the pid (%h rendering [local] before [%p]) reads nothing. This is the same fail-closed behavior plan capture has.

🤖 Generated with Claude Code

https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv

[erikdarlingdata]

Security review, round 1 (Opus), and the coordinator's dispositions. The review ran about 23 adversarial lines through s_prefixLine, the assembler and s_deadlockBlock on this branch and on dev.

Clean:

• Statement text can't reach the new alternative's pid or label. The test lines covered [, : and non-ASCII names, [local], IPv6 %r, translated labels, and a [999] after the real pid.
• No ReDoS: 40k-character pathological lines finish in 35 ms or less.
• The SQL and C# patterns match: [^[\n] equals [^\[\n], and lookaheads and newlines under 'gn' agree.
• _prefixRest changes no line dev read, and it fixes a latent %u@%d[%p]%e gluing bug.
• Trying the new alternative last leaves every line dev read unchanged.

Medium: client-controlled %u/%d before %p (#4046) now also reaches '%m %u@%d [%p] '. Declined for this PR; the fix is #4046's.

• Verified on PostgreSQL 18.6: a newline in %u/%d starts a new physical line in the prefix.
• Dev's FIRST family already reads such a line, under this prefix and every other one carrying %u or %d, as a forged event. It can also force the zone refusal.
• A gate on the new alternative would close only the bracket spelling, and the newline spelling stays open on the same targets. The suggested lookahead also sees the real pid bracket, so it would never match at all.
• Details and the recommended fix are on 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: tolerate one foreign-zone line, then read csvlog/jsonlog.

Medium/High pending a live check (newline injection): checked. It is real, but not prefix-independent. Already tracked on #4046.

• PostgreSQL tab-indents newlines inside the message, so message text can't start a line.
• Only %u/%d in the prefix can, which PostgreSQL's default %m [%p] doesn't carry.

Low: %r's port read as a SQLSTATE. Fixed at 6b21a10.

• Under the RDS default, every event from a client on a five-digit port stored that port as its sqlstate, often in classes 53-58.
• A token that fills a pair of parentheses is no longer a SQLSTATE; %e still is.
• Red-watched: both tests fail with the old pattern.

Low: \d is Unicode in .NET and ASCII in ARE. No change. PostgreSQL renders stamps and pids in ASCII, so no real line differs.

Low: an application_name carrying : before %p fails its own line closed. Acknowledged: it hides only the sender's line, which is the "hide, never forge" rule.