Refuse deadlock reports from a non-UTC PostgreSQL log (#2993)

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);
     }
 
     /// <summary>

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;
+
+/// <summary>
+/// #2993, Darling half: a log stamped in a non-UTC zone records as <c>PERMISSIONS</c>, not <c>ERROR</c>
+/// and not a successful empty read.
+///
+/// <para>The refusal itself and every zone decision are pinned in Lite.Tests
+/// (<c>PgDeadlockLogParserTests</c>) 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 <see cref="DarlingLockTimeoutYieldTests"/>: source-level, because there is no way to
+/// reach the arm without a monitored PostgreSQL target.</para>
+///
+/// <para>The status is the load-bearing part. <c>ERROR</c> 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;
+/// <c>PERMISSIONS</c> is the store's non-fatal degradation bucket, and
+/// <c>CollectorRuntimePrecondition</c>'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.</para>
+/// </summary>
+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);
+    }
+
+    /// <summary>
+    /// The <c>pg_read_file</c> 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.
+    /// </summary>
+    [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));
+    }
+}

Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs

@@ -2704,11 +2704,11 @@
            The baseline advances only on SUCCESS, so a failed attempt retries on the next reload rather
            than being recorded as applied. */
         if (_postgres is not null
             && DarlingManagedRoles.ShouldReassertComposeStatementTimeout(
                 view.ComposeStatementTimeoutSeconds, _appliedComposeStatementTimeoutSeconds,
                 config.Postgres.Managed, OperatingSystem.IsWindows()))
         {
             if (await DarlingManagedRoles.ReassertComposeStatementTimeoutAsync(
                     _postgres, view.ComposeStatementTimeoutSeconds, _logger, cancellationToken))
             {
                 _appliedComposeStatementTimeoutSeconds = view.ComposeStatementTimeoutSeconds;
@@ -6149,6 +6149,33 @@
                 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

Darling/PerformanceMonitor.Darling.Service/Targets/RdsDeadlockIngestor.cs

@@ -51,6 +51,11 @@ public RdsDeadlockIngestor(NpgsqlDataSource postgres, RdsLogSource? logs = null,
     /// <param name="host">The target's connection host. A non-RDS host is skipped silently — that target
     /// uses the <c>pg_read_file</c> route instead, and there is nothing to report.</param>
     /// <returns>Rows stored, or zero when this target is not RDS or had nothing new.</returns>
+    /// <exception cref="PgLogTimezoneUnsupportedException">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
+    /// <see cref="RdsLogUnavailableException"/> 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.</exception>
     public async Task<int> 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)

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";
 
+    /// <summary>
+    /// The captured report with its prefix zone SUBSTITUTED, and the zone is the only thing changed.
+    ///
+    /// <para>Synthesised on purpose, and it is what makes the #2993 assertions mean anything: every target
+    /// on the fleet runs <c>log_timezone = UTC</c>, 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.</para>
+    /// </summary>
+    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);
     }
 
+    /// <summary>
+    /// #2993: a log stamped in a non-UTC zone is REFUSED, naming the setting.
+    ///
+    /// <para>Before this, the prefix zone was captured by the pattern and read by nothing, and the stamp
+    /// went through <c>TryParse</c> with <c>AssumeUniversal</c> — 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.</para>
+    /// </summary>
+    [Fact]
+    public void RefusesAReportWhoseLogPrefixIsNotUtc_NamingTheSetting()
+    {
+        var ex = Assert.Throws<PgLogTimezoneUnsupportedException>(
+            () => 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);
+    }
+
+    /// <summary>
+    /// A zone with no abbreviation renders as a NUMERIC offset, and that shape has to be refused too.
+    ///
+    /// <para>It is the case that would have escaped the check by never reaching it: the pattern matched the
+    /// zone as <c>\w+</c>, which matches neither the sign nor the colon, so a <c>+07</c> 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.</para>
+    /// </summary>
+    [Theory]
+    [InlineData("+07")]
+    [InlineData("-03:30")]
+    [InlineData("+0530")]
+    public void RefusesANumericNonZeroOffsetPrefix_RatherThanMatchingNothing(string zone)
+    {
+        var ex = Assert.Throws<PgLogTimezoneUnsupportedException>(
+            () => PgDeadlockLogParser.Extract(WithLogZone(zone)));
+
+        Assert.Equal(zone, ex.ObservedZone);
+    }
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>
+    /// 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. <c>BST</c> and
+    /// <c>CST</c> are here to be REFUSED: they are the ambiguity that makes conversion impossible —
+    /// <c>CST</c> is three zones — and refusing them is the whole trade this fix makes.
+    /// </summary>
+    [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));
+
+    /// <summary>
+    /// The WIRING, not the pattern: the collector's four result columns reach the parser in the right
+    /// order, driven through the real <c>ReadAsync</c>.
+    ///
+    /// <para>An <c>Assert.Contains</c> 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.</para>
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    [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<PgLogTimezoneUnsupportedException>(
+            async () => await PgDeadlocksCollector.Instance.ReadAsync(reader, MakeContext(), CancellationToken.None));
+
+        Assert.Equal("EST", ex.ObservedZone);
+    }
+
+    /// <summary>
+    /// A window holding a non-UTC block and a readable UTC one refuses the WHOLE read, siblings included.
+    ///
+    /// <para>Raised in review on the PR rather than predicted: the throw is per block and unwinds
+    /// <c>Extract</c>'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 <c>log_timezone</c> change crosses the read.
+    /// What it costs differs by transport, which <see cref="PgDeadlockLogParser.Extract"/>'s remarks
+    /// state: the <c>pg_read_file</c> 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.</para>
+    /// </summary>
+    [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<PgLogTimezoneUnsupportedException>(
+            () => 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,