Repository navigation
Refuse deadlock reports from a non-UTC PostgreSQL log (#2993) - #3001
Conversation
PgDeadlockLogParser captured the log prefix's zone and read it nowhere, then put the naive timestamp through DateTime.TryParse with AssumeUniversal. A target whose log_timezone is not UTC got every occurred_at shifted by the zone offset with nothing erroring. The captured zone is now read. It cannot be converted from — CST is three different zones — but it answers whether the offset is zero exactly, and it is log_timezone as the server rendered it for the line being parsed, so it needs no GUC read and works on the managed transport, which has no connection to ask. A non-zero-offset prefix throws PgLogTimezoneUnsupportedException, which the worker records as PERMISSIONS with a message naming the setting. The zone token widens from \w+ to [^ \n]+ in both the C# pattern and the collector's server-side one: a zone with no abbreviation renders as a numeric offset, which \w+ could not match at all, so the whole block matched nothing and the server reported no deadlocks.
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
|
Reviewed the diff (parser, exception type, collector query, worker classification, and both new test files). Wiring checks out end to end. The zone column threads consistently: Postgres Regex mirroring is correct. No Lite/Darling parity gap. No SQL injection / secrets concerns. The new Postgres query text is a static literal; One edge case flagged inline on Style-wise this matches CONTRIBUTING.md conventions (WHY-focused comments, schema/ordinal discipline); no T-SQL touched by this PR. |
CollectionLogDrainForensicsStoreTests.ThePeerMarkIsCapturedAtDispatchNotAtCompletion counts the RunOneAsync arms that pass drain and fetchPhases as null, and the new log_timezone arm is an eighth. It qualifies for both on the reasons the pin's own comment gives: nothing was drained and no item completed. The arithmetic is the change; the arm is not. The refusal is per block, so it abandons the whole read when a window straddles a log_timezone change and holds a readable UTC block beside a non-UTC one. That is the trade rather than an oversight, and it is now documented and pinned: storing the UTC half would leave a partial history from a target just declared unreadable with nothing in the data marking what is missing, and a reader could not tell a quiet server from a half-collected one. Both transports read the newest log file only, so a rotation clears the straddle, and every cycle until then records the refusal with the setting named.
|
Reviewed the diff (C#/regex changes across Correctness
Lite/Darling parity
Security / other
No blocking issues found. Nice test discipline — the red-first mutation table in the PR description is a good practice and the fixtures (e.g., placing the readable block first in the straddle test) actually validate the property claimed rather than just exercising the code path. |
The prose beside both counted assertions said seven while the assertions said eight. A count restated in a comment is what drifted here in the first place, so the comments describe the arms and let the assertion hold the number.
|
Reviewed the diff (parser, collector query, exception type, worker classification, RDS ingestor, tests). This is an unusually well-documented and well-tested change — the red-then-green mutation testing in the description is a good pattern. Lite/Darling parity: No gap here. Lite is SQL-Server-only (no Postgres target support at all — One correctness issue found, posted inline on Everything else checked out: exception-arm ordering/placement in |
The remarks said both transports read the newest file only, so a rotation clears a straddled window. That is true of the pg_read_file route, which re-reads an overlapping byte-window tail every cycle, and false of the RDS log-API route: RdsLogSource.ReadNewestAsync advances and persists its resume marker as a side effect of the fetch, before the parser is reached, so text abandoned by the refusal is not re-fetched for the life of that marker. The claim is replaced by the asymmetry, named per transport, with the reason it is a property of the read rather than of the refusal. The loss on the consume-once route is real and is not addressed here.
|
Reviewed the diff (parser, collector, exception type, Exception propagation verified end-to-end. Traced both transports to confirm
Both dispatch through the same Lite/Darling parity: not a gap here. Regex/allowlist logic checked by hand against the test matrix ( One pre-existing/disclosed item worth double-checking before merge rather than a new finding: the PR description already flags that the RDS log-API route's marker advance ( No missing-index DMV suggestions made per project convention. No T-SQL style issues (the touched query is PostgreSQL, and |
DARLING01's PG18 target (log_timezone America/Los_Angeles) records this refusal on pg_log_events, and the message said "every timestamp in its deadlock reports" and "NOT 'no deadlocks were detected'". The one throw site is PgLogEntryAssembler, which both PgLogEventClassifier (pg_log_events) and PgDeadlockLogParser (pg_deadlocks) read through, so the text written for deadlocks in #3001 now shows on log-event rows too. The message now names the log and says it is NOT an empty log. It keeps the zone token, log_timezone, the CST example, the parameter-group note and the reload-without-restart note, and drops the dashes and the semicolon. Lite's pin moves to "this is NOT an empty log" and fails if "deadlock" comes back. The exception's doc comment and the worker's catch arm comment name both readers. Claude-Session: https://claude.ai/code/session_01Ua31ugERL5DmhFVRtf6keQ Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
1 participant
Part of #2993.
PgDeadlockLogParsercaptured the log prefix's timezone in a named group and read it nowhere, then put the naive timestamp throughDateTime.TryParsewithAdjustToUniversal | AssumeUniversal. On a target whoselog_timezoneis not UTC, everyoccurred_atwas shifted by the zone offset with nothing erroring: trend buckets in the wrong hour, deadlock detail misaligned against every other UTC-keyed collection, plausible rows at the wrong moment. Measured against the parser with the check removed, anEST-stamped 22:25:24 line comes back as 22:25:24Kind=Utc— five hours early — andISTand+07are wrong in the other direction by the same mechanism.What this does
Option 3 from the issue, not option 2, and not from a
log_timezoneread. The abbreviation is unusable for conversion —CSTis three different zones, which is the good reason the capture was never wired up — but it answers "is this offset zero" exactly, and that is the only questionoccurred_atneeds answered. 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. That makes it a better witness thancurrent_setting('log_timezone')on two counts: it describes the line rather than 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 receives log text and runs no SQL. OnEurope/Londonthe two even disagree for half the year — winter lines are stampedGMTand really are UTC, and a GUC read would refuse them.A non-zero-offset prefix throws
PgLogTimezoneUnsupportedException, whichDarlingWorkerrecords asPERMISSIONSwith a message naminglog_timezone, quoting the observed zone, saying the remedy, and saying outright that this is not "no deadlocks were detected".PERMISSIONSrather thanERRORfor the reason theFeatureDisabledarm beside it gives: none of the store's five statuses means "this target is configured in a way this source cannot be read under", the cause is a setting an operator can change (a parameter-group change on a managed fleet, effective on reload), andCollectorRuntimePrecondition'sPERMISSIONSarm already frames the condition as satisfiable and re-derives it every read. Both transports land on the one arm — thepg_read_fileroute throws out ofReadAsync, the RDS route out of the ingestor'sExtract.Refusing rather than skipping is the point. This is the only intolerant thing in a deliberately tolerant parser: everything else a block can be wrong about is read whole on the next overlapping pass, while this neither clears itself nor announces itself. Returning null would have stored no deadlocks and read as a server that has none — the same silent-wrong one layer up.
Why the allowlist is not just
UTCGMTand the numeric zero forms are in it deliberately, and the issue's own independent re-verification is what makes that concrete: across 16 sampled targetslog_timezone = UTCcomes fromsource = configuration filewithdefault_value = GMTandis_default = false. So PostgreSQL's own compiled default here isGMT— a target that lost the configuration-file setting would renderGMT, which is zero-offset and genuinely UTC. An allowlist ofUTCalone would have refused it and taken deadlock capture away from a server that was never wrong.UTis deliberately absent for the mirror-image reason: it is not a zone PostgreSQL renders, and an over-long allowlist is the same silent-wrong defect as no check at all, arriving one entry at a time.The dead capture is now load-bearing
The
zonegroup is read, and reading it is what the refusal is built on, so it can no longer be a thing someone "just uses" for a conversion.The zone token widens, in both patterns
\w+to[^ \n]+, in the C# pattern and in the collector's server-sideregexp_matches. A zone with no abbreviation renders as a numeric offset (+07,-03:30), and\w+matches neither the sign nor the colon — so the whole block matched nothing and the server reported no deadlocks at all. Same category as the shifted stamp, silent in the other direction, and the one shape that would have escaped the new check by never reaching it. The collector's query now returns the zone as its own column (log_zone_text), which is what gives the SQL route anything to check.Both are matched with a bracket-expression form the query already relies on in production (
[^\n]*), rather than a new escape construct, since neither the .NET nor the PostgreSQL pattern can be run against a live server from here.Verification
Every new test was proved red first, one mutation at a time, against the real committed source:
FromBlockRefusesAReportWhoseLogPrefixIsNotUtc_NamingTheSetting—Assert.Throws() Failure: No exception was thrown(5 tests)\w+RefusesANumericNonZeroOffsetPrefix_RatherThanMatchingNothing(zone: "+07")— no exception thrown; the probe prints+07 -> 0 deadlocks(7 tests)TheCollectorHandsTheParserItsFourColumnsInOrder—Assert.Single() Failure: The collection was empty(1 test)ERRORWorker_Records_A_NonUtc_Log_As_Permissions_Not_Error(1 test)The_Collector_Query_Returns_The_Prefix_Zone(1 test)The non-UTC fixture is the captured report with only its prefix zone substituted. It is what makes any of this meaningful: the whole fleet is uniformly UTC, so a fixture carrying the captured zone passes identically whether the check exists or not.
TheCollectorHandsTheParserItsFourColumnsInOrderdrives the realReadAsyncthrough a four-column fake reader, because the zone arrived as a new column in the middle of the list and a mis-ordinal would hand the parser the zone where it expects the victim pid — which parses as nothing, returns null, and drops every deadlock silently. AnAssert.Containson the query text cannot see that.Darling.TestsandLite.Testsarenet10.0-windowsand cannot run on macOS, so the real test files were compiled into throwawaynet10.0xunit v3 hosts staged outside the repo:Lite.Tests38 tests / 0 failed / 0 not run,Darling.Tests2 / 0 / 0.The straddled window, raised in review
The throw is per block and unwinds
Extract's loop, so a window holding a non-UTC block and a readable UTC one abandons both. That is the trade rather than an oversight, and it is now documented at the throw and pinned byAStraddledWindowRefusesTheWholeRead_NotJustTheOffendingBlock, whose fixture puts the readable block FIRST so a catch-and-continue would return one deadlock and no exception (proved: it goes red on exactly that mutation).Storing the UTC half would leave a partial history from a target just declared unreadable, with nothing in the data marking what is missing — a reader could not then tell a quiet server from a half-collected one, which is the failure this whole change exists to stop. One log has one
log_timezoneat any instant, so the mixed window only arises while a change to that setting straddles the read.What that costs is not the same on the two transports, and an earlier revision of this description and of the source claimed otherwise. Review caught it and the claim is corrected in
eee73527a.PgDeadlocksCollectorre-reads an overlapping byte-window tail every cycle, so a straddled window there loses nothing permanently. The RDS log-API route is consume-once:RdsLogSource.ReadNewestAsyncsets_markers[key] = response.Markeras a side effect of the fetch, before the parser is reached, so text the refusal abandons is not re-fetched for the life of that marker and the readable siblings in it are lost. That loss is real and is not fixed here — see Not covered.Not covered
The server-side
regexp_matcheschange is unexercised here — no PostgreSQL target is reachable from this environment, andDarling PostgreSQL testsruns against a store rather than a monitored target. Its bracket-expression form is the one the query already uses, and the C# pattern it mirrors is tested directly.pg_deadlockslog reads are denied fleet-wide on the managed path (filed separately), so both halves of this are unexercised in production today.The consume-once loss on the RDS transport is not fixed here, and it needs a decision that touches another lane. The marker advance lives in
RdsLogSource.ReadNewestAsync, which is #3002's active file, so the symmetric fix — do not persist the marker until the chunk's rows are written — is not mine to make unilaterally. The alternative is asymmetric and entirely in these files: give the consume-once route a non-throwing entry point that stores what parsed and reports the refusal, justified by the two routes' different read semantics rather than by preference. Both are real; the choice is a coordination call, and the mechanism is verified either way. It is latent today because the grant is denied fleet-wide, and it becomes live the moment that is restored.This PR does not attempt an ARE-level validation of the server-side pattern against a live PostgreSQL from a development machine: there is no local PostgreSQL here, and the one read-only probe available (the monitoring store over SSM) was not reachable in this environment. The bracket-expression form is the one the shipped query already relies on in production, and the .NET pattern it mirrors is tested directly.
PgPlanLogParser, the sibling that shares the RDS transport, parses no timestamp out of the log prefix and stores none, so it does not carry this defect.