From d499f1487c1302abda0c1d6538cc4f8d4f8f9147 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Wed, 23 Sep 2026 08:41:00 -0400 Subject: [PATCH] Trace-flag display reads anchor on the collector's newest successful run, not the newest row (#3999) get_trace_flags (MCP), the web viewer's Trace Flags grid, and Lite's equivalent all anchored on capture_time = MAX(capture_time) over trace_flags alone. A capture that finds every flag off writes ZERO rows (DBCC TRACESTATUS(-1) only lists flags that are ON), so that MAX cannot see the 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. Each read now also requires the newest trace_flags row to be at least as new as the newest SUCCESSFUL collection_log run for the trace_flags collector. When a later successful run found nothing on, that comparison fails and the read reports no flags - exact, rather than a stale fallback. A COALESCE floor ('1900-01-01') preserves the old reading when collection_log has no matching row at all (its retention aged past the oldest trace_flags row, or nothing has run yet), so the fix cannot suppress a real result it has no evidence against. Fixed in DarlingCurrentConfigReader.TraceFlagsSql (get_trace_flags), ViewerDataService.Config.TraceFlagsSql (the web viewer), and Lite's LocalDataService.Config.cs GetLatestTraceFlagsAsync (parity). Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01GdmA4ND1wLSqA91ax1m4xv --- .../Darling.Tests/ViewerConfigurationTests.cs | 64 +++++++++++++++++++ .../Mcp/DarlingCurrentConfigReader.cs | 19 +++++- .../ViewerDataService.Config.cs | 14 ++++ Lite/Services/LocalDataService.Config.cs | 13 ++++ 4 files changed, 109 insertions(+), 1 deletion(-) diff --git a/Darling/Darling.Tests/ViewerConfigurationTests.cs b/Darling/Darling.Tests/ViewerConfigurationTests.cs index b3856dd34e..c610c526a8 100644 --- a/Darling/Darling.Tests/ViewerConfigurationTests.cs +++ b/Darling/Darling.Tests/ViewerConfigurationTests.cs @@ -404,6 +404,70 @@ 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. + /// + [Fact] + public async Task TraceFlags_AllOffSinceNewerSuccessfulRun_ReadsNoFlags_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."); + + using var connection = new NpgsqlConnection(connectionString); + await connection.OpenAsync(TestContext.Current.CancellationToken); + await PgMigrations.MigrateAsync(connection, TestContext.Current.CancellationToken); + await DeleteRowsAsync(connection, "trace_flags", TraceFlagsServerId, TestContext.Current.CancellationToken); + await DeleteRowsAsync(connection, "collection_log", TraceFlagsServerId, TestContext.Current.CancellationToken); + + await using var viewer = new ViewerDataService(connectionString!); + + var bodySucceeded = false; + try + { + var flagWasOnAt = TruncateToSeconds(DateTime.UtcNow.AddDays(-2)); + var laterSuccessfulRunFoundNothingAt = flagWasOnAt.AddDays(1); + + await InsertTraceFlagAsync(connection, flagWasOnAt, 1117, status: true, isGlobal: true, isSession: false); + await InsertCollectionLogSuccessAsync(connection, laterSuccessfulRunFoundNothingAt); + + /* 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); + + Assert.Empty(rows); + + bodySucceeded = true; + } + finally + { + await LiveStoreCleanup.RunAsync(connectionString!, bodySucceeded, async (cleanup, cleanupCt) => + { + await DeleteRowsAsync(cleanup, "trace_flags", TraceFlagsServerId, cleanupCt); + await DeleteRowsAsync(cleanup, "collection_log", TraceFlagsServerId, cleanupCt); + }); + } + } + + private static async Task InsertCollectionLogSuccessAsync(NpgsqlConnection connection, DateTime collectionTimeUtc) + { + 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); + command.Parameters.AddWithValue(CollectionIdGenerator.Next()); + command.Parameters.AddWithValue(TraceFlagsServerId); + command.Parameters.AddWithValue("viewer-trace-flags-e2e"); + command.Parameters.AddWithValue(DateTime.SpecifyKind(collectionTimeUtc, DateTimeKind.Unspecified)); + await command.ExecuteNonQueryAsync(TestContext.Current.CancellationToken); + } + private static async Task InsertServerConfigAsync( NpgsqlConnection connection, DateTime captureTimeUtc, string configurationName, long valueConfigured, long valueInUse, bool isDynamic, bool isAdvanced) diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs index 4073e4af0f..ecbc096ec6 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingCurrentConfigReader.cs @@ -161,12 +161,29 @@ public sealed record TraceFlagReadRow(int TraceFlag, bool Status, bool IsGlobal, /// Latest trace-flags snapshot for one server — the viewer's TraceFlagsSql plus the trailing /// capture_time (#3541 A10). $1 server_id. A row exists only while a flag is enabled, so an empty - /// result means no active flags at the last capture — and, having no row, no stamp either. + /// result means no active flags at the last capture — and, having no row, no stamp either. + /// + /// #3999: anchored on the collector's newest SUCCESSFUL run, not the newest row. A capture + /// 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. + /// 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') ORDER BY trace_flag """; diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs index 8ec205d5cb..bf2e1083bb 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Config.cs @@ -78,11 +78,25 @@ FROM v_query_store_health 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. + /// 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') ORDER BY trace_flag """; diff --git a/Lite/Services/LocalDataService.Config.cs b/Lite/Services/LocalDataService.Config.cs index 2a22601b49..5d3f6ef99d 100644 --- a/Lite/Services/LocalDataService.Config.cs +++ b/Lite/Services/LocalDataService.Config.cs @@ -217,6 +217,15 @@ FROM v_database_scoped_config /// /// Gets the latest trace flags snapshot. + /// + /// #3999: anchored on the trace_flags collector's newest SUCCESSFUL run, not the newest row - the + /// Darling twin of this read (DarlingCurrentConfigReader.TraceFlagsSql / + /// 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. /// public async Task> GetLatestTraceFlagsAsync(int serverId) { @@ -227,6 +236,10 @@ 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') ORDER BY trace_flag"; command.Parameters.Add(new DuckDBParameter { Value = serverId });