diff --git a/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs b/Darling/Darling.Tests/CollectionLogDrainForensicsStoreTests.cs index cc359bfb13..f7ff7fbbd0 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. 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(7, Regex.Matches(worker, @"fetchPhases: null").Count); + Assert.Equal(8, Regex.Matches(worker, @"fetchPhases: null").Count); } /// 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..17d03971ba 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,189 @@ 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); + } + + /// + /// 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 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() + { + /* 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 9977d91485..36fb26014b 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,25 @@ 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 . + /// + /// 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) { @@ -96,6 +131,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 +145,38 @@ 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. + + 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 — 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); + } + if (!DateTime.TryParse( timestampText, CultureInfo.InvariantCulture, @@ -180,6 +238,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..3a2848f438 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,18 @@ 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. 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), - 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..f29b453cad --- /dev/null +++ b/PerformanceMonitor.Collectors/PgLogTimezoneUnsupportedException.cs @@ -0,0 +1,68 @@ +/* + * 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 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 +/// 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."; + } +}