Repository navigation
PgDeadlockLogParser captures the log's timezone abbreviation and never reads it — occurred_at assumes UTC no matter what log_timezone says #2993
Description
Found while auditing the pgmon fleet's timestamp handling. Latent today, undefended forever: the three targets sampled directly (target-a, target-b, target-c — 3 of 50) all run log_timezone = UTC via a shared configuration-file setting, so nothing is currently wrong on this fleet. Nothing in the code keeps it that way.
Mechanism
PerformanceMonitor.Collectors/PgDeadlockLogParser.cs:61 — the log-prefix regex captures the zone:
@"^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) (?<zone>\w+) \[(?<pid>\d+)\][^\n]*ERROR: deadlock detected\s*\n"The zone group is never read anywhere in the file. The timestamp goes through DateTime.TryParse(..., DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeUniversal, ...) (lines 122–125), which treats the naive log timestamp as UTC unconditionally. A repo-wide search for log_timezone returns zero hits — the GUC that decides what those timestamps mean is never consulted, collected, or checked.
What happens when it bites
A target whose log_timezone is not UTC gets every parsed deadlock's occurred_at shifted by the zone offset, silently: trend buckets land in the wrong hour, deadlock detail misaligns against every other UTC-keyed collection, and nothing errors. The failure direction is the bad one — plausible-looking data, wrong moment.
Options
- Convert using the captured abbreviation — worst option; zone abbreviations are ambiguous (CST is three different zones), which is presumably why the capture was never wired up.
- Read
log_timezoneat collection time (one GUC; the server-config collection already reads settings) and convert properly — correct, small. - Cheapest honest defense: same GUC read, but refuse to parse under a non-UTC
log_timezoneand record the refusal as a note naming the setting — turns silent-wrong into visible-unsupported.
2, with 3's note as the interim, is the shape the honest-empties convention wants. No measurement decides anything here — it is a defense, not a tuning question.
Related: the same collector's log reads are currently denied fleet-wide on the managed path (filed separately), so this parser is doubly unexercised in production right now.
Activity
erikdarlingdata commentedon Sep 5, 2026
Independent re-verification of this issue's claims (separate session, same investigation).
Code defect confirmed as described. Read
PerformanceMonitor.Collectors/PgDeadlockLogParser.csdirectly:(?<zone>\w+)from the log-prefix timestamp.git grep -n "zone" PerformanceMonitor.Collectors/PgDeadlockLogParser.csreturns only the regex definition line).DateTime.TryParse(timestampText, CultureInfo.InvariantCulture, DateTimeStyles.AdjustToUniversal | DateTimeStyles.AssumeUniversal, out var occurredAt)unconditionally treats the naive timestamp as UTC.PgDeadlocksCollector.cs:96doesn't even capture the zone into itsregexp_matchesarray (\w+matched, not grouped) — so the zone is discarded before it reaches C# on that transport too.Lite.Tests/PgDeadlockLogParserTests.csonly ever exercises aUTCliteral in its fixtures — no regression coverage exists for a non-UTC zone.log_timezone(not the sessiontimezoneGUC) is the relevant setting.Correction to the "zero hits" claim.
git grep -w "log_timezone"(positive-controlled againstgit grep -w "timezone", which returns 72 hits, so the grep tooling isn't silently failing) returns 2 hits, not zero — both inDarling/Darling.Tests/DarlingManagedPostgresTests.cs, asserting that the internal managed store's ownpostgresql.confdeliberately does not setlog_timezone(only the sessiontimezoneGUC matters there, per that test's own comment). That's a different concern — the store's own config, not a monitored target's log format — so it doesn't defend against this issue at all. But "zero hits anywhere in the codebase" as literally stated isn't accurate; "zero hits that defend against a target'slog_timezone" is the accurate framing.Independent fleet sample — 16 targets, not just the original 3. Queried
log_timezonedirectly viaget_pg_server_config(not trusting the original 3-target sample) across one representative from each display-name family on the fleet, for 16 of the 50 monitored targets:log_timezone = UTC.default_value=GMT(compiled default, so this is not an unconfigured default),source=configuration file(notALTER SYSTEM, not per-role/per-database),is_default=false.Net: this issue's mechanism and risk framing hold up under independent re-check. The fleet is not currently exposed, but that's a fact about today's shared config, not something the code enforces — the defect described here is real and worth the fix as scoped.
Follow the arm count and pin the straddled-window refusal (#2993)
Stop the arm comments carrying their own count (#2993)
Stop claiming the refusal is bounded on both transports (#2993)
Refuse deadlock reports from a non-UTC PostgreSQL log (#2993) (#3001)
erikdarlingdata commentedon Sep 5, 2026
Closed by #3001 (
3f47ce40). Closing by hand — this repository merges todev, so a closing keyword never fires.The option chosen was to assert the assumption, but reading the zone from the log line itself rather than from a
log_timezoneGUC read — and that is better than the GUC for two reasons worth recording. PostgreSQL renders%minlog_timezoneand prints that zone's abbreviation beside the stamp, so the captured token is the GUC as the server rendered it for the line being parsed, not the collector's connection at some later moment. And it needs no round trip, so it works identically on the RDS log-API transport, which has no target connection at all.The
Europe/Londoncase settles it: winter lines are stampedGMTand genuinely are UTC, so a GUC read would refuse them. The allowlist isUTC/GMT/UCTplus^[+-]0+(?::0+)*$, andGMTis load-bearing — this issue's own re-verification recordeddefault_value = GMTon 16 targets, so a target that lost its configuration-file setting rendersGMTand is correctly accepted rather than refused.The dead
zonecapture this issue complained about is now read, and the refusal is built on it. A non-zero-offset prefix throwsPgLogTimezoneUnsupportedException, recorded asPERMISSIONSrather thanERROR— matching the three existing classified-exception arms and the framing of a satisfiable, per-cycle-re-derived condition.The scope addition is the more important half
The zone token widened from
\w+to[^ \n]+in both the C# pattern and the server-sideregexp_matches. A numeric-offset zone such as+07matched no block at all under\w+, so the server reported no deadlocks — the same defect as this issue, silent in the opposite direction, and the one shape that would have escaped the new check by never reaching it.A probe against a mutated build quantified the original defect: an
EST-stamped line at 22:25:24 was stored as22:25:24.100 Kind=Utc, five hours early, withISTand+07wrong the other way.A claim this PR wrote and then retracted
The parser remarks initially said the straddled-window loss was bounded by log rotation, on the grounds that both transports read the newest file only. That is true of the
pg_read_fileroute and false of the RDS log-API route, which is consume-once:RdsLogSource.ReadNewestAsyncpersists its resume marker as a side effect of the fetch, before the parser is reached, so text the refusal abandons is never re-fetched and the readable UTC deadlocks sharing that chunk are lost. Retracted ineee73527a, which states the asymmetry per transport instead of a single bound.That loss is real and is not fixed here. The symmetric fix — commit the marker only after the chunk's rows are written — is being worked separately, and was chosen over a non-throwing parser entry point because the asymmetric route needs an answer to
DarlingWorker.RunOneAsync's row-count-or-throw contract, which has no honest representation for "stored 8 rows AND refused some".One thing this PR ships that is already filed against
Its new
PERMISSIONSarm hardcodes0, 0, 0for its timing fields. That is consistent with every existing classified arm and is not a defect against current convention — but it is a fresh instance of the pattern #3011 describes, and #3011's sweep must include this arm or the fix will miss it.Not verified
The server-side pattern was never run against a live PostgreSQL. There was no local PostgreSQL or container runtime available, and a read-only probe over SSM was blocked by the sandbox classifier. The probe was built from the shipped
BuildQuery(...).Textrather than a retyped copy, so it is ready to run. The bracket-expression form is what the shipped query already relies on in production, and the .NET pattern mirroring it is tested directly — but that is inference rather than measurement. No live PostgreSQL target was reached, so neither transport was exercised end to end.Merge origin/dev, taking the drain/fetchPhases pin to nine
Scope the de-skew's accuracy claim where the column outlives a DST tr…
Tell a permissions fault from a missing log file, and logging_collect…
One line stamped in another zone no longer refuses a UTC target's log…
The non-UTC log refusal names the log, not deadlocks (#2993) (#4070)