From 8716671cdbcde2b2e37978fc0367086edf0d702e Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sat, 5 Sep 2026 07:33:43 -0400 Subject: [PATCH 1/4] Refuse deadlock reports from a non-UTC PostgreSQL log (#2993) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- .../PgDeadlockLogTimezoneTests.cs | 85 ++++++++++ .../DarlingWorker.cs | 27 +++ .../Targets/RdsDeadlockIngestor.cs | 8 + Lite.Tests/PgDeadlockLogParserTests.cs | 160 ++++++++++++++++++ .../PgDeadlockLogParser.cs | 94 +++++++++- .../PgDeadlocksCollector.cs | 22 ++- .../PgLogTimezoneUnsupportedException.cs | 67 ++++++++ 7 files changed, 453 insertions(+), 10 deletions(-) create mode 100644 Darling/Darling.Tests/PgDeadlockLogTimezoneTests.cs create mode 100644 PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs diff --git a/Darling/Darling.Tests/PgDeadlockLogTimezoneTests.cs b/Darling/Darling.Tests/PgDeadlockLogTimezoneTests.cs new file mode 100644 index 0000000000..35fea44984 --- /dev/null +++ b/Darling/Darling.Tests/PgDeadlockLogTimezoneTests.cs @@ -0,0 +1,85 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System.IO; +using System.Runtime.CompilerServices; +using Xunit; + +namespace Darling.Tests; + +/// +/// #2993, Darling half: a log stamped in a non-UTC zone records as PERMISSIONS, not ERROR +/// and not a successful empty read. +/// +/// The refusal itself and every zone decision are pinned in Lite.Tests +/// (PgDeadlockLogParserTests) against the shared parser both transports use. What is only pinnable +/// here is the CLASSIFICATION, which is try/catch glue around a live collection sweep — the same shape and +/// the same reason as : source-level, because there is no way to +/// reach the arm without a monitored PostgreSQL target. +/// +/// The status is the load-bearing part. ERROR would be a monitoring fault, which this is not, +/// and collection health would carry it forever for as long as the parameter group says what it says; +/// PERMISSIONS is the store's non-fatal degradation bucket, and +/// CollectorRuntimePrecondition's arm for it already tells a reader the condition can be satisfied +/// on the monitored server and is re-derived every cycle. Both are true here. +/// +public sealed class PgDeadlockLogTimezoneTests +{ + [Fact] + public void Worker_Records_A_NonUtc_Log_As_Permissions_Not_Error() + { + var source = ReadRepoFile(Path.Combine("Darling", "PerformanceMonitor.Darling.Service", "DarlingWorker.cs")); + + var armIndex = source.IndexOf("catch (PgLogTimezoneUnsupportedException ex)", System.StringComparison.Ordinal); + Assert.True(armIndex >= 0, "The #2993 classification arm is gone — a non-UTC log would fall to the general handler and record ERROR every cycle."); + + /* Bounded to the arm's own body. An unscoped Contains would pass on any of the other PERMISSIONS + arms in this file and prove nothing about this one. */ + var body = source[armIndex..]; + var close = body.IndexOf("\n return 0;", System.StringComparison.Ordinal); + body = close > 0 ? body[..close] : body; + + Assert.Contains("\"PERMISSIONS\"", body, System.StringComparison.Ordinal); + Assert.DoesNotContain("\"ERROR\"", body, System.StringComparison.Ordinal); + + /* The message is the exception's own, which is where log_timezone is named. Re-authoring it in the + arm would be a second copy of prose whose whole value is naming one setting correctly. */ + Assert.Contains("ex.Message", body, System.StringComparison.Ordinal); + } + + /// + /// The pg_read_file route's own half: the query has to RETURN the prefix zone, or the parser has + /// nothing to check and the refusal is unreachable on the transport that has a database connection. + /// The zone was matched and discarded here before #2993. + /// + [Fact] + public void The_Collector_Query_Returns_The_Prefix_Zone() + { + var source = ReadRepoFile(Path.Combine("PerformanceMonitor.Collectors", "PgDeadlocksCollector.cs")); + + Assert.Contains("AS log_zone_text", source, System.StringComparison.Ordinal); + + /* [^ \n]+ rather than \w+: a numeric-offset zone matched no block at all under \w+, so the + server reported no deadlocks instead of reporting a zone this cannot store. */ + Assert.Contains("([^ \\n]+) \\[(\\d+)\\]", source, System.StringComparison.Ordinal); + Assert.DoesNotContain("\\w+ \\[(\\d+)\\]", source, System.StringComparison.Ordinal); + } + + /* Locate the repo from this file — the DarlingLockTimeoutYieldTests idiom; no build-output copying. */ + private static string ReadRepoFile(string relative, [CallerFilePath] string thisFile = "") + { + var dir = Path.GetDirectoryName(thisFile)!; + while (dir is not null && !File.Exists(Path.Combine(dir, relative))) + { + dir = Path.GetDirectoryName(dir); + } + + Assert.NotNull(dir); + return File.ReadAllText(Path.Combine(dir!, relative)); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index d967f58044..3e166a225d 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -6149,6 +6149,33 @@ await DarlingObservability.LogCollectionAsync( fanout: null, phases: null, drain: null, fetchPhases: null, sweepPeerMaxMs: peerMaxAtDispatchMs, _logger, cancellationToken); return 0; } + catch (PgLogTimezoneUnsupportedException ex) + { + /* #2993: this target's log_timezone is not UTC, so the deadlock reports in its server log are + stamped in local time and occurred_at cannot be filled from them. + + PERMISSIONS for the same reason the PostgresException FeatureDisabled arm below is: none of + the store's five statuses means "this target is configured in a way this source cannot be + read under", so the non-fatal degradation bucket carries it and the MESSAGE is where the + truth goes. It also earns that bucket on the merits — the cause is a setting on the + monitored server, an operator can clear it, and CollectorRuntimePrecondition's PERMISSIONS + arm already frames the condition as satisfiable and re-derives it on every read. + + Not ERROR: nothing is broken on the monitoring side, and a parameter group does not change + because we shouted about it once a minute. Not a SUCCESS row with zero rows, which is what + dropping the unusable blocks quietly would have produced — a target whose log is in the + wrong zone reading as a target with no deadlocks. + + Both transports arrive here: the pg_read_file route throws out of the collector's ReadAsync, + the RDS log-API route out of the ingestor's Extract. */ + _logger.LogWarning(" [{Server}] {Collector} => PERMISSIONS: the server log is stamped '{Zone}', not UTC", + server.Config.DisplayName, collectorName, ex.ObservedZone); + + await DarlingObservability.LogCollectionAsync( + _postgres!, runtime, collectorName, "PERMISSIONS", 0, 0, 0, ex.Message, + fanout: null, phases: null, drain: null, fetchPhases: null, sweepPeerMaxMs: peerMaxAtDispatchMs, _logger, cancellationToken); + return 0; + } catch (SqlException ex) when (ex.Number == 1222 && CollectorCatalog.YieldsOnLockTimeout(collectorName)) { /* The 1-second LOCK_TIMEOUT guard doing its job (#1805): the snapshot sweep stepped aside diff --git a/Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs b/Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs index b8866180c6..0a9bd6c0e5 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs @@ -51,6 +51,11 @@ public RdsDeadlockIngestor(NpgsqlDataSource postgres, RdsLogSource? logs = null, /// The target's connection host. A non-RDS host is skipped silently — that target /// uses the pg_read_file route instead, and there is nothing to report. /// Rows stored, or zero when this target is not RDS or had nothing new. + /// The log is stamped in a non-UTC zone, so its + /// timestamps are local and nothing in it can be stored (#2993). Propagated for the same reason + /// is: the runner classifies it and names the setting, where + /// swallowing it would return zero rows and be recorded as a log that was read and held no + /// deadlocks. public async Task IngestAsync( int serverId, string storageName, @@ -82,6 +87,9 @@ and empty. */ return 0; } + /* Not inside the tolerant catch above, which covers the AWS FETCH. A parse refusal is a statement + about the target's configuration rather than about reaching it, and it has to reach the runner + to be classified. */ var deadlocks = PgDeadlockLogParser.Extract(chunk.Value.Text); if (deadlocks.Count == 0) diff --git a/Lite.Tests/PgDeadlockLogParserTests.cs b/Lite.Tests/PgDeadlockLogParserTests.cs index 89f73d4e8d..eae0148132 100644 --- a/Lite.Tests/PgDeadlockLogParserTests.cs +++ b/Lite.Tests/PgDeadlockLogParserTests.cs @@ -3,6 +3,8 @@ using System; using System.Linq; +using System.Threading; +using System.Threading.Tasks; using Lite.Tests.Helpers; using PerformanceMonitor.Collectors; using Xunit; @@ -27,6 +29,17 @@ public sealed class PgDeadlockLogParserTests + "\tBEGIN; UPDATE dl SET v=v+1 WHERE id=2; SELECT pg_sleep(2); UPDATE dl SET v=v+1 WHERE id=1; COMMIT;\n" + "2026-08-26 22:25:24.100 UTC [1549] 322048460535975151HINT: See server log for query details.\n"; + /// + /// The captured report with its prefix zone SUBSTITUTED, and the zone is the only thing changed. + /// + /// Synthesised on purpose, and it is what makes the #2993 assertions mean anything: every target + /// on the fleet runs log_timezone = UTC, so a fixture carrying the captured zone passes + /// identically whether the check exists or not. A prefix the fleet does not produce is the only + /// evidence available for the path that matters. + /// + private static string WithLogZone(string zone) => + RealBlock.Replace(" UTC [", $" {zone} [", StringComparison.Ordinal); + [Fact] public void ParsesARealReport_WholeGraphAndBothStatements() { @@ -189,6 +202,153 @@ public void CollectorDeclaresEveryColumnItWrites() Assert.Equal(PgDeadlocksCollector.Instance.PayloadColumns.Count, writer.Values.Count); } + /// + /// #2993: a log stamped in a non-UTC zone is REFUSED, naming the setting. + /// + /// Before this, the prefix zone was captured by the pattern and read by nothing, and the stamp + /// went through TryParse with AssumeUniversal — so this exact fixture parsed, cleanly, + /// into a deadlock at 22:25:24 UTC that actually happened at 03:25:24 the next day. Nothing errored, + /// nothing was empty, and the row was five hours wrong in a trend bucket. That is why the refusal is + /// the assertion here: there is no output to check, because the whole point is that no output is + /// produced. + /// + [Fact] + public void RefusesAReportWhoseLogPrefixIsNotUtc_NamingTheSetting() + { + var ex = Assert.Throws( + () => PgDeadlockLogParser.Extract(WithLogZone("EST"))); + + Assert.Equal("EST", ex.ObservedZone); + Assert.Contains("log_timezone", ex.Message, StringComparison.Ordinal); + Assert.Contains("EST", ex.Message, StringComparison.Ordinal); + + /* The sentence that stops the row being read as an empty log. A refusal whose message does not say + so is the same silent nothing one layer over. */ + Assert.Contains("NOT 'no deadlocks were detected'", ex.Message, StringComparison.Ordinal); + } + + /// + /// A zone with no abbreviation renders as a NUMERIC offset, and that shape has to be refused too. + /// + /// It is the case that would have escaped the check by never reaching it: the pattern matched the + /// zone as \w+, which matches neither the sign nor the colon, so a +07 prefix matched no + /// block at all and the collector reported a server with no deadlocks. Silent in a different direction + /// from the shifted stamp, and the same category — so it is refused rather than skipped, which is what + /// this asserts: an exception, not an empty list. + /// + [Theory] + [InlineData("+07")] + [InlineData("-03:30")] + [InlineData("+0530")] + public void RefusesANumericNonZeroOffsetPrefix_RatherThanMatchingNothing(string zone) + { + var ex = Assert.Throws( + () => PgDeadlockLogParser.Extract(WithLogZone(zone))); + + Assert.Equal(zone, ex.ObservedZone); + } + + /// + /// Every spelling of zero offset still parses, through the whole pattern rather than the predicate + /// alone. A check that refused a UTC server would be worse than no check: it would take deadlock + /// capture away from the entire fleet. + /// + [Theory] + [InlineData("UTC")] + [InlineData("GMT")] + [InlineData("UCT")] + [InlineData("+00")] + [InlineData("-00")] + [InlineData("+00:00")] + [InlineData("-0000")] + public void AZeroOffsetPrefixStillParses(string zone) + { + var deadlock = Assert.Single(PgDeadlockLogParser.Extract(WithLogZone(zone))); + + Assert.Equal(new DateTime(2026, 8, 26, 22, 25, 24, 100, DateTimeKind.Utc), deadlock.OccurredAtUtc); + Assert.Equal(1549, deadlock.VictimPid); + } + + /// + /// The predicate on its own, because the allowlist is the load-bearing part and an over-long one is + /// the same silent-wrong defect as no check at all, arriving one entry at a time. BST and + /// CST are here to be REFUSED: they are the ambiguity that makes conversion impossible — + /// CST is three zones — and refusing them is the whole trade this fix makes. + /// + [Theory] + [InlineData("UTC", true)] + [InlineData("utc", true)] + [InlineData("GMT", true)] + [InlineData("UCT", true)] + [InlineData("+00", true)] + [InlineData("-00:00", true)] + [InlineData("EST", false)] + [InlineData("CST", false)] + [InlineData("BST", false)] + [InlineData("IST", false)] + [InlineData("AEST", false)] + [InlineData("+01", false)] + [InlineData("+0030", false)] + [InlineData("-05:30", false)] + [InlineData("+", false)] + [InlineData("", false)] + [InlineData(null, false)] + public void IsZeroOffsetLogZone_AnswersDetectionRatherThanConversion(string? zone, bool expected) + => Assert.Equal(expected, PgDeadlockLogParser.IsZeroOffsetLogZone(zone)); + + /// + /// The WIRING, not the pattern: the collector's four result columns reach the parser in the right + /// order, driven through the real ReadAsync. + /// + /// An Assert.Contains on the query text cannot see this. The zone arrived as a new column + /// in the middle of the list, so 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. This is the + /// one seam where that is possible. + /// + [Fact] + public async Task TheCollectorHandsTheParserItsFourColumnsInOrder() + { + var reader = new FakeCollectorDataReader( + new object[] + { + "2026-08-26 22:25:24.100", + "UTC", + "1549", + "Process 1549 waits for ShareLock on transaction 809; blocked by process 1556.\n" + + "\tProcess 1556 waits for ShareLock on transaction 808; blocked by process 1549.\n", + }); + + var rows = await PgDeadlocksCollector.Instance.ReadAsync(reader, MakeContext(), CancellationToken.None); + + var row = Assert.Single(rows); + Assert.Equal(1549, row.VictimPid); + Assert.Equal(2, row.ParticipantCount); + Assert.Equal(new DateTime(2026, 8, 26, 22, 25, 24, 100, DateTimeKind.Utc), row.OccurredAtUtc); + } + + /// + /// And the same seam refuses: the zone column is READ rather than carried past, so a non-UTC target + /// gets a classified refusal out of the collector instead of rows stamped in local time. + /// + [Fact] + public async Task TheCollectorRefusesWhenItsZoneColumnIsNotUtc() + { + var reader = new FakeCollectorDataReader( + new object[] + { + "2026-08-26 22:25:24.100", + "EST", + "1549", + "Process 1549 waits for ShareLock on transaction 809; blocked by process 1556.\n" + + "\tProcess 1556 waits for ShareLock on transaction 808; blocked by process 1549.\n", + }); + + var ex = await Assert.ThrowsAsync( + async () => await PgDeadlocksCollector.Instance.ReadAsync(reader, MakeContext(), CancellationToken.None)); + + Assert.Equal("EST", ex.ObservedZone); + } + private static CollectorContext MakeContext() => new() { ServerId = 42, diff --git a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs index 9977d91485..a6bad998a8 100644 --- a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs +++ b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs @@ -56,9 +56,19 @@ public readonly record struct ParsedDeadlock( The DETAIL block is the first line plus every TAB-INDENTED line after it. It ends at the next line carrying a log prefix, which is what (?:\t[^\n]*\n)* expresses: a statement inside the block can itself contain newlines, and each continuation arrives tab-indented, so a line-count rule or a - blank-line rule would truncate multi-line SQL silently. */ + blank-line rule would truncate multi-line SQL silently. + + The zone is captured and READ (#2993). PostgreSQL renders %m in log_timezone and prints that zone's + abbreviation beside the stamp, so this token is the setting's own rendered value for THIS line, and + it is what decides whether the naive timestamp next to it is already UTC. See IsZeroOffsetLogZone + for why that question is answerable from an abbreviation when "which zone is this" is not. + + [^ \n]+ for it rather than \w+: 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 failed to match and the + server reported no deadlocks at all — the same silent nothing the [^\n]* trap above avoids, and the + one shape that would have slipped past the zone check by never reaching it. */ private static readonly Regex s_deadlockBlock = new( - @"^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) (?\w+) \[(?\d+)\][^\n]*ERROR: deadlock detected\s*\n" + @"^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) (?[^ \n]+) \[(?\d+)\][^\n]*ERROR: deadlock detected\s*\n" + @"[^\n]*DETAIL: (?(?:[^\n]*\n)(?:\t[^\n]*\n)*)", RegexOptions.Compiled | RegexOptions.Multiline); @@ -70,6 +80,12 @@ enumeration would silently drop the shapes it did not anticipate. */ @"Process (?\d+) waits for (?[A-Za-z ]+) on (?[^;]+); blocked by process (?\d+)\.", RegexOptions.Compiled); + /* A numeric log-prefix offset that is zero: +00, -00, +00:00, -0000. Anchored, so a non-zero offset + sharing a prefix with a zero one (+0030) cannot match part of itself and pass. */ + private static readonly Regex s_zeroOffset = new( + @"^[+-]0+(?::0+)*$", + RegexOptions.Compiled); + /* `Process 1549: ` then the statement, which runs to the next such header or the end of the block. */ private static readonly Regex s_participant = new( @"^Process (?\d+): ?[ \t]*\n?", @@ -82,6 +98,9 @@ enumeration would silently drop the shapes it did not anticipate. */ /// : both transports read a bounded window, so a report cut in half at the /// edge is an ordinary consequence of not reading the whole file rather than a fault worth surfacing /// every cycle. It will be read whole on the next pass, because the window overlaps. + /// + /// The one exception is a log stamped in a non-UTC zone, which throws + /// instead: see . /// public static List Extract(string? logBody) { @@ -96,6 +115,7 @@ public static List Extract(string? logBody) { var parsed = FromBlock( match.Groups[1].Value, + match.Groups["zone"].Value, match.Groups["pid"].Value, match.Groups["detail"].Value); @@ -109,16 +129,33 @@ public static List Extract(string? logBody) } /// - /// One report, from its timestamp, victim pid and DETAIL block. Null when the block carries no wait - /// edge, which is the one thing that makes it a deadlock report rather than some other DETAIL. + /// One report, from its log-prefix timestamp and zone, its victim pid and its DETAIL block. Null when + /// the block carries no wait edge, which is the one thing that makes it a deadlock report rather than + /// some other DETAIL. /// - public static ParsedDeadlock? FromBlock(string timestampText, string victimPidText, string? detail) + /// The zone token from the log prefix, which is log_timezone as the + /// server rendered it for this line. Required, and required to mean an offset of zero. + /// The prefix zone is not a zero-offset one, so the + /// timestamp beside it is local rather than UTC and the report cannot be stored (#2993). + public static ParsedDeadlock? FromBlock(string timestampText, string zoneText, string victimPidText, string? detail) { if (string.IsNullOrWhiteSpace(detail)) { return null; } + /* THROWN rather than skipped, and it is the only thing in this parser that is not tolerant. + Everything else a block can be wrong about is read again on the next overlapping pass, so + skipping it costs nothing. This one neither clears itself nor announces itself: the timestamp + below parses PERFECTLY under a non-UTC prefix, AssumeUniversal takes it for UTC, and the row + lands in the wrong hour with nothing anywhere disagreeing. Returning null instead would store no + deadlocks and read as a server that has none, which is the same silent-wrong one layer up. A + refusal the runner can classify is the only outcome that names the setting. */ + if (!IsZeroOffsetLogZone(zoneText)) + { + throw new PgLogTimezoneUnsupportedException(zoneText); + } + if (!DateTime.TryParse( timestampText, CultureInfo.InvariantCulture, @@ -180,6 +217,53 @@ statement headers are absent when the server could not recover the text — a pa GraphText: graph); } + /// + /// Whether a log-prefix zone token means an offset of exactly zero, so the naive timestamp printed + /// beside it is already UTC and needs no conversion. + /// + /// Detection, never conversion. An abbreviation cannot be converted from — CST is + /// US Central, China Standard and Cuba Standard — and that is the good reason the captured zone was + /// never wired up. But "is this offset zero" is a far weaker question than "which zone is this", and + /// the token answers it exactly: three abbreviations are zero by definition, a numeric offset says so + /// arithmetically, and everything else either has an offset or is ambiguous about having one, which for + /// this purpose is the same answer. + /// + /// Per LINE rather than per server, which is why log_timezone is not read from the + /// target. current_setting('log_timezone') describes the collector's connection now; this + /// token was written by the server into the line being parsed, under whatever the setting was then, so + /// it is the better witness of the two for the row it is attached to. On Europe/London they + /// disagree for half the year — winter lines are stamped GMT and really are UTC, and a GUC read + /// would refuse them — and on the managed transport there is no connection to ask at all, because that + /// route receives log TEXT and runs no SQL. + /// + public static bool IsZeroOffsetLogZone(string? zone) + { + if (string.IsNullOrWhiteSpace(zone)) + { + /* Nothing said the timestamp was UTC. Unreachable through Extract, whose pattern requires + the token, and reachable through the collector, which reads the zone from a result column + that can come back NULL. */ + return false; + } + + var token = zone.Trim(); + + /* UT is deliberately absent: 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. */ + if (string.Equals(token, "UTC", StringComparison.OrdinalIgnoreCase) + || string.Equals(token, "GMT", StringComparison.OrdinalIgnoreCase) + || string.Equals(token, "UCT", StringComparison.OrdinalIgnoreCase)) + { + return true; + } + + /* A zone with no abbreviation renders as a numeric offset, and a numerically zero one is UTC by + another spelling. Matched as a SHAPE rather than enumerated, because the rendering carries only + as much precision as the offset needs (+00, +00:00, -0000) and an allowlist that missed a form + would refuse a server that is perfectly UTC. */ + return s_zeroOffset.IsMatch(token); + } + /// /// Each participant's statement, keyed by pid. A statement runs from its Process N: header to the /// next header or the end of the block, because arbitrary user SQL contains newlines and taking one line diff --git a/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs b/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs index 9ef85bb776..5ee44207ab 100644 --- a/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs +++ b/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs @@ -70,8 +70,14 @@ public readonly record struct Row( participant's statement is arbitrary user SQL that can contain newlines, each arriving tab-indented. A blank-line or line-count rule truncates multi-line SQL silently. + ([^ \n]+) for the prefix's ZONE, returned as its own column (#2993). It was matched and discarded + here, and the parser could then only assume the stamp beside it was UTC. [^ \n]+ rather than \w+ + because a zone with no abbreviation renders as a numeric offset (+07) that \w+ cannot match, so + the block matched nothing and the server reported no deadlocks. + The 'n' flag makes ^ match at line starts. Parsing of the block itself is C#, in - PgDeadlockLogParser, so the RDS transport — which receives log TEXT and runs no SQL — shares it. */ + PgDeadlockLogParser, so the RDS transport — which receives log TEXT and runs no SQL — shares it, and + both routes get the same zone refusal from the same code. */ private const string QueryText = @" WITH newest AS ( SELECT name, size @@ -88,12 +94,13 @@ FROM newest AS n ) SELECT m[1] AS occurred_at_text, - m[2] AS victim_pid_text, - m[3] AS detail_body + m[2] AS log_zone_text, + m[3] AS victim_pid_text, + m[4] AS detail_body FROM tail, regexp_matches( tail.body, - '^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) \w+ \[(\d+)\][^\n]*ERROR: deadlock detected\s*\n[^\n]*DETAIL: ((?:[^\n]*\n)(?:\t[^\n]*\n)*)', + '^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+) ([^ \n]+) \[(\d+)\][^\n]*ERROR: deadlock detected\s*\n[^\n]*DETAIL: ((?:[^\n]*\n)(?:\t[^\n]*\n)*)', 'gn') AS m LIMIT 500"; @@ -138,10 +145,15 @@ public override async ValueTask> ReadAsync(DbDataReader reader, Collec while (await reader.ReadAsync(cancellationToken)) { + /* Ordinals track the query's four columns: stamp, zone, victim pid, DETAIL. The zone is + ordinal 1 and reaching the parser is what makes the stamp's meaning checked rather than + assumed; a non-zero-offset one throws out of here, and the worker records the refusal + against log_timezone instead of storing a shifted occurred_at. */ var parsed = PgDeadlockLogParser.FromBlock( reader.IsDBNull(0) ? string.Empty : reader.GetString(0), reader.IsDBNull(1) ? string.Empty : reader.GetString(1), - reader.IsDBNull(2) ? null : reader.GetString(2)); + reader.IsDBNull(2) ? string.Empty : reader.GetString(2), + reader.IsDBNull(3) ? null : reader.GetString(3)); /* A block that will not parse is skipped rather than reported. The window is bounded, so a report cut in half at its edge is ordinary and is read whole on the next overlapping pass. */ diff --git a/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs b/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs new file mode 100644 index 0000000000..ef7deee223 --- /dev/null +++ b/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs @@ -0,0 +1,67 @@ +/* + * Copyright (c) 2026 Erik Darling, Darling Data LLC + * + * This file is part of the SQL Server Performance Monitor. + * + * Licensed under the MIT License. See LICENSE file in the project root for full license information. + */ + +using System; + +namespace PerformanceMonitor.Collectors; + +/// +/// The PostgreSQL server log is timestamped in a zone that is not UTC, so the deadlock reports in it cannot +/// be stored (#2993). +/// +/// Why this refuses rather than converting. The log prefix carries the zone as an +/// ABBREVIATION, and abbreviations are ambiguous: CST is US Central, China Standard and Cuba +/// Standard — three offsets and two hemispheres of daylight saving. There is no correct conversion to make +/// from one, which is presumably why captured the zone and never read +/// it. What the token DOES answer exactly is whether the offset is zero, and that is the only question +/// asked of it here: occurred_at is a naive UTC column, as every other collection on the server is. +/// +/// +/// And why it is not simply skipped. The parser tolerates everything else a block can be wrong +/// about, because both transports read an OVERLAPPING window and a report cut at its edge is whole on the +/// next pass. This is different in both directions: it does not clear itself, and the block PARSES — the +/// timestamp is well formed, the graph is intact, and the only thing wrong with the row is the moment it +/// claims. Stored, it puts every deadlock in the wrong trend bucket and misaligns it against every +/// UTC-keyed collection beside it, with nothing erroring anywhere. Dropped silently, it reads as a server +/// with no deadlocks. Thrown, the runner records the store's non-fatal degradation status with a message +/// naming log_timezone — a setting an operator can change, and on a managed fleet a parameter-group +/// change. +/// +public sealed class PgLogTimezoneUnsupportedException : Exception +{ + /// + /// The setting to change, named in one place so the message and any caller inspecting this cannot + /// disagree about which GUC is at fault. + /// + public const string SettingName = "log_timezone"; + + public PgLogTimezoneUnsupportedException(string? observedZone) + : base(BuildMessage(observedZone)) + => ObservedZone = observedZone; + + /// + /// The zone token the log prefix actually carried, kept alongside the message so a caller can log or + /// group on it without parsing prose back out. + /// + public string? ObservedZone { get; } + + private static string BuildMessage(string? observedZone) + { + var zone = string.IsNullOrWhiteSpace(observedZone) ? "(none)" : observedZone.Trim(); + + return $"The PostgreSQL server log on this target is timestamped '{zone}', which is not a " + + $"zero-offset zone: {SettingName} is not UTC, so every timestamp in its deadlock reports is " + + "local time. Nothing was stored this cycle, and this is NOT 'no deadlocks were detected'. " + + "The reports are refused rather than shifted because a log-prefix zone is an ABBREVIATION " + + "and abbreviations are ambiguous — CST alone is three different zones — so there is no " + + "conversion to apply that would not be a guess, and a guess here produces plausible rows " + + $"stamped at the wrong moment. Set {SettingName} = 'UTC' on the target (on managed " + + "PostgreSQL that is a parameter-group change, and it takes effect on reload rather than " + + "needing a restart); the next collection cycle stores normally."; + } +} From 4135e7a6782f8bb563a2c4460b84dacf6533b5b2 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sat, 5 Sep 2026 07:54:59 -0400 Subject: [PATCH 2/4] Follow the arm count and pin the straddled-window refusal (#2993) 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. --- .../CollectionLogDrainForensicsStoreTests.cs | 7 ++-- Lite.Tests/PgDeadlockLogParserTests.cs | 34 +++++++++++++++++++ .../PgDeadlockLogParser.cs | 16 ++++++++- .../PgDeadlocksCollector.cs | 5 ++- 4 files changed, 57 insertions(+), 5 deletions(-) diff --git a/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs b/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs index cc359bfb13..92d2896e9f 100644 --- a/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs +++ b/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs @@ -329,13 +329,14 @@ bookkeeping into their rows. */ rationale is that a ratio needs a denominator from ordinary rows, not only from failures. */ Assert.DoesNotContain("sweepPeerMaxMs: null", worker, StringComparison.Ordinal); - /* drain STAYS null on those arms: nothing was drained, so there is nothing to describe. */ - Assert.Equal(7, Regex.Matches(worker, @"drain: null").Count); + /* drain STAYS null on those arms: nothing was drained, so there is nothing to describe. + 8 since #2993 added a PERMISSIONS arm for a target whose log_timezone is not UTC. */ + Assert.Equal(8, Regex.Matches(worker, @"drain: null").Count); /* And V110's fetch sums stay null on the same seven arms and for the same reason: no item completed, so no fetch was performed. Counted rather than merely present, so an arm that starts passing a real value - which would mean attributing another run's fetch to a failure row - is a red. */ - Assert.Equal(7, Regex.Matches(worker, @"fetchPhases: null").Count); + Assert.Equal(8, Regex.Matches(worker, @"fetchPhases: null").Count); } /// diff --git a/Lite.Tests/PgDeadlockLogParserTests.cs b/Lite.Tests/PgDeadlockLogParserTests.cs index eae0148132..d020b64a99 100644 --- a/Lite.Tests/PgDeadlockLogParserTests.cs +++ b/Lite.Tests/PgDeadlockLogParserTests.cs @@ -349,6 +349,40 @@ public async Task TheCollectorRefusesWhenItsZoneColumnIsNotUtc() Assert.Equal("EST", ex.ObservedZone); } + /// + /// A window holding a non-UTC block and a readable UTC one refuses the WHOLE read, siblings included. + /// + /// Raised in review on the PR rather than predicted: the throw is per block and unwinds + /// Extract's loop, so a straddled window loses deadlocks that were perfectly storable. It is + /// the accepted trade and this pins it as a DECISION rather than leaving it an accident - 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 then tell a quiet server from a + /// half-collected one. The straddle only arises while a log_timezone change crosses the tail, + /// and the transports read the newest file only, so a rotation clears it. + /// + [Fact] + public void AStraddledWindowRefusesTheWholeRead_NotJustTheOffendingBlock() + { + /* Ordered so the readable block comes FIRST: if the loop returned what it had instead of + unwinding, this would come back with one deadlock and no exception. */ + var straddled = WithLogZone("UTC") + + RealBlock.Replace(" UTC [", " EST [", StringComparison.Ordinal) + .Replace("1549", "1827", StringComparison.Ordinal) + .Replace("1556", "1830", StringComparison.Ordinal); + + Assert.Equal(2, s_blockCount.Matches(straddled).Count); + + var ex = Assert.Throws( + () => PgDeadlockLogParser.Extract(straddled)); + + Assert.Equal("EST", ex.ObservedZone); + } + + /* The fixture's own positive control: without it a straddled slab that had somehow stopped holding + two recognisable blocks would satisfy the refusal above for the wrong reason. */ + private static readonly System.Text.RegularExpressions.Regex s_blockCount = + new(@"ERROR: deadlock detected"); + private static CollectorContext MakeContext() => new() { ServerId = 42, diff --git a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs index a6bad998a8..23d18a58c6 100644 --- a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs +++ b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs @@ -101,6 +101,16 @@ sharing a prefix with a zero one (+0030) cannot match part of itself and pass. * /// /// The one exception is a log stamped in a non-UTC zone, which throws /// instead: see . + /// + /// That throw abandons the WHOLE read, siblings included, and that is the accepted trade + /// rather than an oversight. One log has one log_timezone at any instant, so a window + /// holding both a non-UTC and a UTC stamp only happens while a change to that setting straddles the + /// tail. Storing the UTC half and refusing the rest would leave a partial history from a target we + /// have just declared unreadable, with nothing in the data marking what is missing — the reader could + /// not then tell a quiet server from a half-collected one. A whole-read refusal says one thing, and + /// the runner's row says it. The straddle is bounded by the log itself: both transports read the + /// NEWEST file only, so a rotation clears it, and until then every cycle records the refusal with the + /// setting named rather than going quiet. /// public static List Extract(string? logBody) { @@ -150,7 +160,11 @@ public static List Extract(string? logBody) below parses PERFECTLY under a non-UTC prefix, AssumeUniversal takes it for UTC, and the row lands in the wrong hour with nothing anywhere disagreeing. Returning null instead would store no deadlocks and read as a server that has none, which is the same silent-wrong one layer up. A - refusal the runner can classify is the only outcome that names the setting. */ + refusal the runner can classify is the only outcome that names the setting. + + Per BLOCK, so it abandons the whole read from inside Extract's loop and the collector's row + loop alike. See Extract's remarks for why losing the readable siblings is preferred to storing + a partial history nothing marks as partial. */ if (!IsZeroOffsetLogZone(zoneText)) { throw new PgLogTimezoneUnsupportedException(zoneText); diff --git a/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs b/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs index 5ee44207ab..3a2848f438 100644 --- a/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs +++ b/PerformanceMonitor.Collectors/PgDeadlocksCollector.cs @@ -148,7 +148,10 @@ public override async ValueTask> ReadAsync(DbDataReader reader, Collec /* Ordinals track the query's four columns: stamp, zone, victim pid, DETAIL. The zone is ordinal 1 and reaching the parser is what makes the stamp's meaning checked rather than assumed; a non-zero-offset one throws out of here, and the worker records the refusal - against log_timezone instead of storing a shifted occurred_at. */ + against log_timezone instead of storing a shifted occurred_at. The throw abandons rows + already read in this batch, which is the trade PgDeadlockLogParser.Extract's remarks argue + for: a partial history from a target declared unreadable is worse for the reader than a + refusal that says one thing. */ var parsed = PgDeadlockLogParser.FromBlock( reader.IsDBNull(0) ? string.Empty : reader.GetString(0), reader.IsDBNull(1) ? string.Empty : reader.GetString(1), From 64599928f19e91df31e00f7cfdddec260ba15d26 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sat, 5 Sep 2026 08:08:47 -0400 Subject: [PATCH 3/4] Stop the arm comments carrying their own count (#2993) 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. --- .../Darling.Tests/CollectionLogDrainForensicsStoreTests.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs b/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs index 92d2896e9f..f7ff7fbbd0 100644 --- a/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs +++ b/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs @@ -329,11 +329,11 @@ bookkeeping into their rows. */ rationale is that a ratio needs a denominator from ordinary rows, not only from failures. */ Assert.DoesNotContain("sweepPeerMaxMs: null", worker, StringComparison.Ordinal); - /* drain STAYS null on those arms: nothing was drained, so there is nothing to describe. - 8 since #2993 added a PERMISSIONS arm for a target whose log_timezone is not UTC. */ + /* drain STAYS null on those arms: nothing was drained, so there is nothing to describe. The count + follows the arms - #2993's log_timezone PERMISSIONS arm was the eighth. */ Assert.Equal(8, Regex.Matches(worker, @"drain: null").Count); - /* And V110's fetch sums stay null on the same seven arms and for the same reason: no item completed, + /* And V110's fetch sums stay null on those same arms and for the same reason: no item completed, so no fetch was performed. Counted rather than merely present, so an arm that starts passing a real value - which would mean attributing another run's fetch to a failure row - is a red. */ Assert.Equal(8, Regex.Matches(worker, @"fetchPhases: null").Count); From eee73527a38cc42bb5459d4d23b75e16b3f4ba76 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Sat, 5 Sep 2026 08:21:24 -0400 Subject: [PATCH 4/4] Stop claiming the refusal is bounded on both transports (#2993) 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. --- Lite.Tests/PgDeadlockLogParserTests.cs | 6 +++-- .../PgDeadlockLogParser.cs | 27 ++++++++++++------- .../PgLogTimezoneUnsupportedException.cs | 5 ++-- 3 files changed, 24 insertions(+), 14 deletions(-) diff --git a/Lite.Tests/PgDeadlockLogParserTests.cs b/Lite.Tests/PgDeadlockLogParserTests.cs index d020b64a99..17d03971ba 100644 --- a/Lite.Tests/PgDeadlockLogParserTests.cs +++ b/Lite.Tests/PgDeadlockLogParserTests.cs @@ -357,8 +357,10 @@ public async Task TheCollectorRefusesWhenItsZoneColumnIsNotUtc() /// the accepted trade and this pins it as a DECISION rather than leaving it an accident - 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 then tell a quiet server from a - /// half-collected one. The straddle only arises while a log_timezone change crosses the tail, - /// and the transports read the newest file only, so a rotation clears it. + /// half-collected one. The straddle only arises while a log_timezone change crosses the read. + /// What it costs differs by transport, which 's remarks + /// state: the pg_read_file route re-reads an overlapping tail, while the RDS log-API route is + /// consume-once and loses the readable siblings for the life of its resume marker. /// [Fact] public void AStraddledWindowRefusesTheWholeRead_NotJustTheOffendingBlock() diff --git a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs index 23d18a58c6..36fb26014b 100644 --- a/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs +++ b/PerformanceMonitor.Collectors/PgDeadlockLogParser.cs @@ -102,15 +102,21 @@ sharing a prefix with a zero one (+0030) cannot match part of itself and pass. * /// The one exception is a log stamped in a non-UTC zone, which throws /// instead: see . /// - /// That throw abandons the WHOLE read, siblings included, and that is the accepted trade - /// rather than an oversight. One log has one log_timezone at any instant, so a window - /// holding both a non-UTC and a UTC stamp only happens while a change to that setting straddles the - /// tail. Storing the UTC half and refusing the rest would leave a partial history from a target we - /// have just declared unreadable, with nothing in the data marking what is missing — the reader could - /// not then tell a quiet server from a half-collected one. A whole-read refusal says one thing, and - /// the runner's row says it. The straddle is bounded by the log itself: both transports read the - /// NEWEST file only, so a rotation clears it, and until then every cycle records the refusal with the - /// setting named rather than going quiet. + /// That throw abandons the WHOLE read, siblings included. One log has one + /// log_timezone at any instant, so a window holding both a non-UTC and a UTC stamp only + /// happens while a change to that setting straddles the read. Storing the UTC half and refusing the + /// rest would leave a partial history from a target we have just declared unreadable, with nothing in + /// the data marking what is missing — the reader could not then tell a quiet server from a + /// half-collected one. A whole-read refusal says one thing, and the runner's row says it. + /// + /// What that costs is NOT the same on the two transports, and the difference is the read, not + /// this method. re-reads an overlapping byte-window tail every + /// cycle, so a straddled window there loses nothing permanently — the same text arrives again next + /// cycle, and once the non-UTC lines age out of the window the readable siblings store. The RDS + /// log-API route is CONSUME-ONCE: RdsLogSource.ReadNewestAsync advances and persists its resume + /// marker as a side effect of the fetch, before this parser is reached, so text abandoned here is not + /// re-fetched for the life of that marker and the readable siblings in it are lost. Do not describe + /// this refusal as bounded without saying which transport is meant. /// public static List Extract(string? logBody) { @@ -164,7 +170,8 @@ refusal the runner can classify is the only outcome that names the setting. Per BLOCK, so it abandons the whole read from inside Extract's loop and the collector's row loop alike. See Extract's remarks for why losing the readable siblings is preferred to storing - a partial history nothing marks as partial. */ + a partial history nothing marks as partial — and for why that trade is cheap on the + re-reading transport and NOT cheap on the consume-once one. */ if (!IsZeroOffsetLogZone(zoneText)) { throw new PgLogTimezoneUnsupportedException(zoneText); diff --git a/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs b/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs index ef7deee223..f29b453cad 100644 --- a/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs +++ b/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs @@ -23,8 +23,9 @@ namespace PerformanceMonitor.Collectors; /// /// /// And why it is not simply skipped. The parser tolerates everything else a block can be wrong -/// about, because both transports read an OVERLAPPING window and a report cut at its edge is whole on the -/// next pass. This is different in both directions: it does not clear itself, and the block PARSES — the +/// about, because the pg_read_file transport re-reads an overlapping window and a report cut at its +/// edge is whole on the next pass. This is different in both directions: it does not clear itself, and the +/// block PARSES — the /// timestamp is well formed, the graph is intact, and the only thing wrong with the row is the moment it /// claims. Stored, it puts every deadlock in the wrong trend bucket and misaligns it against every /// UTC-keyed collection beside it, with nothing erroring anywhere. Dropped silently, it reads as a server