From 8d88cef85683956583ce534fe425557b92ab48ea Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Wed, 23 Sep 2026 08:52:10 -0400 Subject: [PATCH] Trace-flag reads decide on the newest successful run's row count, not its timestamp, so an ordinary run no longer hides every enabled flag #4030 compared MAX(trace_flags.capture_time) against the newest SUCCESS's collection_time. Darling stamps collection_log when a run ENDS, after its capture rows, so that comparison was false after every ordinary run and hid every enabled flag in get_trace_flags and the viewer grid. Lite stamps at run START, so the same SQL meant something different there. All three reads (Darling MCP, Darling viewer, Lite) now keep the newest capture unless the newest SUCCESS wrote 0 rows. Every capture writes the full list of flags that are on, so 0 means all off. No SUCCESS row, or a NULL count, keeps the pre-fix reading. - Darling live test seeded in the service's real write order (capture, then an end-stamped log): on, all off, a failed run, on again, through BOTH readers. Red-watched: #4030's SQL fails step 1 with Expected [1117], Actual []. - New Lite twin, TraceFlagsLatestRunTests, seeded in Lite's order (log stamped at start). Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv --- .../Darling.Tests/ViewerConfigurationTests.cs | 70 +++++++--- .../Mcp/DarlingCurrentConfigReader.cs | 25 ++-- .../ViewerDataService.Config.cs | 21 +-- Lite.Tests/TraceFlagsLatestRunTests.cs | 126 ++++++++++++++++++ Lite/Services/LocalDataService.Config.cs | 18 ++- 5 files changed, 212 insertions(+), 48 deletions(-) create mode 100644 Lite.Tests/TraceFlagsLatestRunTests.cs diff --git a/Darling/Darling.Tests/ViewerConfigurationTests.cs b/Darling/Darling.Tests/ViewerConfigurationTests.cs index c610c526a8..4799ccc81c 100644 --- a/Darling/Darling.Tests/ViewerConfigurationTests.cs +++ b/Darling/Darling.Tests/ViewerConfigurationTests.cs @@ -11,6 +11,7 @@ using System.Threading.Tasks; using Npgsql; using PerformanceMonitor.Collectors; +using PerformanceMonitor.Darling.Service.Mcp; using PerformanceMonitor.Darling.Storage; using PerformanceMonitor.Darling.Viewer; using Xunit; @@ -405,19 +406,24 @@ await LiveStoreCleanup.RunAsync(connectionString!, bodySucceeded, async (cleanup } /// - /// #3999: the all-off case. A capture that finds every flag off writes ZERO rows to trace_flags - /// (DBCC TRACESTATUS(-1) only ever lists flags that are ON), so the newest ROW can be older than - /// the newest SUCCESSFUL run. Before this fix, capture_time = MAX(capture_time) could not see that - /// the collector had run again and fell back to the stale ON row - reporting a flag enabled days after it - /// (and every other flag) was turned off. Seeded here at the exact shape: one old ON row, then a newer - /// SUCCESS in collection_log with no corresponding trace_flags row at all. + /// #3999: the display reads answer for the collector's newest SUCCESSFUL run. A capture that finds every + /// flag off writes ZERO rows to trace_flags (DBCC TRACESTATUS(-1) only ever lists flags that + /// are ON), so the newest ROW can outlive the state it describes: before this fix the reads fell back to a + /// stale ON row days after every flag was turned off. + /// + /// Seeded in the order the service really writes. A run's capture rows first, then its + /// collection_log row, stamped when the run ENDS (DarlingObservability.LogCollectionAsync uses + /// UtcNow at log time), so an ordinary run's SUCCESS is always a few seconds NEWER than its own capture. + /// The first version of this fix compared those two timestamps and hid every enabled flag after every + /// ordinary run; step 1 is the pin for that. Both readers are asserted: the viewer grid and the MCP + /// reader carry the same SQL. /// [Fact] - public async Task TraceFlags_AllOffSinceNewerSuccessfulRun_ReadsNoFlags_AgainstDevPostgres() + public async Task TraceFlags_AnswerForTheNewestSuccessfulRun_AgainstDevPostgres() { var connectionString = Environment.GetEnvironmentVariable("DARLING_TEST_PG"); Assert.SkipWhen(string.IsNullOrEmpty(connectionString), - "Set DARLING_TEST_PG to a Postgres connection string to run the live trace-flags all-off test."); + "Set DARLING_TEST_PG to a Postgres connection string to run the live trace-flags anchor test."); using var connection = new NpgsqlConnection(connectionString); await connection.OpenAsync(TestContext.Current.CancellationToken); @@ -426,23 +432,40 @@ public async Task TraceFlags_AllOffSinceNewerSuccessfulRun_ReadsNoFlags_AgainstD await DeleteRowsAsync(connection, "collection_log", TraceFlagsServerId, TestContext.Current.CancellationToken); await using var viewer = new ViewerDataService(connectionString!); + await using var postgres = NpgsqlDataSource.Create(connectionString!); + + async Task BothReadersAsync() + { + var viewerFlags = (await viewer.GetLatestTraceFlagsAsync(TraceFlagsServerId)).Select(r => r.TraceFlag).ToArray(); + var mcpFlags = (await DarlingCurrentConfigReader.GetLatestTraceFlagsAsync(postgres, TraceFlagsServerId, TestContext.Current.CancellationToken)) + .Rows.Select(r => r.TraceFlag).ToArray(); + Assert.Equal(viewerFlags, mcpFlags); + return viewerFlags; + } var bodySucceeded = false; try { - var flagWasOnAt = TruncateToSeconds(DateTime.UtcNow.AddDays(-2)); - var laterSuccessfulRunFoundNothingAt = flagWasOnAt.AddDays(1); + var day1 = TruncateToSeconds(DateTime.UtcNow.AddDays(-3)); - await InsertTraceFlagAsync(connection, flagWasOnAt, 1117, status: true, isGlobal: true, isSession: false); - await InsertCollectionLogSuccessAsync(connection, laterSuccessfulRunFoundNothingAt); + /* 1. An ordinary run: 1117 on, captured, then logged SUCCESS 3 s later with its one row. */ + await InsertTraceFlagAsync(connection, day1, 1117, status: true, isGlobal: true, isSession: false); + await InsertCollectionLogSuccessAsync(connection, day1.AddSeconds(3), rowsCollected: 1); + Assert.Equal(new[] { 1117 }, await BothReadersAsync()); - /* The control: without the newer collection_log SUCCESS, the same row still reads (proven by - TraceFlags_LatestCaptureWins_OrderedByFlag_AgainstDevPostgres above with no collection_log row - at all — the COALESCE floor covers that case). This test is the case that row's coverage - cannot reach: a genuinely newer successful capture that stored nothing. */ - var rows = await viewer.GetLatestTraceFlagsAsync(TraceFlagsServerId); + /* 2. The next day every flag is off: a SUCCESS that wrote nothing. The stale 1117 row must not read. */ + await InsertCollectionLogSuccessAsync(connection, day1.AddDays(1).AddSeconds(3), rowsCollected: 0); + Assert.Empty(await BothReadersAsync()); - Assert.Empty(rows); + /* 3. A run that failed after that proves nothing about the flags, so the answer stays "none". */ + await InsertCollectionLogAsync(connection, day1.AddDays(1).AddHours(1), "ERROR", rowsCollected: 0); + Assert.Empty(await BothReadersAsync()); + + /* 4. The day after, 4199 is on: a new capture with its own SUCCESS reads again, and only 4199. */ + var day3 = day1.AddDays(2); + await InsertTraceFlagAsync(connection, day3, 4199, status: true, isGlobal: true, isSession: false); + await InsertCollectionLogSuccessAsync(connection, day3.AddSeconds(3), rowsCollected: 1); + Assert.Equal(new[] { 4199 }, await BothReadersAsync()); bodySucceeded = true; } @@ -456,15 +479,20 @@ await LiveStoreCleanup.RunAsync(connectionString!, bodySucceeded, async (cleanup } } - private static async Task InsertCollectionLogSuccessAsync(NpgsqlConnection connection, DateTime collectionTimeUtc) + private static Task InsertCollectionLogSuccessAsync(NpgsqlConnection connection, DateTime collectionTimeUtc, int rowsCollected) => + InsertCollectionLogAsync(connection, collectionTimeUtc, "SUCCESS", rowsCollected); + + private static async Task InsertCollectionLogAsync(NpgsqlConnection connection, DateTime collectionTimeUtc, string status, int rowsCollected) { using var command = new NpgsqlCommand( - "INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, status) " + - "VALUES ($1, $2, $3, 'trace_flags', $4, 'SUCCESS')", connection); + "INSERT INTO collection_log (log_id, server_id, server_name, collector_name, collection_time, status, rows_collected) " + + "VALUES ($1, $2, $3, 'trace_flags', $4, $5, $6)", connection); command.Parameters.AddWithValue(CollectionIdGenerator.Next()); command.Parameters.AddWithValue(TraceFlagsServerId); command.Parameters.AddWithValue("viewer-trace-flags-e2e"); command.Parameters.AddWithValue(DateTime.SpecifyKind(collectionTimeUtc, DateTimeKind.Unspecified)); + command.Parameters.AddWithValue(status); + command.Parameters.AddWithValue(rowsCollected); await command.ExecuteNonQueryAsync(TestContext.Current.CancellationToken); } diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs index ecbc096ec6..3ef11f2b68 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs @@ -167,23 +167,26 @@ public sealed record TraceFlagReadRow(int TraceFlag, bool Status, bool IsGlobal, /// that finds every flag off writes ZERO rows (DBCC TRACESTATUS(-1) only ever lists flags that are /// ON), so plain capture_time = MAX(capture_time) cannot see that capture at all and silently falls /// back to an older capture that still had a flag on — reporting a flag enabled days or weeks after it (and - /// every other flag) was turned off. The second AND below closes that: it compares the newest row's - /// own timestamp against the newest SUCCESS this collector logged in v_collection_log, and if that - /// successful run is NEWER than the newest row, the run that ran most recently found nothing on, so the - /// whole predicate goes false and the read reports no flags — exact, rather than a stale fallback. The - /// COALESCE floor only matters when collection_log's retention has aged past this collector's - /// oldest trace_flags row (or nothing has run yet), and defaults to the pre-fix reading rather than - /// wrongly suppressing a real row it cannot corroborate. + /// every other flag) was turned off. The second AND below closes that on the ROW COUNT of the newest + /// SUCCESS this collector logged in v_collection_log: every capture writes the full list of flags + /// that are on, so a newest successful run that wrote 0 rows found every flag off, and the read reports + /// none. Timestamps can't decide it: this service stamps a collection_log row when the run ENDS (after its + /// capture rows), Lite stamps it when the run STARTS, so "is the newest success newer than the newest + /// capture" is true after every ordinary run here and would hide every enabled flag. No SUCCESS row, or a + /// NULL count from an old row, keeps the pre-fix reading rather than suppressing a capture it can't + /// corroborate. /// public const string TraceFlagsSql = """ SELECT trace_flag, status, is_global, is_session, capture_time FROM v_trace_flags WHERE server_id = $1 AND capture_time = (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) - AND (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) >= COALESCE( - (SELECT MAX(collection_time) FROM v_collection_log - WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'), - TIMESTAMP '1900-01-01') + AND COALESCE( + (SELECT rows_collected FROM v_collection_log + WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS' + ORDER BY collection_time DESC NULLS LAST + LIMIT 1), + 1) > 0 ORDER BY trace_flag """; diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs index bf2e1083bb..654b9ddfc4 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs @@ -82,21 +82,24 @@ ORDER BY database_name /// #3999: anchored on the trace_flags collector's newest SUCCESSFUL run, not the newest row. A capture /// that finds every flag off writes ZERO rows (DBCC TRACESTATUS(-1) only lists flags that are ON), /// so a plain capture_time = MAX(capture_time) falls back to an older capture that still had a - /// flag on. The second AND compares the newest row's timestamp against the newest SUCCESS this - /// collector logged in v_collection_log; if that run is newer, it found nothing on, and the whole - /// predicate goes false so the read reports no flags rather than a stale one. The COALESCE floor - /// only matters once collection_log's retention has aged past this collector's oldest trace_flags row, - /// and defaults to the pre-fix reading rather than wrongly suppressing a row it cannot corroborate. + /// flag on. The second AND decides on the ROW COUNT of the newest SUCCESS this collector logged + /// in v_collection_log: every capture writes the full list of flags that are on, so 0 rows means + /// every flag was off and the read reports none. Not on timestamps: the service stamps collection_log at + /// a run's END, after its capture rows, so "newest success is newer than the newest capture" holds after + /// every ordinary run and would hide every enabled flag. No SUCCESS row, or a NULL count, keeps the + /// pre-fix reading. DarlingCurrentConfigReader.TraceFlagsSql and Lite's twin carry the same test. /// public const string TraceFlagsSql = """ SELECT trace_flag, status, is_global, is_session FROM v_trace_flags WHERE server_id = $1 AND capture_time = (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) - AND (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) >= COALESCE( - (SELECT MAX(collection_time) FROM v_collection_log - WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'), - TIMESTAMP '1900-01-01') + AND COALESCE( + (SELECT rows_collected FROM v_collection_log + WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS' + ORDER BY collection_time DESC NULLS LAST + LIMIT 1), + 1) > 0 ORDER BY trace_flag """; diff --git a/Lite.Tests/TraceFlagsLatestRunTests.cs b/Lite.Tests/TraceFlagsLatestRunTests.cs new file mode 100644 index 0000000000..c3d3a1b3a6 --- /dev/null +++ b/Lite.Tests/TraceFlagsLatestRunTests.cs @@ -0,0 +1,126 @@ +/* + * 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.Linq; +using System.Threading.Tasks; +using DuckDB.NET.Data; +using PerformanceMonitorLite.Database; +using PerformanceMonitorLite.Services; +using Xunit; + +namespace PerformanceMonitorLite.Tests; + +/// +/// #3999: Lite's trace-flag read answers for the collector's newest SUCCESSFUL run, the twin of Darling's +/// TraceFlags_AnswerForTheNewestSuccessfulRun_AgainstDevPostgres. A capture that finds every flag off +/// writes ZERO rows (DBCC TRACESTATUS(-1) lists only flags that are on), so the newest trace_flags row +/// can outlive the state it describes. The read decides on the newest SUCCESS's rows_collected, never on +/// timestamps. Lite stamps collection_log when a run STARTS and Darling when it ENDS, so no timestamp +/// comparison means the same thing on both; seeded here in Lite's order, log stamp first. +/// +public sealed class TraceFlagsLatestRunTests : IClassFixture, IDisposable +{ + private const int ServerId = 3999; + + private readonly DuckDbInitializer _duckDb; + private DuckDBConnection? _seedConn; + private long _nextId = 1; + + public TraceFlagsLatestRunTests(SharedDuckDbFixture fixture) + { + fixture.ResetData(); + _duckDb = fixture.DuckDb; + } + + public void Dispose() => _seedConn?.Dispose(); + + [Fact] + public async Task TheReadAnswersForTheNewestSuccessfulRun() + { + var service = new LocalDataService(_duckDb); + var day1 = new DateTime(2026, 9, 20, 6, 0, 0, DateTimeKind.Utc); + + async Task FlagsAsync() => + (await service.GetLatestTraceFlagsAsync(ServerId)).Select(r => r.TraceFlag).ToArray(); + + /* 1. An ordinary run: logged at its start, capture 1 s later with 1117 on. */ + await SeedRunAsync(day1, "SUCCESS", rowsCollected: 1); + await SeedTraceFlagAsync(day1.AddSeconds(1), 1117); + Assert.Equal(new[] { 1117 }, await FlagsAsync()); + + /* 2. The next day every flag is off: a SUCCESS that wrote nothing. The stale 1117 row must not read. */ + await SeedRunAsync(day1.AddDays(1), "SUCCESS", rowsCollected: 0); + Assert.Empty(await FlagsAsync()); + + /* 3. A failed run after that proves nothing about the flags, so the answer stays "none". */ + await SeedRunAsync(day1.AddDays(1).AddHours(1), "ERROR", rowsCollected: 0); + Assert.Empty(await FlagsAsync()); + + /* 4. The day after, 4199 is on: a new run with its capture reads again, and only 4199. */ + await SeedRunAsync(day1.AddDays(2), "SUCCESS", rowsCollected: 1); + await SeedTraceFlagAsync(day1.AddDays(2).AddSeconds(1), 4199); + Assert.Equal(new[] { 4199 }, await FlagsAsync()); + } + + [Fact] + public async Task NoRunRecord_KeepsTheNewestCapture() + { + /* Nothing in collection_log (retention aged it out, or nothing has run through the log yet): the read + keeps the newest capture rather than suppressing a row it cannot corroborate. */ + var service = new LocalDataService(_duckDb); + await SeedTraceFlagAsync(new DateTime(2026, 9, 20, 6, 0, 1, DateTimeKind.Utc), 1117); + + Assert.Equal(new[] { 1117 }, (await service.GetLatestTraceFlagsAsync(ServerId)).Select(r => r.TraceFlag).ToArray()); + } + + private async Task SeedConnectionAsync() + { + if (_seedConn is null) + { + _seedConn = _duckDb.CreateConnection(); + await _seedConn.OpenAsync(); + } + return _seedConn; + } + + private async Task SeedRunAsync(DateTime startedUtc, string status, int rowsCollected) + { + using var readLock = _duckDb.AcquireReadLock(); + var connection = await SeedConnectionAsync(); + using var cmd = connection.CreateCommand(); + cmd.CommandText = @" +INSERT INTO collection_log + (log_id, server_id, server_name, collector_name, collection_time, duration_ms, status, error_message, rows_collected) +VALUES ($1, $2, $3, 'trace_flags', $4, 900, $5, NULL, $6)"; + cmd.Parameters.Add(new DuckDBParameter { Value = _nextId++ }); + cmd.Parameters.Add(new DuckDBParameter { Value = ServerId }); + cmd.Parameters.Add(new DuckDBParameter { Value = "TestSrv" }); + cmd.Parameters.Add(new DuckDBParameter { Value = startedUtc }); + cmd.Parameters.Add(new DuckDBParameter { Value = status }); + cmd.Parameters.Add(new DuckDBParameter { Value = rowsCollected }); + await cmd.ExecuteNonQueryAsync(); + } + + private async Task SeedTraceFlagAsync(DateTime captureTimeUtc, int traceFlag) + { + using var readLock = _duckDb.AcquireReadLock(); + var connection = await SeedConnectionAsync(); + using var cmd = connection.CreateCommand(); + cmd.CommandText = @" +INSERT INTO trace_flags + (config_id, capture_time, server_id, server_name, trace_flag, status, is_global, is_session) +VALUES ($1, $2, $3, $4, $5, true, true, false)"; + cmd.Parameters.Add(new DuckDBParameter { Value = _nextId++ }); + cmd.Parameters.Add(new DuckDBParameter { Value = captureTimeUtc }); + cmd.Parameters.Add(new DuckDBParameter { Value = ServerId }); + cmd.Parameters.Add(new DuckDBParameter { Value = "TestSrv" }); + cmd.Parameters.Add(new DuckDBParameter { Value = traceFlag }); + await cmd.ExecuteNonQueryAsync(); + } +} diff --git a/Lite/Services/LocalDataService.Config.cs b/Lite/Services/LocalDataService.Config.cs index 5d3f6ef99d..6c140e6d33 100644 --- a/Lite/Services/LocalDataService.Config.cs +++ b/Lite/Services/LocalDataService.Config.cs @@ -223,9 +223,11 @@ FROM v_database_scoped_config /// ViewerDataService.Config.TraceFlagsSql) carries the same fix, and the reasoning there applies /// verbatim: a capture that finds every flag off writes ZERO rows, so a plain /// capture_time = MAX(capture_time) falls back to an older capture that still had a flag on. The - /// second AND compares the newest row's timestamp against the newest SUCCESS this collector - /// logged in v_collection_log; if that run is newer, it found nothing on, and the whole predicate - /// goes false so the read reports no flags rather than a stale one. + /// second AND decides on the ROW COUNT of the newest SUCCESS this collector logged in + /// v_collection_log: every capture writes the full list of flags that are on, so 0 rows means + /// every flag was off and the read reports none. Not on timestamps: Lite stamps collection_log when a run + /// STARTS and Darling when it ENDS, so no timestamp comparison means the same thing on both. No SUCCESS + /// row, or a NULL count, keeps the pre-fix reading. /// public async Task> GetLatestTraceFlagsAsync(int serverId) { @@ -236,10 +238,12 @@ public async Task> GetLatestTraceFlagsAsync(int serverId) FROM v_trace_flags WHERE server_id = $1 AND capture_time = (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) -AND (SELECT MAX(capture_time) FROM v_trace_flags WHERE server_id = $1) >= COALESCE( - (SELECT MAX(collection_time) FROM v_collection_log - WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS'), - TIMESTAMP '1900-01-01') +AND COALESCE( + (SELECT rows_collected FROM v_collection_log + WHERE server_id = $1 AND collector_name = 'trace_flags' AND status = 'SUCCESS' + ORDER BY collection_time DESC NULLS LAST + LIMIT 1), + 1) > 0 ORDER BY trace_flag"; command.Parameters.Add(new DuckDBParameter { Value = serverId });