From 5482ae0be2ec26116acb74675e6dcf50b6684221 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Tue, 22 Sep 2026 23:48:00 -0400 Subject: [PATCH 1/2] A store with no readable log directory keeps its hourly collector-cost flush (#3971, #3923) The store-log capture's own catch left the re-mask and collector-cost flush on a connection Npgsql had already closed after the capture's 58P01/42501 - lost every hour on a store shaped like the Linux compose image (no log directory at all). The sizing pass shared the outer catch too, so the next statement a store permanently rejects there (#3918 was the last one) could take the whole tick down again. Reopens the connection before the re-mask and the flush run, gives the sizing pass its own narrow catch mirroring the capture's, and pins both from source and against a real store. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv --- .../AlertReadFailureSurfaceTests.cs | 10 +- .../StoreLogSelfMonitoringStoreTests.cs | 43 ++++++- .../StoreSelfMetricsTickRecoveryLiveTests.cs | 105 ++++++++++++++++++ .../DarlingWorker.cs | 39 ++++++- 4 files changed, 188 insertions(+), 9 deletions(-) create mode 100644 Darling/Darling.Tests/StoreSelfMetricsTickRecoveryLiveTests.cs diff --git a/Darling/Darling.Tests/AlertReadFailureSurfaceTests.cs b/Darling/Darling.Tests/AlertReadFailureSurfaceTests.cs index cfb9824817..c9d2246d6a 100644 --- a/Darling/Darling.Tests/AlertReadFailureSurfaceTests.cs +++ b/Darling/Darling.Tests/AlertReadFailureSurfaceTests.cs @@ -943,7 +943,7 @@ private static readonly (string Path, int Counted, int Exempt)[] s_wholeFileScop }; private const int WorkerCountedSites = 10; - private const int WorkerExemptSites = 8; + private const int WorkerExemptSites = 9; /// /// Counted sites tree-wide. ONE numeral with several readers rather than the same number written out at @@ -1013,6 +1013,7 @@ private static readonly (string Path, int Counted, int Exempt)[] s_wholeFileScop ["could not read the store volume free space"] = "a local filesystem read, not a store read", ["could not read the recorded store size"] = "context for the alert text, not the evidence the alert is judged on", ["Store self-metrics sweep did not finish"] = "a metrics write sweep; no alert is judged on its result", + ["so this hour's size rows are missing"] = "a metrics write sweep (#3923); no alert is judged on its result, and the store-log census and collector-cost flush the same tick still run on the connection this narrow catch deliberately leaves open", ["Store log capture failed"] = "a telemetry write sweep (#3021); no alert is judged on its result, and the capture gap it leaves is reported by get_store_log's own denominator", ["Store log: re-masking rows captured before this build failed"] = "a maintenance rewrite of stored store-log text (#3915); no alert is judged on it, it is idempotent and resumes next hour, and until it finishes the store-log reader masks every row on the way out", ["Recently-failed-job check errored"] = "reads the monitored server's msdb on its own connection and timeout", @@ -1191,8 +1192,11 @@ WebTlsCertificateState report the web host publishes - there is no store read to re-announcement at the next restart and never a delivery. 26th since #3915: the store-log re-mask pass, a maintenance rewrite of stored text that resumes next hour, with the reader masking in the meantime. 27th since #3908: the store TimescaleDB self-alert's catch, whose evidence is the version - the bootstrap read before the alert engine existed. */ - Assert.Equal(27, totalExempt); + the bootstrap read before the alert engine existed. 28th since #3923: the sizing pass's own narrow + catch, mirroring the store-log capture's catch beside it - a metrics write sweep whose swallowed + failure costs no alert, and whose whole point is to leave the store-log census and the + collector-cost flush below it running on the connection this catch keeps open. */ + Assert.Equal(28, totalExempt); /* Every exemption in the table is actually used. An exemption for a message that no longer exists is a hole this pin would otherwise keep open indefinitely — the shape that lets a real new catch diff --git a/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs b/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs index a9829a8f27..3a3506017a 100644 --- a/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs +++ b/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs @@ -267,13 +267,35 @@ public void TheSweepRidesTheHourlySelfMetricsTick() Assert.Contains("StoreSelfMetrics.SweepAsync", body, StringComparison.Ordinal); Assert.Contains("StoreLogSweep.SweepAsync", body, StringComparison.Ordinal); - /* And it has its OWN catch, which the two passes either side of it do not. This is the only pass - on the tick whose PRIVILEGE is not guaranteed - reading the log needs pg_read_server_files plus - EXECUTE on pg_read_binary_file, which a bring-your-own store's owner may not have granted - so - sharing the outer catch would let one permanent condition cost the collector-cost flush BELOW it - every hour forever. Asserted by position: a catch has to sit between the two calls. */ + var sizingSweep = body.IndexOf("StoreSelfMetrics.SweepAsync", StringComparison.Ordinal); var logSweep = body.IndexOf("StoreLogSweep.SweepAsync", StringComparison.Ordinal); var costFlush = body.IndexOf("_collectorCost.FlushAsync", StringComparison.Ordinal); + + /* #3923: the sizing pass gets its OWN narrow catch too, ahead of the store-log capture - the same + "cost the flush below it forever" reasoning the capture's catch already carries, hit for real by + #3918 (a catch-all census failing 42703 on TimescaleDB 2.29+) while the sizing pass still shared + the OUTER catch. Position: between the sizing call and the store-log capture, asserted the same + way as the capture's own catch below - a mutation that drops it, or moves it past the capture, + reds here. Filter: excludes a command TIMEOUT (still the outer catch's job) and a connection the + fault already broke (the two passes after it need it live) - the two conditions checked directly + against the catch's own text so a mutation that widens either arm reds too. */ + var sizingCatch = body.IndexOf("catch (PostgresException ex) when", StringComparison.Ordinal); + Assert.True( + sizingCatch > sizingSweep && sizingCatch < logSweep, + "the sizing pass has no catch of its own between it and the store-log capture, so a statement " + + "the store permanently rejects there would cost the store-log census and the collector-cost " + + "flush too"); + + var sizingCatchBody = body[sizingCatch..logSweep]; + Assert.Contains("!PgBaselineProvider.IsCommandTimeout(ex)", sizingCatchBody, StringComparison.Ordinal); + Assert.Contains("connection.State == ConnectionState.Open", sizingCatchBody, StringComparison.Ordinal); + + /* And the store-log capture has its OWN catch, which the two passes either side of it do not. This + is the only pass on the tick whose PRIVILEGE is not guaranteed - reading the log needs + pg_read_server_files plus EXECUTE on pg_read_binary_file, which a bring-your-own store's owner may + not have granted - so sharing the outer catch would let one permanent condition cost the + collector-cost flush BELOW it every hour forever. Asserted by position: a catch has to sit between + the two calls. */ var innerCatch = body.IndexOf("catch (Exception ex) when", logSweep, StringComparison.Ordinal); Assert.True(costFlush > logSweep, "the collector-cost flush no longer follows the store-log sweep"); @@ -282,6 +304,17 @@ on the tick whose PRIVILEGE is not guaranteed - reading the log needs pg_read_se "the store-log sweep has no catch of its own between it and the collector-cost flush, so a " + "store whose role cannot read the log would cost the flush too"); + /* #3971: the passes after that catch need a connection it may have just closed - Npgsql closes THIS + one outright on the capture's ERROR rather than leaving it idle-but-usable. Position: the reopen + has to sit between the store-log catch and the collector-cost flush, so the re-mask in between + (which runs on the same connection) gets it live too. */ + var reopen = body.IndexOf("connection.State != ConnectionState.Open", StringComparison.Ordinal); + Assert.True( + reopen > innerCatch && reopen < costFlush, + "the connection is never checked and reopened between the store-log catch and the " + + "collector-cost flush, so a capture that closed it would take the re-mask and the flush " + + "down too"); + /* No second timer: a new cadence field would put the two series on different grids, which is the thing riding this tick buys. */ Assert.DoesNotContain("_nextStoreLog", worker, StringComparison.Ordinal); diff --git a/Darling/Darling.Tests/StoreSelfMetricsTickRecoveryLiveTests.cs b/Darling/Darling.Tests/StoreSelfMetricsTickRecoveryLiveTests.cs new file mode 100644 index 0000000000..b97e0b19d8 --- /dev/null +++ b/Darling/Darling.Tests/StoreSelfMetricsTickRecoveryLiveTests.cs @@ -0,0 +1,105 @@ +/* + * 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; +using System.Data; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging.Abstractions; +using Npgsql; +using PerformanceMonitor.Darling.Service; +using PerformanceMonitor.Darling.Storage; +using Xunit; + +namespace Darling.Tests; + +/// +/// #3971: a store with no readable server-log directory does not lose the hourly collector-cost flush. +/// +/// The reproduction, against a real store. A fresh PostgreSQL cluster with +/// logging_collector off (the default, and the Linux compose store's shape) has no log +/// directory at all — pg_ls_logdir(), which lists the capture +/// candidates through, fails with 58P01 could not open directory "log" before this test does anything +/// to force it. And Npgsql does not leave the connection idle-but-usable after that ERROR: it closes it +/// outright, which is the fact DarlingWorker.SweepStoreSelfMetricsAsync's next two passes — the +/// store-log re-mask (#3915) and the collector-cost flush (#2674) — ran into every hour, on the same +/// connection, before the fix beside this test. +/// +/// Why this test does not call SweepStoreSelfMetricsAsync itself. That method is a +/// private instance member of a BackgroundService with a full worker's worth of DI behind it, so — +/// like the re-mask pass beside it () — the live behaviour is proven +/// against the real primitives it calls ( and +/// ) on one connection, in the same order, while +/// StoreLogSelfMonitoringStoreTests.TheSweepRidesTheHourlySelfMetricsTick pins that the worker method +/// actually wires the reopen between them. +/// +/// #1776 own-store: it mints and migrates a scratch database through ScratchPostgres, so +/// it is not in the live-postgres collection. +/// +public sealed class StoreSelfMetricsTickRecoveryLiveTests +{ + [Fact] + public async Task AFailedStoreLogCapture_ClosesTheConnection_AndReopeningItLetsTheCollectorCostFlushWrite() + { + var baseConnectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG"); + Assert.SkipWhen(string.IsNullOrWhiteSpace(baseConnectionString), + "Set DARLING_TEST_PG to a superuser connection string to run the #3971 capture-recovery proof " + + "in a scratch database."); + + var ct = TestContext.Current.CancellationToken; + await using var scratch = await ScratchPostgres.CreateAsync(baseConnectionString!, ct); + await using var c = new NpgsqlConnection(scratch.ConnectionString); + await c.OpenAsync(ct); + await PgMigrations.MigrateAsync(c, ct); + + /* The reproduction. No ALTER SYSTEM needed: logging_collector defaults to off, so a fresh cluster + never creates its log directory, which is exactly the Linux compose store's shape (#3971's own + evidence) rather than a condition this test manufactures. */ + var capture = await Assert.ThrowsAsync( + () => StoreLogSweep.SweepAsync(c, DateTime.UtcNow, NullLogger.Instance, ct)); + Assert.Equal("58P01", capture.SqlState); + Assert.Contains("could not open directory", capture.Message, StringComparison.Ordinal); + + /* #3971's central claim: Npgsql does not leave this connection idle-but-usable after that ERROR. If + this ever reads Open on a future Npgsql/PostgreSQL pairing, the reopen this test and the worker + both do below becomes a no-op, not a wrong fix — but the claim itself needs to keep being true, or + the rest of this test proves nothing. */ + Assert.Equal(ConnectionState.Closed, c.State); + + /* The fix (DarlingWorker.SweepStoreSelfMetricsAsync carries the same check): reopen before anything + else on this connection runs. Disable this block (`if (false && ...)`) and the very next + assertion reds with Expected Open / Actual Closed; remove that assertion too and the run reaches + the collector-cost flush below and throws InvalidOperationException: "Connection is not open" — + the exact failure #3971 reported for the re-mask and the collector-cost flush. Both are how this + test was proven to fail on the code before this PR. */ + if (c.State != ConnectionState.Open) + { + await c.OpenAsync(ct); + } + + Assert.Equal(ConnectionState.Open, c.State); + + /* The collector-cost flush still writes its row on the reopened connection — the outcome #3971 says + was lost every hour on a store shaped like this one. */ + var accumulator = new CollectorCostAccumulator(); + accumulator.Record(serverId: 397_100, collectorName: "test_collector_3971", rows: 10, sqlMs: 5, storageMs: 2); + await accumulator.FlushAsync(c, DateTime.UtcNow, NullLogger.Instance, ct); + + await using var read = new NpgsqlCommand( + "SELECT run_count, total_sql_ms, max_sql_ms, total_storage_ms, total_rows " + + "FROM collect.collector_cost WHERE server_id = 397100 AND collector_name = 'test_collector_3971'", + c); + await using var reader = await read.ExecuteReaderAsync(ct); + Assert.True(await reader.ReadAsync(ct), "the collector-cost flush wrote no row for the reopened connection"); + Assert.Equal(1, reader.GetInt32(0)); + Assert.Equal(5L, reader.GetInt64(1)); + Assert.Equal(5L, reader.GetInt64(2)); + Assert.Equal(2L, reader.GetInt64(3)); + Assert.Equal(10L, reader.GetInt64(4)); + Assert.False(await reader.ReadAsync(ct), "more than one row landed for one Record call"); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index b16dfbb42a..ef0073d86e 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -6809,7 +6809,29 @@ could take against a genuinely wedged store. The per-statement CommandTimeout in try { await using var connection = await _postgres!.OpenConnectionAsync(budget.Token); - await StoreSelfMetrics.SweepAsync(connection, _timescaleAvailable, DateTime.UtcNow, _logger, budget.Token); + + /* #3923: its OWN narrow catch, ahead of the store-log capture below and on the same reasoning + that catch already carries - a PostgresException the store permanently rejects here (catalog + drift on a bring-your-own TimescaleDB, a revoked privilege) must not cost the store-log + census or the collector-cost flush below it every hour forever. #3918 was exactly this for + one statement (a catch-all census failing 42703 on TimescaleDB 2.29+); the sizing pass shared + the OUTER catch then, so fixing that one statement left the next one the store rejects able to + take the whole tick down again. Narrower than the capture's catch below: a command TIMEOUT + still falls through to the outer catch (unchanged one-hour-gap handling), and so does a fault + that actually broke the connection - a server-REJECTED statement leaves the session idle and + usable, which is what the two passes after it need. */ + try + { + await StoreSelfMetrics.SweepAsync(connection, _timescaleAvailable, DateTime.UtcNow, _logger, budget.Token); + } + catch (PostgresException ex) when (!PgBaselineProvider.IsCommandTimeout(ex) + && connection.State == ConnectionState.Open) + { + _logger.LogError( + "Store self-metrics sweep failed ({SqlState}), so this hour's size rows are missing; the " + + "store-log census and collector-cost flush on the same tick still run: {Message}", + ex.SqlState, ex.Message); + } /* #3021: the store reading its OWN server log, on the same hourly tick and the same connection. It rides this cadence rather than carrying its own for two reasons. The log grows slowly (a @@ -6841,6 +6863,21 @@ not_collected and names the privilege. */ ex.Message); } + /* #3971: Npgsql closes THIS connection outright on the capture's ERROR rather than leaving it + idle-but-usable - reproduced against a plain PostgreSQL 18.4 store on Npgsql 10.0.3, where a + pg_ls_dir fault (58P01) takes connection.State straight to Closed. The re-mask and the + collector-cost flush below run on this SAME connection, so a store that cannot grant the + capture's privilege, or has no log directory at all (the Linux compose store's shape), lost + both of them every hour before this - get_collector_cost never got a row however long that + store ran. Reopened rather than swapped for a fresh one: this connection came from the pool + through _postgres, so OpenAsync pulls a new physical connection under the same object the + `await using` above already owns and disposes. A capture that succeeded, or failed WITHOUT + closing the connection, finds it already Open here and this is a no-op. */ + if (connection.State != ConnectionState.Open) + { + await connection.OpenAsync(budget.Token); + } + /* #3915: rows stored before this build kept their entries unmasked (an ERROR's STATEMENT line, a DETAIL's key values), for the capture's 400-day retention. Re-masked one bounded slice per tick until the table's end, then not again this process; a new capture is masked on write. Its own From f2d462ceff7fc068c6fcde96baa1e2a7ddede88f Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Tue, 22 Sep 2026 23:51:48 -0400 Subject: [PATCH 2/2] A store-log capture the store will never allow warns once per process, and a Broken connection is closed before the reopen The brief's third item for #3971: 58P01 (no log directory, the Linux compose store's shape) and 42501 (no log read) are store properties, so the capture's catch warns the first time and logs at Debug after that; get_store_log already reports the gap. Any other failure keeps the hourly Warning. The reopen now closes the connection first, because Npgsql refuses to open one that is Broken rather than Closed. Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv --- .../StoreLogSelfMonitoringStoreTests.cs | 8 +++++ .../DarlingWorker.cs | 30 +++++++++++++++---- 2 files changed, 33 insertions(+), 5 deletions(-) diff --git a/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs b/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs index 3a3506017a..bfc2880671 100644 --- a/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs +++ b/Darling/Darling.Tests/StoreLogSelfMonitoringStoreTests.cs @@ -315,6 +315,14 @@ the two calls. */ + "collector-cost flush, so a capture that closed it would take the re-mask and the flush " + "down too"); + /* #3971: a capture the store will never allow (58P01 no log directory, 42501 no log read) warns once + per process, then drops to Debug, inside the capture's own catch. */ + var captureCatch = body.Substring(innerCatch, reopen - innerCatch); + Assert.Contains("PostgresErrorCodes.UndefinedFile", captureCatch, StringComparison.Ordinal); + Assert.Contains("PostgresErrorCodes.InsufficientPrivilege", captureCatch, StringComparison.Ordinal); + Assert.Contains("_storeLogCaptureUnavailableWarned", captureCatch, StringComparison.Ordinal); + Assert.Contains("LogDebug(", captureCatch, StringComparison.Ordinal); + /* No second timer: a new cadence field would put the two series on different grids, which is the thing riding this tick buys. */ Assert.DoesNotContain("_nextStoreLog", worker, StringComparison.Ordinal); diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index ef0073d86e..8ab4f11dfb 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -847,6 +847,12 @@ flip mid-run is picked up by each of them on its next pass with no further wirin private bool _storeLogRemaskDone; + /* #3971: a store-log capture that fails for a reason the store will not change on its own warns once per + process, then logs at Debug: 58P01, no log directory (the Linux compose store logs to stderr and has + none), and 42501, a login without the log read. get_store_log already reports the gap on the read + surface, so the hourly Warning only repeated what nobody was going to change. */ + private bool _storeLogCaptureUnavailableWarned; + /* Stage 4 service self-alerts (collection-stopped, connection lost/restored, capture-down). Built once in RunCollectionLoopAsync over the SAME deliverer/history the shared engine uses, so the self-alerts inherit its delivery/cooldown/restart-replay. Held as a field because the connection @@ -6856,11 +6862,23 @@ not_collected and names the privilege. */ } catch (Exception ex) when (ex is not OperationCanceledException) { - _logger.LogWarning( - "Store log capture failed, so this hour's store-log census is missing (get_store_log " - + "reports the capture gap). Reading the store's own log needs pg_read_server_files and " - + "EXECUTE on pg_read_binary_file; a bring-your-own store may not grant them: {Message}", - ex.Message); + var unavailable = ex is PostgresException + { + SqlState: PostgresErrorCodes.UndefinedFile or PostgresErrorCodes.InsufficientPrivilege, + }; + if (unavailable && _storeLogCaptureUnavailableWarned) + { + _logger.LogDebug("Store log capture is still unavailable: {Message}", ex.Message); + } + else + { + _logger.LogWarning( + "Store log capture failed, so this hour's store-log census is missing (get_store_log " + + "reports the capture gap). Reading the store's own log needs pg_read_server_files and " + + "EXECUTE on pg_read_binary_file; a bring-your-own store may not grant them: {Message}", + ex.Message); + _storeLogCaptureUnavailableWarned |= unavailable; + } } /* #3971: Npgsql closes THIS connection outright on the capture's ERROR rather than leaving it @@ -6875,6 +6893,8 @@ both of them every hour before this - get_collector_cost never got a row however closing the connection, finds it already Open here and this is a no-op. */ if (connection.State != ConnectionState.Open) { + /* A Broken connection must be closed before it can open again; closing a Closed one is a no-op. */ + await connection.CloseAsync(); await connection.OpenAsync(budget.Token); }