From 3966dc93b0ee988dc090d42d1b749242bea8c608 Mon Sep 17 00:00:00 2001 From: Erik Darling <2136037+erikdarlingdata@users.noreply.github.com> Date: Fri, 18 Sep 2026 16:40:28 -0400 Subject: [PATCH 1/9] PostgreSQL's log is read by a classifier now, not by two regexes: errors, connections and lock waits land in pg_log_events off the same tail and the same RDS API the deadlock and plan readers use, redacted with the plan parser's own patterns (#3601) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The server log is the engine's primary event record and Darling read exactly two shapes out of it. This makes the shared part of those two readers explicit — PgServerLogTail is the one spelling of the pg_read_file tailer both siblings now splice byte-for-byte, PgLogEntryAssembler is the prefix/zone/ companion-line assembly done once — and adds the classifier on top: IPgLogFamilyParser is the seam, three families ship with parsers (error, connection, lock_wait), three are recognised and stored under their own name for #3602/#3603 to structure (temp_file, autovacuum, checkpoint). One cursor, every parser on every line, one identity per entry (raw_line_hash) for the overlapping tail to dedupe on. V129 creates collect.pg_log_events exactly as the generator emits it (one index; the family index is a separate rung for V104's reason). Both transports: PgLogEventsCollector (self-hosted; the body crosses the wire so no family's recogniser is spelled twice) and RdsLogEventIngestor (its own RdsLogSource, marker committed after the write). get_pg_log_events reads it with the #3594/#3613 page contract. Retention 30 d, operator-tunable. Censuses moved: 28 PG collectors, 70 collector tables, 71 hypertables (workflows 73/84), 34 get_pg_* tools, 152 tools. --- .github/workflows/build.yml | 8 +- .github/workflows/nightly.yml | 8 +- .../CollectorMeasurementSeamTests.cs | 4 +- .../ConsumedTimestampFrameDisciplineTests.cs | 16 +- .../DarlingPgReadSqlParsesLiveTests.cs | 4 + .../DeltaFamilyIntervalCompletionRungTests.cs | 32 +- .../Darling.Tests/PgLogEventsPipelineTests.cs | 922 ++++++++++++++++++ .../Darling.Tests/PgSchemaGeneratorTests.cs | 7 +- Darling/Darling.Tests/ServerPageTabsTests.cs | 1 + .../DarlingCollectorRunner.cs | 34 + .../DarlingWebEndpoints.cs | 2 + .../DarlingWorker.cs | 14 +- .../Mcp/DarlingMcpHostService.cs | 3 + .../Mcp/DarlingMcpInstructions.cs | 2 +- .../Mcp/DarlingMcpPgLogEventTools.cs | 161 +++ .../Targets/RdsLogEventIngestor.cs | 208 ++++ .../wwwroot/js/pages/server-tabs.js | 32 + .../DarlingPgLogEventReader.cs | 181 ++++ .../PgMigrations.cs | 60 ++ .../StorageVersion.cs | 2 +- .../ViewerDataService.Postgres.cs | 10 + .../ViewerDataService.cs | 31 +- .../ViewerPostgresTabs.cs | 2 +- .../ViewerServerTab.Postgres.cs | 35 + .../ViewerServerTab.xaml | 33 + Darling/README.md | 10 +- .../CrossAppMcpToolInventoryPinTests.cs | 2 + Lite.Tests/LogTailOverlapThresholdPinTests.cs | 25 +- Lite.Tests/PgServerLogPathPinTests.cs | 12 +- .../CollectorCatalog.cs | 4 + .../CollectorEngineCapability.cs | 3 + .../CollectorScheduleDefaults.cs | 19 + .../IPgLogFamilyParser.cs | 120 +++ .../PgDeadlocksCollector.cs | 42 +- PerformanceMonitor.Collectors/PgLogEntry.cs | 95 ++ .../PgLogEntryAssembler.cs | 297 ++++++ PerformanceMonitor.Collectors/PgLogEvent.cs | 86 ++ .../PgLogEventClassifier.cs | 104 ++ .../PgLogEventsCollector.cs | 155 +++ .../PgLogFamilyParsers.cs | 201 ++++ .../PgLogTextRedactor.cs | 119 +++ .../PgPlanCaptureCollector.cs | 62 +- .../PgPlanLogParser.cs | 9 +- .../PgServerLogTail.cs | 102 ++ docs/postgres-first-target-runbook.md | 36 +- 45 files changed, 3162 insertions(+), 153 deletions(-) create mode 100644 Darling/Darling.Tests/PgLogEventsPipelineTests.cs create mode 100644 Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs create mode 100644 Darling/PerformanceMonitor.Darling.Service/Targets/RdsLogEventIngestor.cs create mode 100644 Darling/PerformanceMonitor.Darling.Storage/DarlingPgLogEventReader.cs create mode 100644 PerformanceMonitor.Collectors/IPgLogFamilyParser.cs create mode 100644 PerformanceMonitor.Collectors/PgLogEntry.cs create mode 100644 PerformanceMonitor.Collectors/PgLogEntryAssembler.cs create mode 100644 PerformanceMonitor.Collectors/PgLogEvent.cs create mode 100644 PerformanceMonitor.Collectors/PgLogEventClassifier.cs create mode 100644 PerformanceMonitor.Collectors/PgLogEventsCollector.cs create mode 100644 PerformanceMonitor.Collectors/PgLogFamilyParsers.cs create mode 100644 PerformanceMonitor.Collectors/PgLogTextRedactor.cs create mode 100644 PerformanceMonitor.Collectors/PgServerLogTail.cs diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 4b1b1b7a42..dec9f6e6f4 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -925,8 +925,8 @@ jobs: # # The values are the product's own derivation from the live hypertable count # (TimescaleSupport.HypertableCount = the 62-collector catalog + collection_log = 63): - # timescaledb.max_background_workers = HypertableCount + 2 = 72 - # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 83 + # timescaledb.max_background_workers = HypertableCount + 2 = 73 + # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 84 # Hard-coded here because a workflow cannot call into the product — so # CiClusterWorkerSizingTests parses THIS FILE and fails the build if either number stops # matching the formula as collectors are added, and CiClusterWorkerSizingLiveTests asserts @@ -944,8 +944,8 @@ jobs: Add-Content -Path "$dataDir\postgresql.conf" -Value "shared_preload_libraries = 'timescaledb'" Add-Content -Path "$dataDir\postgresql.conf" -Value "port = 5541" Add-Content -Path "$dataDir\postgresql.conf" -Value "listen_addresses = '127.0.0.1'" - Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 72" - Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 83" + Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 73" + Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 84" & "$bin\pg_ctl.exe" -D $dataDir -l $logFile -w start if ($LASTEXITCODE -ne 0) { if (Test-Path $logFile) { Get-Content $logFile -Tail 50 }; throw "pg_ctl start failed ($LASTEXITCODE)" } & "$bin\createdb.exe" -h 127.0.0.1 -p 5541 -U darling darling diff --git a/.github/workflows/nightly.yml b/.github/workflows/nightly.yml index f37b0d9ea8..6114b598bf 100644 --- a/.github/workflows/nightly.yml +++ b/.github/workflows/nightly.yml @@ -437,8 +437,8 @@ jobs: # customer runs and made scheduler-racing failures luck-of-the-slot instead of reproducible. # Values are the product's own derivation from the live hypertable count # (TimescaleSupport.HypertableCount = the 62-collector catalog + collection_log = 63): - # timescaledb.max_background_workers = HypertableCount + 2 = 72 - # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 83 + # timescaledb.max_background_workers = HypertableCount + 2 = 73 + # max_worker_processes = 3 + (HypertableCount + 2) + 8 = 84 # Kept honest by CiClusterWorkerSizingTests (parses this file against the formula) and # CiClusterWorkerSizingLiveTests (asserts the running cluster serves them). Must configure # the cluster identically to build.yml's darling-pg job: that guard parses the appended @@ -459,8 +459,8 @@ jobs: Add-Content -Path "$dataDir\postgresql.conf" -Value "shared_preload_libraries = 'timescaledb'" Add-Content -Path "$dataDir\postgresql.conf" -Value "port = 5541" Add-Content -Path "$dataDir\postgresql.conf" -Value "listen_addresses = '127.0.0.1'" - Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 72" - Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 83" + Add-Content -Path "$dataDir\postgresql.conf" -Value "timescaledb.max_background_workers = 73" + Add-Content -Path "$dataDir\postgresql.conf" -Value "max_worker_processes = 84" & "$bin\pg_ctl.exe" -D $dataDir -l $logFile -w start if ($LASTEXITCODE -ne 0) { if (Test-Path $logFile) { Get-Content $logFile -Tail 50 }; throw "pg_ctl start failed ($LASTEXITCODE)" } & "$bin\createdb.exe" -h 127.0.0.1 -p 5541 -U darling darling diff --git a/Darling/Darling.Tests/CollectorMeasurementSeamTests.cs b/Darling/Darling.Tests/CollectorMeasurementSeamTests.cs index 6c7ad29224..f00a6ab3e3 100644 --- a/Darling/Darling.Tests/CollectorMeasurementSeamTests.cs +++ b/Darling/Darling.Tests/CollectorMeasurementSeamTests.cs @@ -288,7 +288,7 @@ than in whatever order the last cycle happened to touch them. */ [Fact] public void AnOrdinaryRunLeavesTheColumnNull_ExactlyAsBefore() { - /* 69 collectors measure nothing. None of them may start writing a note. */ + /* 70 collectors measure nothing. None of them may start writing a note. */ Assert.Null(CollectorMeasurementNote.Render(CollectorContext.NoMeasurements)); Assert.Null(CollectorMeasurementNote.Compose(null, CollectorContext.NoMeasurements)); Assert.Null(new CollectorRunResult(12, 34, 56, CollectorContext.NoMeasurements).Note); @@ -435,7 +435,7 @@ An argument it CANNOT resolve FAILS rather than being skipped. That is the direc a skip would silently exempt exactly the case a scanner cannot reason about. WHAT THIS SCAN CANNOT SEE, stated rather than assumed. It reads PerformanceMonitor.Collectors - only - which is where every definition lives (69 concrete ones, flat, one-to-one with + only - which is where every definition lives (70 concrete ones, flat, one-to-one with CollectorCatalog.All), but Measure is public, so a HOST could call it and this would not know. Widening the sweep would be worse rather than better: `.Measure(` is a name this codebase uses heavily for unrelated things - WPF's UIElement.Measure(Size), and the Compose subsystem's diff --git a/Darling/Darling.Tests/ConsumedTimestampFrameDisciplineTests.cs b/Darling/Darling.Tests/ConsumedTimestampFrameDisciplineTests.cs index 08b52bd542..64b054faf1 100644 --- a/Darling/Darling.Tests/ConsumedTimestampFrameDisciplineTests.cs +++ b/Darling/Darling.Tests/ConsumedTimestampFrameDisciplineTests.cs @@ -72,11 +72,12 @@ private enum ClockFrame /* Floors, so a broken walk cannot report a clean bill of health. Measured on dev at cb208f6a4: 66 Timestamp columns over 69 catalog definitions, 49 of them on SqlServer definitions and 17 on - PostgreSql ones. Pinned exactly rather than as a floor because the whole point is a closed census — - a floor would let a column vanish. */ - private const int TimestampColumnCount = 66; + PostgreSql ones; #3601 added pg_log_events.occurred_at, so 67 over 70, 18 PostgreSql. Pinned exactly + rather than as a floor because the whole point is a closed census — a floor would let a column + vanish. */ + private const int TimestampColumnCount = 67; private const int SqlServerTimestampColumnCount = 49; - private const int PostgresTimestampColumnCount = 17; + private const int PostgresTimestampColumnCount = 18; private static IReadOnlyList<(string Table, string Column, string Collector, CollectorTargetEngine Engine)> TimestampColumns() => @@ -92,13 +93,14 @@ a floor would let a column vanish. */ /// The census is the catalog's own columns, and the engine /// split is rather than a name prefix or a hand list. /// - /// The T-SQL classifier below reaches the SqlServer arm ONLY. The 17 PostgreSQL columns are a + /// The T-SQL classifier below reaches the SqlServer arm ONLY. The 18 PostgreSQL columns are a /// different provenance mechanism, not a shortfall of this one: PostgreSQL has no /// column = expression alias form at all (there it is a boolean comparison), so those collectors /// write expression AS column, and their timestamps arrive as timestamptz normalised in /// four different spellings — AT TIME ZONE 'UTC' inline, the same inside an interpolated SQL - /// fragment, a bare min() handled in the reader, and two computed entirely in C# - /// (pg_cpu_utilization.sample_time, pg_deadlocks.occurred_at). Counting them here is what + /// fragment, a bare min() handled in the reader, and three computed entirely in C# + /// (pg_cpu_utilization.sample_time, pg_deadlocks.occurred_at, pg_log_events.occurred_at + /// — the last through the same zone check as the deadlock one, #3601). Counting them here is what /// makes the T-SQL arm's reach a measured fact instead of an implied one. /// [Fact] diff --git a/Darling/Darling.Tests/DarlingPgReadSqlParsesLiveTests.cs b/Darling/Darling.Tests/DarlingPgReadSqlParsesLiveTests.cs index 896e767c80..1b93ef274e 100644 --- a/Darling/Darling.Tests/DarlingPgReadSqlParsesLiveTests.cs +++ b/Darling/Darling.Tests/DarlingPgReadSqlParsesLiveTests.cs @@ -97,6 +97,10 @@ predicate spliced into CurrentLongRunningSessionsSqlTemplate by BuildCurrentLong in the parse-checked population, so the fragment is verified where it is used. */ "DarlingPgSessionStatesReader.BackupUtilitiesFilter", "DarlingPgTableBloatReader.StaleStatisticsChurnRatioSql", + /* #3601: the severity CASE expression, spliced into EventsSql so the read and the tool's label-to-rank + mapping share one spelling. A fragment, not a statement; the query it is spliced into IS in the + parse-checked population, so the fragment is verified where it is used. */ + "DarlingPgLogEventReader.SeverityRankSql", }; private static string? ConnectionString => Environment.GetEnvironmentVariable("DARLING_TEST_PG"); diff --git a/Darling/Darling.Tests/DeltaFamilyIntervalCompletionRungTests.cs b/Darling/Darling.Tests/DeltaFamilyIntervalCompletionRungTests.cs index 0ace3a7bc0..224a8dd603 100644 --- a/Darling/Darling.Tests/DeltaFamilyIntervalCompletionRungTests.cs +++ b/Darling/Darling.Tests/DeltaFamilyIntervalCompletionRungTests.cs @@ -25,10 +25,11 @@ namespace Darling.Tests; /// over, so the calculator's (delta 0, interval 0) "no delta knowable" marker reaches the store from every /// family, and the restart seed can rebuild the one key the store could not reproduce. /// -/// This file carries the "I am the top rung" claims that moved off -/// (V127) when this rung landed, the same handoff that file -/// received from (V126) — a fully-migrated store must map to -/// EXACTLY this version, or the viewer's connect-time gate refuses a store that is actually current. +/// The "I am the top rung" claims this file carried moved to PgLogEventsRungTests (V129) when +/// that rung landed, the same handoff this file received from +/// (V127) and that one from (V126). What stays here is the +/// one-rung-behind half: a store carrying this and not V129 maps to 128, which is the honest answer for it +/// and what makes the upgrade banner correct in both directions. /// public sealed class DeltaFamilyIntervalCompletionRungTests { @@ -36,7 +37,9 @@ public sealed class DeltaFamilyIntervalCompletionRungTests private const int PreviousVersion = 127; - /// This rung's sentinel ordinal in the viewer probe — the newest, so the last argument. + /// This rung's sentinel ordinal in the viewer probe. No longer the last argument — V129 appended + /// its own — so the invariant that outlives the handoff is that the ordinal is FIXED: a later rung + /// appends after it and never shifts it. private const int ProbeOrdinal = 103; private const string IntervalColumn = "sample_interval_seconds"; @@ -58,7 +61,9 @@ public void TheRungIsRegisteredAtTheTopOfADenseLadder() Assert.Equal(StorageVersion.SchemaVersion, PgMigrations.Scripts[^1].Version); Assert.Equal(StorageVersion.SchemaVersion, versions.Max()); - Assert.Equal(RungVersion, StorageVersion.SchemaVersion); + /* One below the top since V129 landed; the "RungVersion == StorageVersion.SchemaVersion" half of + the top-arm claim moved to PgLogEventsRungTests with the top. */ + Assert.True(RungVersion < StorageVersion.SchemaVersion, "V128 is expected to sit below the ladder's top now that V129 has landed"); Assert.Equal(versions.Distinct().OrderBy(v => v), versions); } @@ -283,7 +288,6 @@ public void TheProbeMapsAFullyMigratedStoreToThisTopRung() var viewer = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Viewer", "ViewerDataService.cs"); Assert.Contains($"reader.GetBoolean({ProbeOrdinal})", viewer, StringComparison.Ordinal); - Assert.DoesNotContain($"reader.GetBoolean({ProbeOrdinal + 1})", viewer, StringComparison.Ordinal); Assert.Contains("hasDeltaFamilyIntervalCompletion", viewer, StringComparison.Ordinal); Assert.Equal(StorageVersion.SchemaVersion, ViewerDataService.RequiredStoreSchemaVersion); @@ -292,13 +296,9 @@ public void TheProbeMapsAFullyMigratedStoreToThisTopRung() .GetMethod("MapProbedSchemaVersion", BindingFlags.NonPublic | BindingFlags.Static)!; var arity = method.GetParameters().Length; - /* The top rung's sentinel IS the last argument. */ - Assert.Equal(ProbeOrdinal, arity - 1); - - /* Every sentinel true = a fully-migrated store, which must map to exactly this version. Built by - reflection so the arity tracks the signature. */ - var all = Enumerable.Repeat((object)true, arity).ToArray(); - Assert.Equal(StorageVersion.SchemaVersion, (int)method.Invoke(null, all)!); + /* This rung's sentinel sits strictly BELOW the last argument now that V129 has appended its own; the + "is the last argument" claim moved to PgLogEventsRungTests with the top. */ + Assert.True(ProbeOrdinal < arity - 1, "V128's sentinel is expected to sit below the top rung's now that V129 has landed"); /* This rung's own arm answers for a store that stopped here. Expressed as "false above" rather than as one named ordinal, so a rung landing on top of this one does not quietly turn this case into a @@ -319,8 +319,8 @@ that method — and returns this build's version rather than a literal that coul Assert.True(previousArm >= 0, "the previous rung's arm is gone, so this pin is comparing against nothing"); Assert.True(thisArm < previousArm, "the V128 arm sits below the previous rung's, so a current store maps one rung low"); Assert.Contains( - "return " + StorageVersion.SchemaVersion.ToString(CultureInfo.InvariantCulture) + ";", - viewer[thisArm..], StringComparison.Ordinal); + "return " + RungVersion.ToString(CultureInfo.InvariantCulture) + ";", + viewer[thisArm..previousArm], StringComparison.Ordinal); } /* ---- the writers ---------------------------------------------------------------------------------- */ diff --git a/Darling/Darling.Tests/PgLogEventsPipelineTests.cs b/Darling/Darling.Tests/PgLogEventsPipelineTests.cs new file mode 100644 index 0000000000..0029c85d56 --- /dev/null +++ b/Darling/Darling.Tests/PgLogEventsPipelineTests.cs @@ -0,0 +1,922 @@ +/* + * 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.Collections.Generic; +using System.Globalization; +using System.Linq; +using System.Reflection; +using System.Text.RegularExpressions; +using System.Threading; +using System.Threading.Tasks; +using Amazon.RDS; +using Amazon.RDS.Model; +using Npgsql; +using PerformanceMonitor.Collectors; +using PerformanceMonitor.Common; +using PerformanceMonitor.Darling.Service; +using PerformanceMonitor.Darling.Service.Mcp; +using PerformanceMonitor.Darling.Service.Targets; +using PerformanceMonitor.Darling.Storage; +using PerformanceMonitor.Darling.Viewer; +using Xunit; + +namespace Darling.Tests; + +/// +/// The log-event pipeline (#3601): assembly, the three proving family parsers, the recognised-only +/// families, redaction, the shared tailer, and both transports. +/// +/// Fixtures are real log lines. Every prefix-and-message shape below is what PostgreSQL 16–18 +/// writes at stderr under the two log_line_prefix families the deadlock parser already meets +/// (its own fixtures are the source of the %Q-glued query id and the managed %t:%r:%u@%d:[%p]: +/// prefix). Identifiers are synthesised; shapes are verbatim. +/// +public sealed class PgLogEventsPipelineTests +{ + /* ---- fixtures ------------------------------------------------------------------------------------ */ + + private const string P = "2026-09-18 03:07:12.345 UTC "; + + /// One of everything, self-hosted default prefix, in log order. + private const string SelfHostedLog = + P + "[4102] LOG: connection received: host=192.0.2.10 port=52345\n" + + P + "[4102] LOG: connection authenticated: identity=\"app_rw\" method=scram-sha-256 (/etc/postgresql/pg_hba.conf:117)\n" + + P + "[4102] LOG: connection authorized: user=app_rw database=app_db application_name=psql SSL enabled (protocol=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384, bits=256)\n" + + P + "[4102] LOG: process 4102 still waiting for ShareLock on transaction 809 after 1000.123 ms\n" + + P + "[4102] DETAIL: Process holding the lock: 4099. Wait queue: 4102.\n" + + P + "[4102] CONTEXT: while updating tuple (0,7) in relation \"orders\"\n" + + P + "[4102] STATEMENT: UPDATE orders SET status = 'shipped', note = 'gift for O''Brien' WHERE id = 42 AND customer_id = 1007\n" + + P + "[4102] LOG: process 4102 acquired ShareLock on transaction 809 after 2345.678 ms\n" + + P + "[4102] STATEMENT: UPDATE orders SET status = 'shipped', note = 'gift for O''Brien' WHERE id = 42 AND customer_id = 1007\n" + + P + "[4102] ERROR: duplicate key value violates unique constraint \"customers_email_key\"\n" + + P + "[4102] DETAIL: Key (email)=(someone@example.com) already exists.\n" + + P + "[4102] STATEMENT: INSERT INTO customers (email, name) VALUES ('someone@example.com', 'Someone')\n" + + P + "[4102] LOG: temporary file: path \"base/pgsql_tmp/pgsql_tmp4102.0\", size 4294967296\n" + + P + "[4102] STATEMENT: SELECT * FROM orders ORDER BY created_at\n" + + P + "[3001] LOG: automatic vacuum of table \"app_db.public.orders\": index scans: 1\n" + + "\tpages: 0 removed, 12345 remain, 12345 scanned (100.00% of total)\n" + + "\ttuples: 4567 removed, 890123 remain, 0 are dead but not yet removable\n" + + P + "[2999] LOG: checkpoint starting: time\n" + + P + "[2999] LOG: checkpoint complete: wrote 42 buffers (0.3%); 0 WAL file(s) added, 0 removed, 1 recycled\n" + + P + "[4103] FATAL: password authentication failed for user \"intruder\"\n" + + P + "[4103] DETAIL: Connection matched file \"/etc/postgresql/pg_hba.conf\" line 117: \"host all all 0.0.0.0/0 scram-sha-256\"\n" + + P + "[4102] LOG: disconnection: session time: 0:00:03.412 user=app_rw database=app_db host=192.0.2.10 port=52345\n" + + P + "[1200] LOG: database system is ready to accept connections\n" + + P + "[4104] WARNING: there is already a transaction in progress\n" + + P + "[4105] ERROR: canceling statement due to user request\n" + + P + "[4105] STATEMENT: SELECT pg_sleep(30)\n"; + + /// The managed parameter-group prefix, no fractional seconds, %r and %u@%d before the pid. + private const string ManagedLog = + "2026-09-18 03:07:12 UTC:192.0.2.10(52345):app_rw@app_db:[4102]:ERROR: canceling statement due to statement timeout\n" + + "2026-09-18 03:07:12 UTC:192.0.2.10(52345):app_rw@app_db:[4102]:STATEMENT: SELECT count(*) FROM orders WHERE customer_id = 1007\n" + + "2026-09-18 03:07:13 UTC::@:[3001]:LOG: checkpoint starting: time\n"; + + /// A %e-bearing prefix and a %Q-glued one. + private const string PrefixVariantsLog = + "2026-09-18 03:07:12.345 UTC [4102] 28P01 FATAL: password authentication failed for user \"app_rw\"\n" + + "2026-09-18 03:07:12.345 UTC [1549] 322048460535975151ERROR: deadlock detected\n" + + "2026-09-18 03:07:12.345 UTC [1549] 322048460535975151DETAIL: 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" + + "2026-09-18 03:07:12.345 UTC [1549] 322048460535975151HINT: See server log for query details.\n"; + + private static List Classify(string text) => PgLogEventClassifier.Default.Classify(text); + + /* ---- assembly ------------------------------------------------------------------------------------ */ + + [Fact] + public void TheAssembler_FoldsCompanionLinesAndTabContinuations_IntoOneEntryPerPrimaryLine() + { + var entries = PgLogEntryAssembler.Assemble(SelfHostedLog); + + /* 15 primary lines in the fixture; DETAIL / CONTEXT / STATEMENT / tab lines are folded, not counted. */ + Assert.Equal(15, entries.Count); + + var lockWait = entries.Single(e => e.Message.StartsWith("process 4102 still waiting", StringComparison.Ordinal)); + Assert.Equal("LOG", lockWait.Severity); + Assert.Equal(4102, lockWait.Pid); + Assert.Equal("Process holding the lock: 4099. Wait queue: 4102.", lockWait.Detail); + Assert.Equal("while updating tuple (0,7) in relation \"orders\"", lockWait.Context); + Assert.StartsWith("UPDATE orders SET status = 'shipped'", lockWait.Statement, StringComparison.Ordinal); + Assert.Equal(new DateTime(2026, 9, 18, 3, 7, 12, 345, DateTimeKind.Utc), lockWait.OccurredAtUtc); + Assert.Equal(DateTimeKind.Utc, lockWait.OccurredAtUtc.Kind); + + var vacuum = entries.Single(e => e.Message.StartsWith("automatic vacuum", StringComparison.Ordinal)); + Assert.Contains("\npages: 0 removed, 12345 remain", vacuum.Message, StringComparison.Ordinal); + Assert.Contains("\ntuples: 4567 removed", vacuum.Message, StringComparison.Ordinal); + + /* The raw text is the whole entry, verbatim, and it is what the identity hash is over. */ + Assert.StartsWith(P + "[4102] LOG: process 4102 still waiting", lockWait.RawText, StringComparison.Ordinal); + Assert.Contains(P + "[4102] STATEMENT: UPDATE orders", lockWait.RawText, StringComparison.Ordinal); + } + + [Fact] + public void TheAssembler_ReadsBothPrefixFamilies_AndLiftsUserDatabaseAndSqlStateFromThePrefix() + { + var managed = PgLogEntryAssembler.Assemble(ManagedLog); + Assert.Equal(2, managed.Count); + Assert.Equal("app_rw", managed[0].UserName); + Assert.Equal("app_db", managed[0].DatabaseName); + Assert.Equal(4102, managed[0].Pid); + Assert.Equal(new DateTime(2026, 9, 18, 3, 7, 12, DateTimeKind.Utc), managed[0].OccurredAtUtc); + Assert.StartsWith("SELECT count(*)", managed[0].Statement, StringComparison.Ordinal); + /* A background process renders `@` alone under %u@%d: neither half is a name. */ + Assert.Null(managed[1].UserName); + Assert.Null(managed[1].DatabaseName); + + var variants = PgLogEntryAssembler.Assemble(PrefixVariantsLog); + Assert.Equal(2, variants.Count); + Assert.Equal("28P01", variants[0].SqlState); + Assert.Equal("FATAL", variants[0].Severity); + /* %Q glues the query id to the label: the label is still found, the id is not mistaken for a + SQLSTATE (18 digits, not 5), and the pid is the bracketed one. */ + Assert.Equal("ERROR", variants[1].Severity); + Assert.Equal(1549, variants[1].Pid); + Assert.Null(variants[1].SqlState); + Assert.Equal("deadlock detected", variants[1].Message); + Assert.Contains("Process 1556 waits for ShareLock", variants[1].Detail, StringComparison.Ordinal); + Assert.Equal("See server log for query details.", variants[1].Hint); + } + + [Fact] + public void TheAssembler_DropsTheCutHead_AndTheCutTail() + { + /* The self-hosted tail starts at an arbitrary byte; the RDS chunk ends at one. */ + var cutHead = "tail end of a line that started before the window\n" + P + "[1] ERROR: whole\n"; + Assert.Single(PgLogEntryAssembler.Assemble(cutHead)); + + var cutTail = P + "[1] ERROR: whole\n" + P + "[2] ERROR: half a li"; + var entries = PgLogEntryAssembler.Assemble(cutTail); + Assert.Single(entries); + Assert.Equal("whole", entries[0].Message); + } + + [Fact] + public void TheAssembler_RefusesANonUtcLog_Whole_WithTheDeadlockRoutesException() + { + var local = SelfHostedLog.Replace(" UTC ", " EST ", StringComparison.Ordinal); + var refusal = Assert.Throws(() => PgLogEntryAssembler.Assemble(local)); + Assert.Equal("EST", refusal.ObservedZone); + + /* And the zero-offset spellings the deadlock parser admits are admitted here, because it is the + same method: GMT, UCT, +00, +00:00. */ + foreach (var zone in new[] { "GMT", "UCT", "+00", "+00:00" }) + { + Assert.Equal(15, PgLogEntryAssembler.Assemble(SelfHostedLog.Replace(" UTC ", $" {zone} ", StringComparison.Ordinal)).Count); + } + } + + /* ---- classification ------------------------------------------------------------------------------ */ + + [Fact] + public void TheClassifier_RoutesEveryFamily_AndDropsWhatNoFamilyClaims() + { + var events = Classify(SelfHostedLog); + var byFamily = events.GroupBy(e => e.Family).ToDictionary(g => g.Key, g => g.Count(), StringComparer.Ordinal); + + /* Four connection lines (received, authenticated, authorized, disconnection), two lock-wait lines + (still waiting, acquired), four errors (duplicate key, FATAL auth, WARNING, cancel), one spill, + one autovacuum, two checkpoints. "database system is ready" is claimed by nobody and is dropped. */ + Assert.Equal(4, byFamily[PgLogFamilies.Connection]); + Assert.Equal(2, byFamily[PgLogFamilies.LockWait]); + Assert.Equal(4, byFamily[PgLogFamilies.Error]); + Assert.Equal(1, byFamily[PgLogFamilies.TempFile]); + Assert.Equal(1, byFamily[PgLogFamilies.Autovacuum]); + Assert.Equal(2, byFamily[PgLogFamilies.Checkpoint]); + Assert.Equal(14, events.Count); + Assert.DoesNotContain(events, e => e.Message.Contains("ready to accept", StringComparison.Ordinal)); + Assert.All(events, e => Assert.True(PgLogFamilies.IsKnown(e.Family), e.Family)); + } + + [Fact] + public void TheErrorFamily_IsSeverityFirst_SoAFatalConnectionRefusal_IsAnErrorCarryingItsUser() + { + var fatal = Classify(SelfHostedLog).Single(e => e.Severity == "FATAL"); + Assert.Equal(PgLogFamilies.Error, fatal.Family); + Assert.Equal("intruder", fatal.UserName); + Assert.Equal(5, fatal.SeverityRank); + + /* The %e prefix's SQLSTATE rides along; the message's user is lifted; the deadlock ERROR lands in + the error family beside its full graph in pg_deadlocks. */ + var variants = Classify(PrefixVariantsLog); + Assert.Equal("28P01", variants[0].SqlState); + Assert.Equal("app_rw", variants[0].UserName); + Assert.Equal(PgLogFamilies.Error, variants[1].Family); + Assert.Equal("deadlock detected", variants[1].Message); + } + + [Fact] + public void TheConnectionFamily_LiftsUserDatabaseAndApplication_FromTheMessage() + { + var authorized = Classify(SelfHostedLog).Single(e => e.Message.StartsWith("connection authorized", StringComparison.Ordinal)); + Assert.Equal(PgLogFamilies.Connection, authorized.Family); + Assert.Equal("app_rw", authorized.UserName); + Assert.Equal("app_db", authorized.DatabaseName); + Assert.Equal("psql", authorized.ApplicationName); + + var disconnection = Classify(SelfHostedLog).Single(e => e.Message.StartsWith("disconnection", StringComparison.Ordinal)); + Assert.Equal("app_rw", disconnection.UserName); + Assert.Equal("app_db", disconnection.DatabaseName); + Assert.Contains("session time: 0:00:03.412", disconnection.Message, StringComparison.Ordinal); + } + + [Fact] + public void TheLockWaitFamily_KeepsPidsModesAndDurations_AndFingerprintsTheStatement() + { + var waits = Classify(SelfHostedLog).Where(e => e.Family == PgLogFamilies.LockWait).ToList(); + Assert.Equal(2, waits.Count); + Assert.Equal("process 4102 still waiting for ShareLock on transaction 809 after 1000.123 ms", waits[0].Message); + Assert.Equal("Process holding the lock: 4099. Wait queue: 4102.", waits[0].Detail); + Assert.Equal("process 4102 acquired ShareLock on transaction 809 after 2345.678 ms", waits[1].Message); + + /* The same statement under both lines fingerprints alike — that is the pairing key beside the pid. */ + Assert.NotNull(waits[0].StatementFingerprint); + Assert.Equal(waits[0].StatementFingerprint, waits[1].StatementFingerprint); + Assert.Equal(32, waits[0].StatementFingerprint!.Length); + /* Different entries, different identity. */ + Assert.NotEqual(waits[0].RawLineHash, waits[1].RawLineHash); + } + + [Fact] + public void TheRecognisedOnlyFamilies_AreStoredUnderTheirOwnName_WithNothingLifted() + { + var events = Classify(SelfHostedLog); + var spill = events.Single(e => e.Family == PgLogFamilies.TempFile); + Assert.StartsWith("temporary file: path \"base/pgsql_tmp/pgsql_tmp4102.0\", size 4294967296", spill.Message, StringComparison.Ordinal); + Assert.NotNull(spill.StatementFingerprint); + + var vacuum = events.Single(e => e.Family == PgLogFamilies.Autovacuum); + Assert.StartsWith("automatic vacuum of table \"app_db.public.orders\"", vacuum.Message, StringComparison.Ordinal); + + /* The recognised-only list is exactly the three, and the parsed list exactly the three, and + together with the reserved word they are the vocabulary. */ + Assert.Equal(new[] { "temp_file", "autovacuum", "checkpoint" }, PgLogFamilies.RecognisedOnly); + Assert.Equal(new[] { "error", "connection", "lock_wait" }, PgLogFamilies.Parsed); + Assert.Equal(PgLogFamilies.Parsed.Concat(PgLogFamilies.RecognisedOnly).Append(PgLogFamilies.Other), PgLogFamilies.All); + + /* And the seam has exactly the registration order the interface documents: severity first, then + the LOG-level shapes, then the recognised-only arm LAST so a sibling's parser goes before it. */ + Assert.Equal( + new[] { typeof(PgErrorEventParser), typeof(PgConnectionEventParser), typeof(PgLockWaitEventParser), typeof(PgRecognisedFamilyParser) }, + PgLogEventClassifier.DefaultParsers.Select(p => p.GetType())); + Assert.Equal(typeof(PgRecognisedFamilyParser), PgLogEventClassifier.DefaultParsers[^1].GetType()); + } + + /// A sibling family parser registers ahead of the recognised-only arm and takes its lines out of it — the #3602 / #3603 shape, proven with a stand-in. + [Fact] + public void ASiblingParser_RegisteredAheadOfTheRecognisedArm_TakesItsFamilysLines() + { + var parsers = PgLogEventClassifier.DefaultParsers.ToList(); + parsers.Insert(parsers.Count - 1, new StandInTempFileParser()); + var classifier = new PgLogEventClassifier(parsers); + + var events = classifier.Classify(SelfHostedLog); + var spill = events.Single(e => e.Family == PgLogFamilies.TempFile); + /* The stand-in lifted the database from the statement's context; the generic arm would have left it null. */ + Assert.Equal("from-sibling", spill.DatabaseName); + Assert.Equal(14, events.Count); + } + + private sealed class StandInTempFileParser : IPgLogFamilyParser + { + public string Family => PgLogFamilies.TempFile; + + public bool TryParse(in PgLogEntry entry, out PgLogEvent logEvent) + { + if (entry.Severity != "LOG" || !entry.Message.StartsWith("temporary file: ", StringComparison.Ordinal)) + { + logEvent = default; + return false; + } + + logEvent = PgLogEvent.From(entry, Family, databaseName: "from-sibling"); + return true; + } + } + + /* ---- redaction ----------------------------------------------------------------------------------- */ + + /// The issue's scope note, as a pin: a literal fed in never reaches the row. + [Fact] + public void Redaction_StripsEveryLiteral_BeforeAnythingIsStored() + { + var events = Classify(SelfHostedLog); + + foreach (var e in events) + { + Assert.DoesNotContain("someone@example.com", e.Message + e.Detail + e.StatementFingerprint, StringComparison.Ordinal); + Assert.DoesNotContain("O'Brien", e.Message + e.Detail, StringComparison.Ordinal); + Assert.DoesNotContain("shipped", e.Message + e.Detail, StringComparison.Ordinal); + Assert.DoesNotContain("gift", e.Message + e.Detail, StringComparison.Ordinal); + } + + /* The unique-violation DETAIL's value tuple is the one unquoted value shape in PostgreSQL's prose. */ + var duplicate = events.Single(e => e.Message.StartsWith("duplicate key", StringComparison.Ordinal)); + Assert.Equal("Key (email)=(?) already exists.", duplicate.Detail); + /* Identifiers stay: the constraint name is double-quoted and is not a value. */ + Assert.Equal("duplicate key value violates unique constraint \"customers_email_key\"", duplicate.Message); + + /* The statement is never a column at all: the row type has no member carrying it. */ + Assert.DoesNotContain(typeof(PgLogEvent).GetProperties(), p => p.Name.Contains("Statement", StringComparison.Ordinal) && p.PropertyType == typeof(string) && p.Name != "StatementFingerprint"); + Assert.DoesNotContain(PgLogEventsCollector.Instance.PayloadColumns, c => c.Name is "statement" or "statement_text"); + } + + [Fact] + public void Redaction_IsThePlanParsersOwnPatterns_AppliedAtTwoStrengths() + { + /* Statement: literals and bare numbers go, identifier-glued digits stay — exactly the plan parser's + condition-field rule over SQL text. */ + Assert.Equal( + "UPDATE transactionitems1 SET note = '?' WHERE id = ? AND amount > ?", + PgLogTextRedactor.RedactStatement("UPDATE transactionitems1 SET note = 'it''s' WHERE id = 42 AND amount > 10.5")); + + /* Prose: literals go, numbers stay — a lock wait's numbers are its evidence. */ + Assert.Equal( + "process 4102 still waiting for ShareLock on transaction 809 after 1000.123 ms", + PgLogTextRedactor.RedactMessage("process 4102 still waiting for ShareLock on transaction 809 after 1000.123 ms")); + Assert.Equal("invalid input syntax for type integer: '?'", PgLogTextRedactor.RedactMessage("invalid input syntax for type integer: 'abc'")); + + /* Same shape, different values, one fingerprint; and the fingerprint is over the REDACTED text, so + the raw literal is not even hashed. */ + var a = PgLogTextRedactor.Fingerprint(PgLogTextRedactor.RedactStatement("SELECT * FROM t WHERE id = 1 AND name = 'a'")); + var b = PgLogTextRedactor.Fingerprint(PgLogTextRedactor.RedactStatement("SELECT * FROM t\nWHERE id = 999 AND name = 'zzz'")); + Assert.Equal(a, b); + Assert.Null(PgLogTextRedactor.Fingerprint(null)); + + /* The two regexes are the plan parser's own instances, not copies: the field is internal and this + type reads it. A second spelling is the drift the scope note forbids. */ + var source = RepoFile.ReadRepoFile("PerformanceMonitor.Collectors", "PgLogTextRedactor.cs"); + Assert.Contains("PgPlanLogParser.s_quotedLiteral.Replace", source, StringComparison.Ordinal); + Assert.Contains("PgPlanLogParser.s_bareNumber.Replace", source, StringComparison.Ordinal); + Assert.DoesNotMatch(@"new Regex\(""'\(", source); + } + + /* ---- the self-hosted collector and the shared tailer --------------------------------------------- */ + + /// + /// Extracting the tailer left the two siblings' SHIPPED SQL byte-for-byte what it was: pinned against + /// the text as it stood at the parent commit, reconstructed from the inline constants. + /// + [Fact] + public void TheTailerExtraction_LeftBothSiblingsSqlByteIdentical() + { + const string tail = "\nWITH newest AS (\n SELECT name, size\n FROM pg_catalog.pg_ls_logdir()\n WHERE pg_catalog.current_setting('logging_collector') = 'on'\n ORDER BY modification DESC\n LIMIT 1\n),\ntail AS (\n SELECT pg_catalog.pg_read_file(\n pg_catalog.current_setting('log_directory') || '/' || n.name,\n greatest(n.size - 4194304, 0),\n 4194304) AS body\n FROM newest AS n\n)"; + + const string plansBefore = tail + "\nSELECT\n (m[1])::bigint AS query_id,\n (m[2])::double precision AS duration_ms,\n replace(m[3], chr(9), '') AS plan_json\nFROM tail,\n regexp_matches(\n tail.body,\n '\\[\\d+\\] (-?\\d+) LOG: duration: ([0-9.]+) ms plan:\\s*\\n((?:\\t[^\\n]*\\n)+)',\n 'g') AS m\nUNION ALL\nSELECT NULL::bigint, NULL::double precision, 'logging_collector=off'\nWHERE pg_catalog.current_setting('logging_collector') <> 'on'\nLIMIT 2000"; + + const string deadlocksBefore = tail + "\nSELECT\n m[1] AS occurred_at_text,\n m[2] AS log_zone_text,\n m[3] AS victim_pid_text,\n m[4] AS detail_body\nFROM tail,\n regexp_matches(\n tail.body,\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)*)',\n 'gn') AS m\nUNION ALL\nSELECT 'logging_collector=off', NULL, NULL, NULL\nWHERE pg_catalog.current_setting('logging_collector') <> 'on'\nLIMIT 500"; + + /* Line endings normalised on both sides: the repo's `text=auto eol=crlf` checks the sources out as + CRLF on Windows and this pin's literals are LF, and a verbatim string carries whatever its file + does. PostgreSQL does not care; the pin is about the SQL, not the newline flavour. */ + static string Lf(string sql) => sql.Replace("\r\n", "\n", StringComparison.Ordinal); + + var context = TestContext(); + Assert.Equal(plansBefore, Lf(PgPlanCaptureCollector.Instance.BuildQuery(context).Text)); + Assert.Equal(deadlocksBefore, Lf(PgDeadlocksCollector.Instance.BuildQuery(context).Text)); + + /* And the third reader opens with the same tailer and returns the body whole. */ + var events = Lf(PgLogEventsCollector.Instance.BuildQuery(context).Text); + Assert.StartsWith(tail, events, StringComparison.Ordinal); + Assert.Contains("SELECT tail.body AS log_body", events, StringComparison.Ordinal); + Assert.Contains("'" + PgLoggingCollectorOffException.Marker + "'", events, StringComparison.Ordinal); + Assert.Equal(tail, Lf(PgServerLogTail.TailCteSql)); + } + + [Fact] + public async Task TheCollector_ClassifiesTheBody_ThrowsOnTheMarker_AndWritesTheColumnsInOrder() + { + var definition = PgLogEventsCollector.Instance; + Assert.Equal("pg_log_events", definition.Name); + Assert.Equal("pg_log_events", definition.TargetTable); + Assert.True(definition.AppliesTo(new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql, IsAurora = true })); + Assert.False(definition.RunsPerDatabase(new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql })); + + Assert.Equal( + new[] { "occurred_at", "family", "severity", "sqlstate", "database_name", "user_name", "application_name", "pid", "message", "detail", "statement_fingerprint", "raw_line_hash" }, + definition.PayloadColumns.Select(c => c.Name)); + + var context = TestContext(); + + using var body = new FakeReader(new object?[][] { new object?[] { SelfHostedLog } }); + var rows = await definition.ReadAsync(body, context, CancellationToken.None); + Assert.Equal(14, rows.Count); + + using var marker = new FakeReader(new object?[][] { new object?[] { PgLoggingCollectorOffException.Marker } }); + await Assert.ThrowsAsync(async () => await definition.ReadAsync(marker, context, CancellationToken.None)); + + var writer = new RecordingWriter(); + definition.WritePayload(rows[0], writer, context); + Assert.Equal(definition.PayloadColumns.Count, writer.Values.Count); + Assert.Equal(DateTimeKind.Unspecified, ((DateTime)writer.Values[0]!).Kind); + Assert.Equal(PgLogFamilies.Connection, writer.Values[1]); + Assert.Equal("LOG", writer.Values[2]); + Assert.Equal(4102, writer.Values[7]); + Assert.Equal(rows[0].RawLineHash, writer.Values[11]); + } + + [Fact] + public void TheCollector_IsWiredEverywhereItsSiblingsAre() + { + Assert.Contains(CollectorCatalog.All, d => ReferenceEquals(d, PgLogEventsCollector.Instance)); + Assert.Equal(new CollectorScheduleDefaults.Entry(5, 30), CollectorScheduleDefaults.All["pg_log_events"]); + Assert.Equal(CollectorScheduleDefaults.All["pg_deadlocks"].FrequencyMinutes, CollectorScheduleDefaults.All["pg_log_events"].FrequencyMinutes); + Assert.True(CollectorScheduleDefaults.All["pg_log_events"].RetentionDays < CollectorScheduleDefaults.All["pg_deadlocks"].RetentionDays); + + var worker = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Service", "DarlingWorker.cs"); + Assert.Contains("[\"pg_log_events\"] = (r, s, ct) =>", worker, StringComparison.Ordinal); + Assert.Contains("r.IngestRdsLogEventsAsync(s, ct)", worker, StringComparison.Ordinal); + Assert.Contains("r.RunAsync(PgLogEventsCollector.Instance, s, ct)", worker, StringComparison.Ordinal); + Assert.Matches(@"collectorName is ""pg_deadlocks"" or ""pg_plan_capture"" or ""pg_log_events""", worker); + + Assert.Contains("pg_log_events", RepoFile.ReadRepoFile("PerformanceMonitor.Collectors", "CollectorEngineCapability.cs"), StringComparison.Ordinal); + + /* The two RDS notes are a PAIR and are different — #3017's shape. */ + Assert.NotEqual(DarlingCollectorRunner.RdsLogEventsEmptyNote, DarlingCollectorRunner.RdsLogEventsNotReachedNote); + Assert.Contains("did not look", DarlingCollectorRunner.RdsLogEventsNotReachedNote, StringComparison.Ordinal); + } + + /* ---- the severity ranking agrees across C# and SQL ----------------------------------------------- */ + + [Fact] + public void TheSeverityRank_IsOneOrdering_InCSharpAndInTheReadersSql() + { + foreach (var (label, rank) in new[] { ("PANIC", 6), ("FATAL", 5), ("ERROR", 4), ("WARNING", 3), ("NOTICE", 2), ("INFO", 1), ("LOG", 1) }) + { + Assert.Equal(rank, PgLogEntry.RankOf(label)); + Assert.Matches($@"WHEN '{label}'\s+THEN {rank}\b", DarlingPgLogEventReader.SeverityRankSql); + } + + Assert.Equal(0, PgLogEntry.RankOf("DEBUG1")); + Assert.Equal(0, PgLogEntry.RankOf(null)); + Assert.Contains("ELSE 0", DarlingPgLogEventReader.SeverityRankSql, StringComparison.Ordinal); + + /* The read's page contract (#3594, #3613): the cap is a parameter, the window total is on the same + statement, the dedupe is on the identity column, and the chunk-excluding bound is there. */ + Assert.EndsWith("LIMIT $6", DarlingPgLogEventReader.EventsSql.TrimEnd(), StringComparison.Ordinal); + Assert.DoesNotMatch(@"LIMIT\s+\d", DarlingPgLogEventReader.EventsSql); + Assert.Contains("COUNT(*) OVER ()::int AS window_total", DarlingPgLogEventReader.EventsSql, StringComparison.Ordinal); + Assert.Contains("DISTINCT ON (e.raw_line_hash)", DarlingPgLogEventReader.EventsSql, StringComparison.Ordinal); + Assert.Contains("e.collection_time >= $2", DarlingPgLogEventReader.EventsSql, StringComparison.Ordinal); + } + + /* ---- the tool ------------------------------------------------------------------------------------ */ + + [Fact] + public void TheTool_IsRegistered_Dispatched_Described_AndCounted() + { + var method = typeof(DarlingMcpPgLogEventTools).GetMethods().Single(m => m.GetCustomAttribute()?.Name == "get_pg_log_events"); + var description = method.GetCustomAttribute()!.Description; + Assert.Contains("truncated", description, StringComparison.Ordinal); + Assert.Contains("limit", description, StringComparison.Ordinal); + Assert.Contains("REDACTED", description, StringComparison.Ordinal); + Assert.Contains("log_lock_waits", description, StringComparison.Ordinal); + Assert.Contains("truncated", method.GetParameters().Single(p => p.Name == "limit").GetCustomAttribute()!.Description, StringComparison.Ordinal); + + var host = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Service", "Mcp", "DarlingMcpHostService.cs"); + Assert.Contains(".WithGeminiCompatibleTools()", host, StringComparison.Ordinal); + + var dispatch = DarlingWebEndpoints.BuildReadDispatch(); + Assert.True(dispatch.ContainsKey("get_pg_log_events")); + + var body = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Service", "Mcp", "DarlingMcpPgLogEventTools.cs"); + Assert.Contains("limit + 1", body, StringComparison.Ordinal); + Assert.Contains("page.Rows.Count > limit", body, StringComparison.Ordinal); + Assert.Contains("total_events = page.WindowTotal", body, StringComparison.Ordinal); + Assert.DoesNotContain(">= limit", body, StringComparison.Ordinal); + + /* The instructions' census moved with the tool. */ + var instructions = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Service", "Mcp", "DarlingMcpInstructions.cs"); + Assert.Contains("thirty-four are the PostgreSQL reads", instructions, StringComparison.Ordinal); + } + + /* ---- the RDS transport --------------------------------------------------------------------------- */ + + private const string DeadStore = "Host=127.0.0.1;Port=1;Username=none;Password=none;Database=none;Timeout=1"; + private const string RdsHost = "solo.abc123.us-east-1.rds.amazonaws.com"; + + private sealed class FakeRds : AmazonRDSClient + { + public FakeRds() : base(new Amazon.Runtime.BasicAWSCredentials("a", "b"), Amazon.RegionEndpoint.USEast1) { } + + public List Downloads { get; } = new(); + + public string FirstBody { get; init; } = SelfHostedLog; + + public override Task DescribeDBLogFilesAsync(DescribeDBLogFilesRequest request, CancellationToken cancellationToken = default) + => Task.FromResult(new DescribeDBLogFilesResponse + { + DescribeDBLogFiles = new List { new() { LogFileName = "error/postgresql.log.2026-09-18-03", LastWritten = 9999 } }, + }); + + public override Task DownloadDBLogFilePortionAsync(DownloadDBLogFilePortionRequest request, CancellationToken cancellationToken = default) + { + Downloads.Add(request); + var resumed = request.Marker == "MARKER-1"; + return Task.FromResult(new DownloadDBLogFilePortionResponse + { + LogFileData = resumed ? P + "[1200] LOG: database system is ready to accept connections\n" : FirstBody, + Marker = resumed ? "MARKER-2" : "MARKER-1", + AdditionalDataPending = false, + }); + } + } + + [Fact] + public async Task TheRdsIngestor_DoesNotAdvanceTheMarker_WhenTheStoreWriteFails_OrTheZoneIsRefused() + { + await using var store = NpgsqlDataSource.Create(DeadStore); + + var client = new FakeRds(); + var ingestor = new RdsLogEventIngestor(store, new RdsLogSource(_ => client)); + + var failure = await Assert.ThrowsAnyAsync(() => ingestor.IngestAsync(1, "target-a", RdsHost)); + Assert.IsNotType(failure); + Assert.IsNotType(failure); + await Assert.ThrowsAnyAsync(() => ingestor.IngestAsync(1, "target-a", RdsHost)); + Assert.Equal(2, client.Downloads.Count); + Assert.Null(client.Downloads[1].Marker); + + var local = new FakeRds { FirstBody = SelfHostedLog.Replace(" UTC ", " EST ", StringComparison.Ordinal) }; + var refusing = new RdsLogEventIngestor(store, new RdsLogSource(_ => local)); + await Assert.ThrowsAsync(() => refusing.IngestAsync(1, "target-a", RdsHost)); + await Assert.ThrowsAsync(() => refusing.IngestAsync(1, "target-a", RdsHost)); + Assert.Null(local.Downloads[1].Marker); + + /* A non-RDS host is NOT_REACHED, not zero rows (#3017), and no AWS call is made. */ + var quiet = new FakeRds(); + var notReached = await new RdsLogEventIngestor(store, new RdsLogSource(_ => quiet)).IngestAsync(1, "target-a", "db.internal.example"); + Assert.False(notReached.SourceReached); + Assert.Empty(quiet.Downloads); + } + + /* ---- helpers ------------------------------------------------------------------------------------- */ + + private static CollectorContext TestContext() => new() + { + ServerId = 1, + ServerName = "target-a", + CollectionTime = new DateTime(2026, 9, 18, 3, 10, 0, DateTimeKind.Unspecified), + Deltas = new CollectorDeltaCalculator(), + Target = new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql }, + }; + + private sealed class FakeReader : System.Data.Common.DbDataReader + { + private readonly object?[][] _rows; + private int _index = -1; + + public FakeReader(object?[][] rows) => _rows = rows; + + public override bool Read() => ++_index < _rows.Length; + public override Task ReadAsync(CancellationToken cancellationToken) => Task.FromResult(Read()); + public override bool IsDBNull(int ordinal) => _rows[_index][ordinal] is null; + public override string GetString(int ordinal) => (string)_rows[_index][ordinal]!; + public override object GetValue(int ordinal) => _rows[_index][ordinal]!; + public override int FieldCount => _rows.Length == 0 ? 0 : _rows[0].Length; + public override bool HasRows => _rows.Length > 0; + public override bool IsClosed => false; + public override int RecordsAffected => 0; + public override int Depth => 0; + public override object this[int ordinal] => _rows[_index][ordinal]!; + public override object this[string name] => throw new NotSupportedException(); + public override bool GetBoolean(int ordinal) => (bool)_rows[_index][ordinal]!; + public override byte GetByte(int ordinal) => throw new NotSupportedException(); + public override long GetBytes(int ordinal, long dataOffset, byte[]? buffer, int bufferOffset, int length) => throw new NotSupportedException(); + public override char GetChar(int ordinal) => throw new NotSupportedException(); + public override long GetChars(int ordinal, long dataOffset, char[]? buffer, int bufferOffset, int length) => throw new NotSupportedException(); + public override string GetDataTypeName(int ordinal) => "text"; + public override DateTime GetDateTime(int ordinal) => (DateTime)_rows[_index][ordinal]!; + public override decimal GetDecimal(int ordinal) => (decimal)_rows[_index][ordinal]!; + public override double GetDouble(int ordinal) => (double)_rows[_index][ordinal]!; + public override System.Collections.IEnumerator GetEnumerator() => _rows.GetEnumerator(); + public override Type GetFieldType(int ordinal) => typeof(string); + public override float GetFloat(int ordinal) => (float)_rows[_index][ordinal]!; + public override Guid GetGuid(int ordinal) => (Guid)_rows[_index][ordinal]!; + public override short GetInt16(int ordinal) => (short)_rows[_index][ordinal]!; + public override int GetInt32(int ordinal) => (int)_rows[_index][ordinal]!; + public override long GetInt64(int ordinal) => (long)_rows[_index][ordinal]!; + public override string GetName(int ordinal) => "log_body"; + public override int GetOrdinal(string name) => 0; + public override int GetValues(object[] values) => throw new NotSupportedException(); + public override bool NextResult() => false; + } + + private sealed class RecordingWriter : ICollectorRowWriter + { + public List Values { get; } = new(); + private ICollectorRowWriter Add(object? v) { Values.Add(v); return this; } + public ICollectorRowWriter Value(string? value) => Add(value); + public ICollectorRowWriter Value(long value) => Add(value); + public ICollectorRowWriter Value(long? value) => Add(value); + public ICollectorRowWriter Value(int value) => Add(value); + public ICollectorRowWriter Value(int? value) => Add(value); + public ICollectorRowWriter Value(short value) => Add(value); + public ICollectorRowWriter Value(short? value) => Add(value); + public ICollectorRowWriter Value(double value) => Add(value); + public ICollectorRowWriter Value(double? value) => Add(value); + public ICollectorRowWriter Value(decimal value) => Add(value); + public ICollectorRowWriter Value(decimal? value) => Add(value); + public ICollectorRowWriter Value(bool value) => Add(value); + public ICollectorRowWriter Value(bool? value) => Add(value); + public ICollectorRowWriter Value(DateTime value) => Add(value); + public ICollectorRowWriter Value(DateTime? value) => Add(value); + public ICollectorRowWriter NullValue() => Add(null); + } +} + +/// +/// V129 (#3601): collect.pg_log_events, and the "I am the top rung" claims handed off from +/// (V128) — a fully-migrated store must map to EXACTLY +/// this version, or the viewer's connect-time gate refuses a store that is actually current. +/// +public sealed class PgLogEventsRungTests +{ + private const int RungVersion = 129; + private const int PreviousVersion = 128; + + /// This rung's sentinel ordinal in the viewer probe — the newest, so the last argument. + private const int ProbeOrdinal = 104; + + [Fact] + public void TheRungIsRegisteredAtTheTopOfADenseLadder() + { + var versions = PgMigrations.Scripts.Select(s => s.Version).ToList(); + + Assert.Equal("pg-log-events", PgMigrations.Scripts.Single(s => s.Version == RungVersion).Name); + Assert.Equal(StorageVersion.SchemaVersion, PgMigrations.Scripts[^1].Version); + Assert.Equal(StorageVersion.SchemaVersion, versions.Max()); + Assert.Equal(RungVersion, StorageVersion.SchemaVersion); + Assert.Equal(versions.Distinct().OrderBy(v => v), versions); + } + + /// The rung is the generated schema exactly — one table, one index — for V103's reason; the family index is a later rung. + [Fact] + public void TheRung_IsTheGeneratedSchema_WithOneIndex_AndThirtyDayRetention() + { + var sql = PgMigrations.Scripts.Single(s => s.Version == RungVersion).Sql; + Assert.Contains("CREATE TABLE IF NOT EXISTS collect.pg_log_events (", sql, StringComparison.Ordinal); + Assert.Contains("raw_line_hash text", sql, StringComparison.Ordinal); + Assert.Contains("statement_fingerprint text", sql, StringComparison.Ordinal); + Assert.DoesNotContain("statement text", sql, StringComparison.Ordinal); + Assert.Equal(1, Regex.Matches(sql, "CREATE INDEX").Count); + Assert.Contains("ON collect.pg_log_events(server_id, collection_time);", sql, StringComparison.Ordinal); + + /* The V104 argument for the missing family index is in the rung doc, so the next author knows it is + a separate rung rather than an omission. */ + var source = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Storage", "PgMigrations.cs"); + var start = source.IndexOf("/// V129 —", StringComparison.Ordinal); + var end = source.IndexOf("private const string V129Sql", StringComparison.Ordinal); + Assert.True(start >= 0 && end > start); + var doc = source[start..end]; + Assert.Contains("SEPARATE rung", doc, StringComparison.Ordinal); + Assert.Contains("thirty days", doc, StringComparison.Ordinal); + Assert.Contains("REDACTED", doc, StringComparison.Ordinal); + + Assert.Equal(30, CollectorScheduleDefaults.All["pg_log_events"].RetentionDays); + Assert.Equal(TimescaleSupport.HypertableTables.Count + 1, TimescaleSupport.HypertableCount); + Assert.Contains(TimescaleSupport.HypertableTables, t => t.TargetTable == "pg_log_events"); + } + + [Fact] + public void TheProbeMapsAFullyMigratedStoreToThisTopRung() + { + Assert.Contains("table_name = 'pg_log_events'", ViewerDataService.StoreSchemaProbeSql, StringComparison.Ordinal); + + var viewer = RepoFile.ReadRepoFile("Darling", "PerformanceMonitor.Darling.Viewer", "ViewerDataService.cs"); + Assert.Contains($"reader.GetBoolean({ProbeOrdinal})", viewer, StringComparison.Ordinal); + Assert.DoesNotContain($"reader.GetBoolean({ProbeOrdinal + 1})", viewer, StringComparison.Ordinal); + Assert.Contains("hasPgLogEvents", viewer, StringComparison.Ordinal); + + Assert.Equal(StorageVersion.SchemaVersion, ViewerDataService.RequiredStoreSchemaVersion); + + var method = typeof(ViewerDataService).GetMethod("MapProbedSchemaVersion", BindingFlags.NonPublic | BindingFlags.Static)!; + var arity = method.GetParameters().Length; + + /* The top rung's sentinel IS the last argument. */ + Assert.Equal(ProbeOrdinal, arity - 1); + + var all = Enumerable.Repeat((object)true, arity).ToArray(); + Assert.Equal(StorageVersion.SchemaVersion, (int)method.Invoke(null, all)!); + + var atThisRung = Enumerable.Range(0, arity).Select(i => (object)(i <= ProbeOrdinal)).ToArray(); + Assert.Equal(RungVersion, (int)method.Invoke(null, atThisRung)!); + + var behind = (object[])atThisRung.Clone(); + behind[ProbeOrdinal] = false; + Assert.Equal(PreviousVersion, (int)method.Invoke(null, behind)!); + + var thisArm = viewer.IndexOf("if (hasPgLogEvents)", StringComparison.Ordinal); + var previousArm = viewer.IndexOf("if (hasDeltaFamilyIntervalCompletion)", StringComparison.Ordinal); + Assert.True(thisArm >= 0, "the viewer has no V129 sentinel arm — a fully-migrated store would map one rung low"); + Assert.True(previousArm >= 0); + Assert.True(thisArm < previousArm, "the V129 arm sits below the previous rung's, so a current store maps one rung low"); + Assert.Contains("return " + StorageVersion.SchemaVersion.ToString(CultureInfo.InvariantCulture) + ";", viewer[thisArm..previousArm], StringComparison.Ordinal); + } + + /// The CI cluster workflows carry the product's formula for the new hypertable count — the pin CiClusterWorkerSizingTests holds, restated as the two numbers this rung moved. + [Fact] + public void TheWorkflowsAndTheRunbook_CarryTheNewHypertableCount() + { + var workers = TimescaleSupport.HypertableCount + 2; + var processes = 3 + workers + 8; + Assert.Equal(73, workers); + Assert.Equal(84, processes); + + var runbook = RepoFile.ReadRepoFile("docs", "postgres-first-target-runbook.md"); + Assert.Contains($"today the numbers are {workers} and {processes} for {TimescaleSupport.HypertableCount} hypertables", runbook, StringComparison.Ordinal); + Assert.Contains($"all {TimescaleSupport.HypertableTables.Count} of them, {CollectorCatalog.All.Count(c => c.TargetEngine == CollectorTargetEngine.PostgreSql)} PostgreSQL", runbook, StringComparison.Ordinal); + Assert.Contains("| `get_pg_log_events` |", runbook, StringComparison.Ordinal); + Assert.Contains("| `pg_log_events` | 5 min | 5 min |", runbook, StringComparison.Ordinal); + + var readme = RepoFile.ReadRepoFile("Darling", "README.md"); + Assert.Contains($"Today that is **{workers}** and **{processes}** for {TimescaleSupport.HypertableCount} hypertables", readme, StringComparison.Ordinal); + Assert.Contains("| **V129** — PostgreSQL log events |", readme, StringComparison.Ordinal); + } +} + +/// +/// Gated (DARLING_TEST_PG) live round-trip: the pipeline's rows through the real table via the RDS +/// transport's write, then read back through the real tool with every filter, the page contract observed at +/// the boundary, and the self-hosted overlap deduped. +/// +public sealed class PgLogEventsLivePostgresTests +{ + private const string ServerName = "darling-pg-log-events-e2e"; + private static readonly int ServerId = ServerIdHelper.GetDeterministicHashCode(ServerName); + private static string? ConnectionString => Environment.GetEnvironmentVariable("DARLING_TEST_PG"); + + [Fact] + public async Task ThePipeline_StoresReadsFiltersAndDedupes_AgainstDevPostgres() + { + var cs = ConnectionString; + Assert.SkipWhen(string.IsNullOrEmpty(cs), "Set DARLING_TEST_PG to a Postgres connection string to run the live log-events test."); + + var ct = TestContext.Current.CancellationToken; + using var connection = new NpgsqlConnection(cs); + await connection.OpenAsync(ct); + await PgMigrations.MigrateAsync(connection, ct); + await DarlingMcpTestData.ExecAsync(connection, ct, "DELETE FROM pg_log_events WHERE server_id = $1", ServerId); + await using var postgres = NpgsqlDataSource.Create(cs!); + + try + { + await DarlingMcpTestData.RegisterServerAsync(connection, ServerId, ServerName, ct); + + /* Stamp the fixture inside the window, then write it TWICE through the collector's own COPY path + — the second write is the overlapping self-hosted re-read, and the read must collapse it. */ + var stamp = DateTime.UtcNow.AddMinutes(-3).ToString("yyyy-MM-dd HH:mm:ss.fff", CultureInfo.InvariantCulture); + var body = LogFixture(stamp); + var events = PgLogEventClassifier.Default.Classify(body); + Assert.Equal(14, events.Count); + + await WriteAsync(postgres, events, ct); + await WriteAsync(postgres, events, ct); + + var everything = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, null, null, 100); + JsonAssert.Contains("\"events_returned\": 14", everything); + JsonAssert.Contains("\"total_events\": 14", everything); + JsonAssert.Contains("\"truncated\": false", everything); + JsonAssert.Contains("\"times_seen\": 2", everything); + Assert.DoesNotContain("someone@example.com", everything, StringComparison.Ordinal); + Assert.DoesNotContain("O'Brien", everything, StringComparison.Ordinal); + + /* The boundary pair: limit = N-1 truncated, limit = N not; total_events is the window either way. */ + var cut = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, null, null, 13); + JsonAssert.Contains("\"events_returned\": 13", cut); + JsonAssert.Contains("\"truncated\": true", cut); + JsonAssert.Contains("\"total_events\": 14", cut); + + var errors = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, null, "WARNING", 100); + JsonAssert.Contains("\"events_returned\": 4", errors); + JsonAssert.Contains("\"total_events\": 4", errors); + Assert.DoesNotContain("\"family\": \"connection\"", errors, StringComparison.Ordinal); + + var locks = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, "lock_wait", null, 100); + JsonAssert.Contains("\"events_returned\": 2", locks); + JsonAssert.Contains("\"total_events\": 2", locks); + + var fatal = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, "error", "FATAL", 100); + JsonAssert.Contains("\"events_returned\": 1", fatal); + JsonAssert.Contains("\"user_name\": \"intruder\"", fatal); + + var none = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, "connection", "PANIC", 100); + JsonAssert.Contains("\"status\": \"no_events\"", none); + Assert.Contains("log_connections", none, StringComparison.Ordinal); + + JsonAssert.Contains("\"status\": \"error\"", await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, "nonsense", null, 100)); + JsonAssert.Contains("\"status\": \"error\"", await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 1, null, "SEVERE", 100)); + } + finally + { + await DarlingMcpTestData.ExecAsync(connection, ct, "DELETE FROM pg_log_events WHERE server_id = $1", ServerId); + } + } + + /// + /// The self-hosted route end to end against a REAL target's own log: the collector's shipped SQL + /// (pg_ls_logdir(), pg_read_file, the logging_collector gate) runs on the target, + /// the classifier runs on what came back, the rows go through the collector's COPY into the store, and + /// the tool reads them. Gated on DARLING_TEST_PG_LOG_TARGET — a connection string to a PostgreSQL whose + /// log the login can read (superuser, or the two grants the runbook names) and which has + /// log_lock_waits, log_connections and log_min_messages at WARNING or lower — with the + /// store from DARLING_TEST_PG. The rig that ran this on the way in: one timescale/timescaledb:2.28.1-pg18 + /// container serving as both, with a workload that produced one event of each family first. + /// + [Fact] + public async Task TheSelfHostedCollector_ReadsTheTargetsOwnLog_EndToEnd() + { + var store = ConnectionString; + var target = Environment.GetEnvironmentVariable("DARLING_TEST_PG_LOG_TARGET"); + Assert.SkipWhen(string.IsNullOrEmpty(store) || string.IsNullOrEmpty(target), + "Set DARLING_TEST_PG (store) and DARLING_TEST_PG_LOG_TARGET (a PostgreSQL whose log the login can read) to run the self-hosted end-to-end."); + + var ct = TestContext.Current.CancellationToken; + using var storeConnection = new NpgsqlConnection(store); + await storeConnection.OpenAsync(ct); + await PgMigrations.MigrateAsync(storeConnection, ct); + await DarlingMcpTestData.ExecAsync(storeConnection, ct, "DELETE FROM pg_log_events WHERE server_id = $1", ServerId); + await using var postgres = NpgsqlDataSource.Create(store!); + + try + { + await DarlingMcpTestData.RegisterServerAsync(storeConnection, ServerId, ServerName, ct); + + var definition = PgLogEventsCollector.Instance; + var context = new CollectorContext + { + ServerId = ServerId, ServerName = ServerName, + CollectionTime = DateTime.SpecifyKind(DateTime.UtcNow, DateTimeKind.Unspecified), + Deltas = new CollectorDeltaCalculator(), Target = new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql }, + }; + + List rows; + await using (var targetConnection = new NpgsqlConnection(target)) + { + await targetConnection.OpenAsync(ct); + await using var command = new NpgsqlCommand(definition.BuildQuery(context).Text, targetConnection); + await using var reader = await command.ExecuteReaderAsync(ct); + rows = await definition.ReadAsync(reader, context, ct); + } + + /* The target's log must hold at least one of each parsed family — the rig's workload put them + there — or this is a test of a quiet server. */ + Assert.Contains(rows, r => r.Family == PgLogFamilies.Error); + Assert.Contains(rows, r => r.Family == PgLogFamilies.Connection); + Assert.Contains(rows, r => r.Family == PgLogFamilies.LockWait); + Assert.All(rows, r => Assert.Equal(DateTimeKind.Utc, r.OccurredAtUtc.Kind)); + + await WriteAsync(postgres, rows, ct); + + var page = await DarlingPgLogEventReader.GetEventsAsync(postgres, ServerId, DateTime.UtcNow.AddDays(-1), DateTime.UtcNow.AddMinutes(5), null, 0, 10_000, ct); + Assert.Equal(rows.Select(r => r.RawLineHash).Distinct().Count(), page.WindowTotal); + + var counts = rows.GroupBy(r => r.Family).ToDictionary(g => g.Key, g => g.Count(), StringComparer.Ordinal); + var read = await DarlingMcpPgLogEventTools.GetPgLogEvents(postgres, ServerName, 24, "lock_wait", null, 5); + JsonAssert.Contains("\"family\": \"lock_wait\"", read); + JsonAssert.Contains("\"truncated\": false", read); + System.Console.WriteLine("rig counts per family: " + string.Join(", ", counts.OrderBy(k => k.Key, StringComparer.Ordinal).Select(k => k.Key + "=" + k.Value))); + } + finally + { + await DarlingMcpTestData.ExecAsync(storeConnection, ct, "DELETE FROM pg_log_events WHERE server_id = $1", ServerId); + } + } + + private static string LogFixture(string stamp) + { + var fixture = typeof(PgLogEventsPipelineTests).GetField("SelfHostedLog", BindingFlags.NonPublic | BindingFlags.Static)!.GetRawConstantValue() as string; + return fixture!.Replace("2026-09-18 03:07:12.345", stamp, StringComparison.Ordinal); + } + + private static async Task WriteAsync(NpgsqlDataSource postgres, IReadOnlyList rows, CancellationToken ct) + { + var definition = PgLogEventsCollector.Instance; + var collectionTime = DateTime.SpecifyKind(DateTime.UtcNow, DateTimeKind.Unspecified); + await using var connection = await postgres.OpenConnectionAsync(ct); + var writer = new PgCollectorRowWriter(); + using var importer = await connection.BeginBinaryImportAsync(PgCollectorRowWriter.CopyCommandFor(definition), ct); + writer.Importer = importer; + var context = new CollectorContext + { + ServerId = ServerId, ServerName = ServerName, CollectionTime = collectionTime, + Deltas = new CollectorDeltaCalculator(), Target = new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql }, + }; + foreach (var row in rows) + { + await importer.StartRowAsync(ct); + writer.Value(CollectionIdGenerator.Next()); + writer.Value(collectionTime).Value(ServerId).Value(ServerName); + writer.BeginPayload(); + definition.WritePayload(row, writer, context); + writer.EndPayload(definition.PayloadColumns.Count); + } + await importer.CompleteAsync(ct); + } +} diff --git a/Darling/Darling.Tests/PgSchemaGeneratorTests.cs b/Darling/Darling.Tests/PgSchemaGeneratorTests.cs index ea3501c8a9..7384223e97 100644 --- a/Darling/Darling.Tests/PgSchemaGeneratorTests.cs +++ b/Darling/Darling.Tests/PgSchemaGeneratorTests.cs @@ -47,13 +47,15 @@ Availability Group collectors (#991) = 38, plus plan_correction (#1952 automatic pg_buffer_usage (#2544, what is resident in shared buffers) = 61, plus pg_index_bloat (#2561) and pg_wait_sampling, pg_kernel_stats, pg_predicate_stats (#2603) and pg_plan_capture (#2566) = 66, plus pg_cpu_utilization (#2719, instance CPU via the RDS/Performance Insights API — no SQL route at - all, see its own doc comment) = 69. The catalog is + all, see its own doc comment) = 69, plus + pg_log_events (#3601, the classified server-log pipeline: the third reader of the same log the + deadlock and plan collectors tail, and the first to carry more than one family) = 70. The catalog is deliberately engine-mixed: the schema generator walks it to create tables and one store can hold both engines' data, so splitting it per engine would fragment DDL generation. Dispatch is gated separately, by engine, in CollectorCatalog.AppliesTo(definition, target). */ - Assert.Equal(69, CollectorCatalog.All.Count); + Assert.Equal(70, CollectorCatalog.All.Count); /* Uniqueness is asserted AGAINST THE COUNT rather than against a second literal. The literals here had drifted to 45 while the real figure tracked the count, so the test that exists to catch a @@ -644,6 +646,7 @@ public void EveryPostgresRung_IsIdenticalToTheGeneratedSchema() (102, PgServerConfigCollector.Instance), (103, PgDeadlocksCollector.Instance), (106, PgCpuUtilizationCollector.Instance), + (129, PgLogEventsCollector.Instance), }; /* Every PostgreSQL collector must appear above. One added without a rung listed here would diff --git a/Darling/Darling.Tests/ServerPageTabsTests.cs b/Darling/Darling.Tests/ServerPageTabsTests.cs index 1ff7a3cb4a..e98e5a2e9f 100644 --- a/Darling/Darling.Tests/ServerPageTabsTests.cs +++ b/Darling/Darling.Tests/ServerPageTabsTests.cs @@ -90,6 +90,7 @@ public sealed class ServerPageTabsTests ["get_pg_io_trend"] = "pg_io_stats", ["get_pg_database_trend"] = "pg_database_stats", ["get_pg_deadlock_detail"] = "pg_deadlocks", + ["get_pg_log_events"] = "pg_log_events", ["get_pg_server_config_changes"] = "pg_server_config", ["get_pg_replication_stats"] = "pg_replication_stats", ["get_pg_top_queries"] = "pg_statement_stats", diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs index 16e0a22c4a..13769ba18d 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingCollectorRunner.cs @@ -662,6 +662,7 @@ would starve whichever of the two runs second in a cycle. Each needs its own mar read "the same bounded tail of the same file" - matching the pg_read_file route, where the two collectors' SQL queries already read that tail independently rather than sharing a cursor. */ private RdsDeadlockIngestor? _rdsDeadlocks; + private RdsLogEventIngestor? _rdsLogEvents; /* Own ingestor for the same "one instance per transport" reason as the two above — see RdsCpuIngestor's own doc comment for why it does NOT need the marker-survival treatment @@ -722,6 +723,31 @@ public async Task IngestRdsDeadlocksAsync( RdsIngestNote(outcome, RdsDeadlockLogNotReachedNote, RdsDeadlockLogEmptyNote)); } + /// + /// Classified log events for Aurora and RDS Postgres, read from the RDS log API (#3601) — the managed + /// half of the log-event pipeline, dispatched where pg_log_events' pg_read_file route + /// cannot run. Same shape, same outcome vocabulary and same note pair as + /// ; the classifier it feeds is the one the self-hosted collector + /// feeds, so the two transports store identical rows for identical text. + /// + public async Task IngestRdsLogEventsAsync( + ServerRuntime server, CancellationToken cancellationToken) + { + _rdsLogEvents ??= new RdsLogEventIngestor(_postgres, logger: _logger); + + var host = new NpgsqlConnectionStringBuilder(server.ConnectionString).Host ?? string.Empty; + + var started = Stopwatch.GetTimestamp(); + + var outcome = await _rdsLogEvents.IngestAsync( + server.ServerId, server.StorageName, host, cancellationToken); + + var elapsedMs = (long)Stopwatch.GetElapsedTime(started).TotalMilliseconds; + + return new CollectorRunResult(outcome.Rows, 0, elapsedMs, CollectorContext.NoMeasurements, + RdsIngestNote(outcome, RdsLogEventsNotReachedNote, RdsLogEventsEmptyNote)); + } + /// /// Instance CPU for Aurora and RDS Postgres, read from the AWS Performance Insights API (#2719) — the /// third "reach the target a different way" collector alongside and @@ -781,6 +807,14 @@ No host is interpolated into any of them. collection_log is read by operators an "this target's host is not an RDS or Aurora endpoint, so no RDS log was requested and no deadlock " + "capture was attempted - this cycle did not look"; + /// The log was read and no line in it classified to a family (#3601). + internal const string RdsLogEventsEmptyNote = "no new classifiable log events in the RDS log window"; + + /// The log was never opened: this host is not an RDS or Aurora endpoint. + internal const string RdsLogEventsNotReachedNote = + "this target's host is not an RDS or Aurora endpoint, so no RDS log was requested and no log-event " + + "capture was attempted - this cycle did not look"; + /// Performance Insights answered and had no new CPU sample. internal const string PiCpuEmptyNote = "no new Performance Insights CPU samples this cycle"; diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs index 28915ad3a2..ea765f4fbe 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWebEndpoints.cs @@ -1937,6 +1937,7 @@ private static CatalogRead R(string category, string description, params Catalog ["get_pg_server_config_changes"] = R(CatData, "PostgreSQL configuration parameters whose value CHANGED in the window, old beside new. Nothing else can reconstruct this after the fact.", PServer(), PHours(168), PLimit(100), PAsOf()), ["get_pg_deadlocks"] = R(CatData, "PostgreSQL deadlocks reported in the window, with the victim, the lock modes and resources, and the victim's statement. Needs nothing configured on the target.", PServer(), PHours(24), PLimit(25), PAsOf()), ["get_pg_deadlock_detail"] = R(CatData, "PostgreSQL deadlock graphs in full: the whole wait graph and every participant's statement, as the server wrote it. Newest first, or one by deadlock_hash.", PServer(), PText("deadlock_hash"), PLimit(5)), + ["get_pg_log_events"] = R(CatData, "PostgreSQL server-log events in the window, classified by family (error, connection, lock_wait, temp_file, autovacuum, checkpoint), newest first, redacted. The 'check the error log' read. Filter by family and min_severity; the page says what bounded it.", PServer(), PHours(24), PText("family"), PText("min_severity"), PLimit(50), PAsOf()), ["get_pg_wait_trend"] = R(CatTrends, "One PostgreSQL wait event over time, per second. Omit wait_event to follow whichever dominates. Estimates from a sampling profiler, so the shape is the finding.", PServer(), PText("wait_event"), PHours(24), PAsOf()), ["get_pg_query_duration_trend"] = R(CatTrends, "One PostgreSQL statement over time by queryid: what a single execution cost in each interval. Omit queryid for the busiest statement. The regression read.", PServer(), PText("queryid"), PHours(24), PAsOf()), ["get_pg_io_trend"] = R(CatTrends, "One PostgreSQL (backend_type, context) pair over time: I/O rates per second, the hit ratio per interval, and latency where the server measures it. Omit both to follow whichever pair moved the most I/O.", PServer(), PText("backend_type"), PText("context"), PHours(24), PAsOf()), @@ -2637,6 +2638,7 @@ cannot parse exactly rather than silently matching nothing. */ ["get_pg_server_config_changes"] = (c, pg, an) => DarlingMcpPgServerStateTools.GetPgServerConfigChanges(pg, Server(c), Hours(c, 168), Rows(c, "limit", 100), as_of: AsOf(c)), ["get_pg_deadlocks"] = (c, pg, an) => DarlingMcpPgDeadlockTools.GetPgDeadlocks(pg, Server(c), Hours(c, 24), Rows(c, "limit", 25), as_of: AsOf(c)), ["get_pg_deadlock_detail"] = (c, pg, an) => DarlingMcpPgDeadlockTools.GetPgDeadlockDetail(pg, Server(c), Str(c, "deadlock_hash"), Rows(c, "limit", 5)), + ["get_pg_log_events"] = (c, pg, an) => DarlingMcpPgLogEventTools.GetPgLogEvents(pg, Server(c), Hours(c, 24), Str(c, "family"), Str(c, "min_severity"), Rows(c, "limit", 50), as_of: AsOf(c)), ["get_pg_wait_trend"] = (c, pg, an) => DarlingMcpPgTrendTools.GetPgWaitTrend(pg, Server(c), Str(c, "wait_event"), Hours(c, 24), as_of: AsOf(c)), ["get_pg_query_duration_trend"] = (c, pg, an) => DarlingMcpPgTrendTools.GetPgQueryDurationTrend(pg, Server(c), Str(c, "queryid"), Hours(c, 24), as_of: AsOf(c)), ["get_pg_io_trend"] = (c, pg, an) => DarlingMcpPgTrendTools.GetPgIoTrend(pg, Server(c), Str(c, "backend_type"), Str(c, "context"), Hours(c, 24), as_of: AsOf(c)), diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs index 2c167f5c70..2e050ef617 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingWorker.cs @@ -7253,13 +7253,14 @@ private static string WhereToCreateIt(string? connectedDatabase) + $"so run CREATE EXTENSION in '{connectedDatabase}'. "; /// - /// The self-hosted log readers (#3239). Their dispatch entries send Aurora and RDS to the log-API - /// ingestors, so a target-side PostgresException under either name comes from the pg_read_file route. + /// The self-hosted log readers (#3239; three since #3601). Their dispatch entries send Aurora and RDS to + /// the log-API ingestors, so a target-side PostgresException under any of the names comes from the + /// pg_read_file route. /// Consulted by two arms: the 42501 grant-pair sentence (#3239) and the 58P01 missing-file sentence /// (#3410), which is why it names the ROUTE rather than either fault. /// private static bool ReadsServerLogWithPgReadFile(string collectorName) - => collectorName is "pg_deadlocks" or "pg_plan_capture"; + => collectorName is "pg_deadlocks" or "pg_plan_capture" or "pg_log_events"; /// /// Where the pg_read_file grants have to be issued, named when we know it (#3239) — function ACLs are @@ -8229,6 +8230,13 @@ the next start. */ s.Target.IsAurora || s.Target.IsAwsRds ? r.IngestRdsDeadlocksAsync(s, ct) : r.RunAsync(PgDeadlocksCollector.Instance, s, ct), + /* TWO TRANSPORTS, one table, the third time (#3601): the classified log-event pipeline reads the + same server log by the same two roads as its two siblings above and below, and the classifier + both roads feed is one instance, so the rows are the same whichever road the text took. */ + ["pg_log_events"] = (r, s, ct) => + s.Target.IsAurora || s.Target.IsAwsRds + ? r.IngestRdsLogEventsAsync(s, ct) + : r.RunAsync(PgLogEventsCollector.Instance, s, ct), ["pg_xmin_horizon"] = (r, s, ct) => r.RunAsync(PgXminHorizonCollector.Instance, s, ct), ["pg_replication_slots"] = (r, s, ct) => r.RunAsync(PgReplicationSlotsCollector.Instance, s, ct), ["pg_autovacuum_stats"] = (r, s, ct) => r.RunAsync(PgAutovacuumStatsCollector.Instance, s, ct), diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpHostService.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpHostService.cs index e57692fea0..36329566ab 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpHostService.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpHostService.cs @@ -695,6 +695,9 @@ McpToolTypeRegistrationTests now derives the check by reflection instead of trus /* get_pg_deadlocks / get_pg_deadlock_detail (#2661) - the reports themselves, out of the server log, rather than pg_stat_database's count. */ .WithGeminiCompatibleTools() + /* get_pg_log_events (#3601) - the classified log-event pipeline's read: errors, connections, + lock waits and the recognised-only families, out of the same server log. */ + .WithGeminiCompatibleTools() /* get_pg_wait_trend / get_pg_query_duration_trend / get_pg_io_trend / get_pg_database_trend (#2663) - the PostgreSQL time series. Fourteen trend reads shipped and none worked on this engine. All four live on one tools class, so this line covers diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpInstructions.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpInstructions.cs index 436e32aae5..82cb9d8d1e 100644 --- a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpInstructions.cs +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpInstructions.cs @@ -62,7 +62,7 @@ public static string Build(DarlingPeerDirectory.Snapshot peers) ## Tool Reference - This server exposes 152 tools. 86 are the same names Performance Monitor Lite exposes, spanning diagnostic analysis, plan analysis, data reads at core and diagnostic depth, resource contention + jobs, trends, system-health parse-on-read, alerts + health overview, and the Default Trace. The remaining 66 are unique to Darling: thirty-four are the PostgreSQL reads (Aurora/PostgreSQL targets only Darling's central store can hold; two of them are the target-onboarding pair — `get_pg_plan_capture_readiness` judges plan capture's preconditions facet by facet and `get_pg_logging_audit` judges the rest of the logging surface setting by setting from the stored configuration, each with the remedy per finding in the hosting flavour's syntax — which together answer whether a target is telling us everything it could), eight are the Custom Views tools (seven manage the saved views — the one view-authoring write surface — and `describe_custom_view_catalog` returns the read-only compose vocabulary those authoring tools draw from), eight are the custom-alert-rule tools (`create_custom_alert_rule` / `update_custom_alert_rule` / `delete_custom_alert_rule` manage the user-authored alert rules, the one alert-authoring write surface, while `get_custom_alert_rule` / `list_custom_alert_rules` read them back, `validate_custom_alert_rule` checks a rule definition against the same compose catalog without saving it, `test_custom_alert_rule` evaluates a rule's metric NOW on each in-scope server and reports whether it would breach without delivering or persisting anything, and `list_custom_alert_templates` lists the built-in starter rule templates to browse and create from), five are alert-tuning write tools (`update_alert_settings` tunes the alert engine's thresholds; `create_mute_rule` / `update_mute_rule` / `delete_mute_rule` / `set_mute_rule_enabled` manage the mute rules, `update_mute_rule` editing a rule in place and `set_mute_rule_enabled` taking one out of force and putting it back — both without destroying it or resetting its creation date) that write only the shared alert configuration in the monitoring store, two are server-onboarding write tools (`add_servers` bulk-adds monitored servers; `remove_server` removes one) that add or remove rows in the monitoring store's monitored-server registry, `get_fleet_overview` and `get_ag_health` are the two cross-server reads of the fleet's CURRENT state only a central store can answer, `get_sweep_reports` is the cross-server read WITH MEMORY — the scheduled fleet sweep's persisted whole-fleet reports (the timeline with each sweep's document embedded, one sweep in full with its would-have-paged ledger, and the watch-item worklist), `get_store_metrics` reads the monitoring store's OWN hourly size/compression/growth series for capacity forecasting, `get_store_log` reads what the monitoring store's OWN PostgreSQL server log recorded as a per-class census with its capture denominator (the self-monitoring that shows the store's half of a client-side symptom), `get_collector_cost` reads the tool's OWN per-collector cost on the monitored servers (the self-monitoring that flags a collector regressing into a hog), `get_collector_stall_probes` reads the out-of-band server-wide wait samples this tool takes while one of its own collectors is stalled mid-read — the only surface here that reports what a monitored instance was doing inside the window the sequential sweep records nothing in — `get_oversized_plan_backlog` reads the backlog of cached plans the capture cap declined and what the out-of-band sweep has since done about each one (the self-monitoring that tells a sweep whose fetch half is working from one that has never once succeeded), and `get_blocking` is Darling's name for the blocked-process-report read that Lite exposes as `get_blocked_process_reports` — a naming difference, not a capability gap. Every data-read tool reads the data the collectors already captured into the store — a stored read, never a live query against the monitored server. + This server exposes 153 tools. 86 are the same names Performance Monitor Lite exposes, spanning diagnostic analysis, plan analysis, data reads at core and diagnostic depth, resource contention + jobs, trends, system-health parse-on-read, alerts + health overview, and the Default Trace. The remaining 67 are unique to Darling: thirty-five are the PostgreSQL reads (Aurora/PostgreSQL targets only Darling's central store can hold; two of them are the target-onboarding pair — `get_pg_plan_capture_readiness` judges plan capture's preconditions facet by facet and `get_pg_logging_audit` judges the rest of the logging surface setting by setting from the stored configuration, each with the remedy per finding in the hosting flavour's syntax — which together answer whether a target is telling us everything it could), eight are the Custom Views tools (seven manage the saved views — the one view-authoring write surface — and `describe_custom_view_catalog` returns the read-only compose vocabulary those authoring tools draw from), eight are the custom-alert-rule tools (`create_custom_alert_rule` / `update_custom_alert_rule` / `delete_custom_alert_rule` manage the user-authored alert rules, the one alert-authoring write surface, while `get_custom_alert_rule` / `list_custom_alert_rules` read them back, `validate_custom_alert_rule` checks a rule definition against the same compose catalog without saving it, `test_custom_alert_rule` evaluates a rule's metric NOW on each in-scope server and reports whether it would breach without delivering or persisting anything, and `list_custom_alert_templates` lists the built-in starter rule templates to browse and create from), five are alert-tuning write tools (`update_alert_settings` tunes the alert engine's thresholds; `create_mute_rule` / `update_mute_rule` / `delete_mute_rule` / `set_mute_rule_enabled` manage the mute rules, `update_mute_rule` editing a rule in place and `set_mute_rule_enabled` taking one out of force and putting it back — both without destroying it or resetting its creation date) that write only the shared alert configuration in the monitoring store, two are server-onboarding write tools (`add_servers` bulk-adds monitored servers; `remove_server` removes one) that add or remove rows in the monitoring store's monitored-server registry, `get_fleet_overview` and `get_ag_health` are the two cross-server reads of the fleet's CURRENT state only a central store can answer, `get_sweep_reports` is the cross-server read WITH MEMORY — the scheduled fleet sweep's persisted whole-fleet reports (the timeline with each sweep's document embedded, one sweep in full with its would-have-paged ledger, and the watch-item worklist), `get_store_metrics` reads the monitoring store's OWN hourly size/compression/growth series for capacity forecasting, `get_store_log` reads what the monitoring store's OWN PostgreSQL server log recorded as a per-class census with its capture denominator (the self-monitoring that shows the store's half of a client-side symptom), `get_collector_cost` reads the tool's OWN per-collector cost on the monitored servers (the self-monitoring that flags a collector regressing into a hog), `get_collector_stall_probes` reads the out-of-band server-wide wait samples this tool takes while one of its own collectors is stalled mid-read — the only surface here that reports what a monitored instance was doing inside the window the sequential sweep records nothing in — `get_oversized_plan_backlog` reads the backlog of cached plans the capture cap declined and what the out-of-band sweep has since done about each one (the self-monitoring that tells a sweep whose fetch half is working from one that has never once succeeded), and `get_blocking` is Darling's name for the blocked-process-report read that Lite exposes as `get_blocked_process_reports` — a naming difference, not a capability gap. Every data-read tool reads the data the collectors already captured into the store — a stored read, never a live query against the monitored server. ### Reading an empty result diff --git a/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs new file mode 100644 index 0000000000..bca5c50cb4 --- /dev/null +++ b/Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingMcpPgLogEventTools.cs @@ -0,0 +1,161 @@ +/* + * 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.ComponentModel; +using System.Linq; +using System.Text.Json; +using System.Threading.Tasks; +using ModelContextProtocol.Server; +using Npgsql; +using PerformanceMonitor.Collectors; +using PerformanceMonitor.Common; +using PerformanceMonitor.Darling.Storage; + +namespace PerformanceMonitor.Darling.Service.Mcp; + +/// +/// PostgreSQL server-log events (#3601) — the classified pipeline's read surface: the SQL Server DBA's +/// "check the error log", answered from what pg_log_events stored off the target's log. +/// +[McpServerToolType] +public sealed class DarlingMcpPgLogEventTools +{ + [McpServerTool(Name = "get_pg_log_events"), Description("Gets the events PostgreSQL wrote to its server log in the window, newest first, classified by FAMILY: error (anything at WARNING or worse - a cancelled statement, a FATAL connection refusal, a constraint violation, a deadlock's ERROR line), connection (log_connections / log_disconnections: received, authorized with user, database and application_name, disconnection with session time), lock_wait (log_lock_waits: 'process N still waiting for ShareLock on transaction M after 1000 ms', and the 'acquired' line that ends the same wait - the engine's own blocked-process report, written rather than sampled), plus temp_file, autovacuum and checkpoint, which are recognised and stored with their message today and gain structured tables in later work. This is the SQL Server DBA's 'check the error log': errors, spills, autovacuum runs and connection churn land in this log and nowhere else, and between two counter samples they were invisible. Filter with family and min_severity; min_severity ranks by SERIOUSNESS - LOG/INFO < NOTICE < WARNING < ERROR < FATAL < PANIC - which is NOT log_min_messages' order (there LOG sits above ERROR, because that setting ranks by how hard a message is to suppress). Each row is one DISTINCT log entry; times_seen counts how often the collector saw the SAME entry, which on a target whose log is read by pg_read_file climbs while the entry stays in the re-read window and on RDS/Aurora is normally 1 - never a count of occurrences. message and detail are REDACTED (quoted literals and unique-violation key values stripped) and the statement text is never stored: statement_fingerprint is a hash of the redacted statement, so the same statement shape recurs to one fingerprint and get_pg_top_queries is where the shape's normalised text lives. sqlstate is null unless the target's log_line_prefix carries %e; database_name and user_name are null unless the prefix carries %u@%d or the message names them. WHAT THE TARGET HAS TO HAVE ON for each family to carry anything: error needs only log_min_messages at WARNING or lower (the default); connection needs log_connections / log_disconnections; lock_wait needs log_lock_waits; temp_file needs log_temp_files; autovacuum needs log_autovacuum_min_duration; checkpoint needs log_checkpoints. A family that is off on the target is EMPTY here and this tool does not audit the settings - get_pg_server_config carries them. Three preconditions are the same ones every target-side log read has: the log must be readable (pg_read_server_files plus GRANT EXECUTE ON pg_read_file self-hosted; the RDS log API on Aurora/RDS), stamped in a zero-offset zone (log_timezone = UTC - a non-UTC log is REFUSED whole rather than shifted), and written in English (lc_messages - a translated severity label matches nothing). The page is bounded by limit and says so: events_returned is the page, truncated is observed (one more row was fetched than shown), oldest_returned_at / newest_returned_at bound the page, and total_events is the WINDOW's distinct-event count under the same family and severity filters on the same statement - so a 25-row page of a 4,000-event hour reads as 25 of 4,000, not as the hour.")] + public static async Task GetPgLogEvents( + NpgsqlDataSource postgres, + [Description("Server name or display name.")] string? server_name = null, + [Description("Hours of history to analyze. Default 24.")] int hours_back = 24, + [Description("One family to return: error, connection, lock_wait, temp_file, autovacuum, checkpoint. Omit for every family.")] string? family = null, + [Description("Lowest severity to return, by seriousness: LOG, INFO, NOTICE, WARNING, ERROR, FATAL, PANIC. Default LOG (everything). WARNING is the 'errors only' setting; connection and lock_wait lines are LOG and are excluded by anything above it.")] string? min_severity = null, + [Description("Maximum events to return. Default 50. The page is truncated when the window holds more; total_events is the window's count.")] int limit = 50, + [Description(McpHelpers.AsOfDescription)] string? as_of = null) + { + var (resolved, error) = await DarlingServerResolver.ResolveOrErrorAsync(postgres, server_name); + if (error != null) return error; + + var validation = McpHelpers.ValidateWindow(hours_back, as_of, out var windowEnd); + if (validation != null) return validation; + + var limitError = McpHelpers.ValidateTop(limit); + if (limitError != null) return McpHelpers.Status("error", limitError); + + /* The family filter is a closed vocabulary and a typo in it must not read as "no events of that + kind" — an unknown family is the caller's mistake, said as one. */ + var familyFilter = string.IsNullOrWhiteSpace(family) ? null : family.Trim().ToLowerInvariant(); + if (familyFilter is not null && !PgLogFamilies.IsKnown(familyFilter)) + { + return McpHelpers.Status("error", + $"family '{family}' is not one this pipeline classifies. Known families: " + + string.Join(", ", PgLogFamilies.All.Where(f => f != PgLogFamilies.Other)) + "."); + } + + /* The severity floor is a label, ranked by PgLogEntry.RankOf — the same ranking the reader's SQL + CASE spells, pinned to agree. An unknown label is refused for the family filter's reason. */ + var minRank = 0; + var severityLabel = string.IsNullOrWhiteSpace(min_severity) ? "LOG" : min_severity.Trim().ToUpperInvariant(); + minRank = PgLogEntry.RankOf(severityLabel); + if (minRank == 0) + { + return McpHelpers.Status("error", + $"min_severity '{min_severity}' is not a PostgreSQL severity label. Use one of LOG, INFO, " + + "NOTICE, WARNING, ERROR, FATAL, PANIC (ranked by seriousness in that order)."); + } + + try + { + /* limit + 1 so truncation is OBSERVED from the extra row rather than inferred from the count reaching + the cap (#3594). */ + var page = await DarlingPgLogEventReader.GetEventsAsync( + postgres, resolved.ServerId, windowEnd.AddHours(-hours_back), windowEnd, + familyFilter, minRank, limit + 1); + + if (page.Rows.Count == 0) + { + /* Capability first, then what the collector's own last run recorded (#3410): a denied + pg_read_file grant, a missing file, a logging_collector that is off, a non-UTC + log_timezone — each lands in collection_log as a named skip, and quoting it here is what + turns "no events" into not-collected WITH THE REASON. Then the honest quiet answer, which + names the settings a family depends on, because an all-off target is the likeliest + reason a log has nothing for a family and nothing else on this surface says so. */ + return await DarlingEngineCapability.NotCollectedStatusAsync( + postgres, resolved.ServerId, resolved.ServerName, "pg_log_events") + ?? await DarlingRuntimePrecondition.StatusAsync( + postgres, resolved.ServerId, resolved.ServerName, "pg_log_events") + ?? McpHelpers.Status( + "no_events", + $"No log event{(familyFilter is null ? string.Empty : $" in family '{familyFilter}'")}" + + $"{(minRank > 1 ? $" at {severityLabel} or worse" : string.Empty)} was stored for " + + $"{resolved.ServerName} in the last {hours_back} hour(s). Four things produce that: " + + "the server wrote none, which is the healthy answer for the error and lock_wait " + + "families; the setting that family depends on is off on the target " + + "(log_connections / log_disconnections for connection, log_lock_waits for " + + "lock_wait, log_temp_files for temp_file, log_autovacuum_min_duration for " + + "autovacuum, log_checkpoints for checkpoint - get_pg_server_config carries them, " + + "and a family whose setting is off is empty here by construction); the log could " + + "not be read (get_pg_plan_capture_readiness judges readability, because plan " + + "capture reads the same file the same way); or the log was read and PostgreSQL " + + "did not write it in English (lc_messages translates the severity label, so a " + + "FEHLER: line matches nothing - the readiness read's message_locale facet). " + + "pg_stat_database's counters in get_pg_database_stats are the independent check " + + "for the error and temp_file families: if they moved and nothing is here, the log " + + "is the problem rather than the server."); + } + + var truncated = page.Rows.Count > limit; + var rows = truncated ? page.Rows.Take(limit).ToList() : page.Rows.ToList(); + + return JsonSerializer.Serialize(new + { + server = resolved.ServerName, + hours_back, + family = familyFilter, + min_severity = severityLabel, + status = "events", + events_returned = rows.Count, + /* The WINDOW's distinct-event count under the same filters, off the same statement (#3613) — + never the page's count under a total's name (#3594). */ + total_events = page.WindowTotal, + truncated, + order = "newest first", + /* Under newest-first the oldest stamp IS the reach of the read: events before it were not + shown, and total_events says how many the window held. */ + oldest_returned_at = rows[^1].OccurredAtUtc, + newest_returned_at = rows[0].OccurredAtUtc, + note = "occurred_at is when PostgreSQL wrote the line, not when the collector found it. " + + "times_seen counts sightings of the SAME entry, never occurrences: a target read with " + + "pg_read_file re-reads an overlapping log tail every cycle, so the count climbs while " + + "the entry stays in the window; on RDS and Aurora the log API is consume-once and it " + + "is normally 1. message and detail are redacted; the statement is never stored, only " + + "fingerprinted. min_severity ranks by seriousness (LOG/INFO < NOTICE < WARNING < ERROR " + + "< FATAL < PANIC), not by log_min_messages' suppression order. total_events is the " + + "window's distinct-event count under these filters; events_returned is this page.", + events = rows.Select(r => new + { + occurred_at = r.OccurredAtUtc, + family = r.Family, + severity = r.Severity, + sqlstate = r.SqlState, + database_name = r.DatabaseName, + user_name = r.UserName, + application_name = r.ApplicationName, + pid = r.Pid, + message = r.Message, + detail = r.Detail, + statement_fingerprint = r.StatementFingerprint, + raw_line_hash = r.RawLineHash, + times_seen = r.TimesSeen, + }), + }, McpHelpers.JsonOptions); + } + catch (Exception ex) + { + return McpHelpers.Status("error", $"Reading PostgreSQL log events failed: {ex.Message}"); + } + } +} diff --git a/Darling/PerformanceMonitor.Darling.Service/Targets/RdsLogEventIngestor.cs b/Darling/PerformanceMonitor.Darling.Service/Targets/RdsLogEventIngestor.cs new file mode 100644 index 0000000000..2d49975ff6 --- /dev/null +++ b/Darling/PerformanceMonitor.Darling.Service/Targets/RdsLogEventIngestor.cs @@ -0,0 +1,208 @@ +/* + * 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.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Npgsql; +using PerformanceMonitor.Collectors; +using PerformanceMonitor.Darling.Storage; + +namespace PerformanceMonitor.Darling.Service.Targets; + +/// +/// Stores classified log events fetched from the RDS log API into collect.pg_log_events (#3601) — +/// the managed-PostgreSQL half of the log-event pipeline, and 's sibling +/// in every structural respect. +/// +/// Its own , not a shared one, for the deadlock ingestor's reason: +/// the source keeps an in-memory resume marker per (instance, file), consumed on every read, so sharing +/// one with the plan or deadlock ingestor would starve whichever ran second. Three ingestors, three +/// markers, one API. Unifying them onto one read of the chunk and one classifier pass — which is what the +/// pipeline makes possible for the first time — is the follow-up the classifier's header names; tonight +/// the two existing ingestors are untouched and this one arrives beside them. +/// +/// What it deliberately does NOT duplicate. Assembly, classification, redaction and hashing +/// are , the same instance the pg_read_file route's +/// calls; this type hands it the chunk's text and gets rows. The WRITE +/// goes through PgCollectorRowWriter and the collector's own definition, so column order and the +/// COPY command are the collector's. The marker moves after the write and nowhere else (#3008). +/// +public sealed class RdsLogEventIngestor +{ + private readonly NpgsqlDataSource _postgres; + private readonly RdsLogSource _logs; + private readonly ILogger? _logger; + + public RdsLogEventIngestor(NpgsqlDataSource postgres, RdsLogSource? logs = null, ILogger? logger = null) + { + _postgres = postgres ?? throw new ArgumentNullException(nameof(postgres)); + _logs = logs ?? new RdsLogSource(); + _logger = logger; + } + + /// The target's connection host. A non-RDS host means this transport does not apply + /// — it uses the pg_read_file route — and the outcome says so rather than reporting an empty log + /// (#3017). + /// The log is stamped in a non-UTC zone (#2993). + /// Propagated so the runner names the setting; the marker is not committed, so the window comes back + /// once the setting is fixed. + public async Task IngestAsync( + int serverId, + string storageName, + string host, + CancellationToken cancellationToken = default) + { + RdsLogSource.LogChunk? chunk; + + try + { + chunk = await _logs.ReadNewestAsync(host, cancellationToken); + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + /* #2633's fix, shared: rethrown so the runner degrades an authorization refusal to PERMISSIONS + rather than recording a SUCCESS row that claims the log was opened and held nothing. */ + _logger?.LogWarning( + "RDS log unavailable for {Server}: {Message} — log-event capture is skipped for this target " + + "this cycle; every other collector is unaffected.", + storageName, ex.Message); + + throw new RdsLogUnavailableException( + ex.Message, RdsLogUnavailableException.IsAuthorizationRefusal(ex), ex); + } + + if (chunk is null) + { + /* #3017: NOT_REACHED, not zero rows — the host is not an RDS or Aurora endpoint, no AWS call was + made, and nothing is known about the log. */ + return RdsIngestOutcome.NotReached; + } + + var written = await StoreAsync(serverId, storageName, chunk.Value.Text, cancellationToken); + + /* THE MARKER MOVES HERE AND NOWHERE ELSE (#3008). Everything the chunk held is in the store or was + nothing to store; anything else threw out of StoreAsync and left the marker where it was. */ + _logs.CommitResume(chunk.Value.Resume); + + return RdsIngestOutcome.Read(written); + } + + private async Task StoreAsync( + int serverId, + string storageName, + string text, + CancellationToken cancellationToken) + { + if (string.IsNullOrEmpty(text)) + { + return 0; + } + + /* Outside IngestAsync's tolerant catch, which covers the AWS FETCH: a zone refusal is a statement + about the target's configuration and has to reach the runner uncommitted (#3008). */ + var events = PgLogEventClassifier.Default.Classify(text); + + if (events.Count == 0) + { + return 0; + } + + return await WriteAsync(serverId, storageName, events, cancellationToken); + } + + /// + /// The same binary COPY the collector runner uses, driven by the collector's own definition — verbatim + /// the deadlock ingestor's write, over a different definition. A shared write helper for the three + /// ingestors is the natural follow-up; it was not pulled out tonight because the deadline-and-phase + /// discipline in it is the part every reviewer of #2874 and #3008 has read in place, and moving it + /// under a new table is not the night to re-read it. + /// + private async Task WriteAsync( + int serverId, + string storageName, + IReadOnlyList rows, + CancellationToken cancellationToken) + { + var definition = PgLogEventsCollector.Instance; + + var collectionTime = DateTime.SpecifyKind(DateTime.UtcNow, DateTimeKind.Unspecified); + + await using var connection = await _postgres.OpenConnectionAsync(cancellationToken); + + var writer = new PgCollectorRowWriter(); + var written = 0; + + using var startDeadline = StoreCopyStartDeadline.Start(cancellationToken); + + var copyPhase = StoreCopyPhase.Start; + + try + { + using (var importer = await connection.BeginBinaryImportAsync( + PgCollectorRowWriter.CopyCommandFor(definition), startDeadline.Token)) + { + copyPhase = StoreCopyPhase.Data; + + importer.Timeout = TimeSpan.FromSeconds(ServiceCommandDeadlines.CollectionSweepSeconds); + + writer.Importer = importer; + + foreach (var row in rows) + { + await importer.StartRowAsync(cancellationToken); + + if (definition.IncludesCollectionId) + { + writer.Value(CollectionIdGenerator.Next()); + } + + writer.Value(collectionTime) + .Value(serverId) + .Value(storageName); + + writer.BeginPayload(); + definition.WritePayload(row, writer, NullContext(serverId, storageName, collectionTime)); + writer.EndPayload(definition.PayloadColumns.Count); + written++; + } + + await importer.CompleteAsync(cancellationToken); + } + } + catch (OperationCanceledException cancellation) + when (copyPhase == StoreCopyPhase.Start && startDeadline.Breached()) + { + var breach = StoreCopyStartDeadline.Breach(cancellation); + CollectorFaultCopyPhase.Stamp(breach, copyPhase); + throw breach; + } + catch (Exception ex) when (ex is not OperationCanceledException) + { + CollectorFaultCopyPhase.Stamp(ex, copyPhase); + throw; + } + + _logger?.LogInformation( + "Stored {Count} log event(s) for {Server} from the RDS log API.", written, storageName); + + return written; + } + + private static CollectorContext NullContext(int serverId, string storageName, DateTime collectionTime) + => new() + { + ServerId = serverId, + ServerName = storageName, + CollectionTime = collectionTime, + Deltas = new CollectorDeltaCalculator(), + Target = new CollectorTargetInfo { Engine = CollectorTargetEngine.PostgreSql }, + }; +} diff --git a/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js b/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js index 1266aea917..c13c17a41f 100644 --- a/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js +++ b/Darling/PerformanceMonitor.Darling.Service/wwwroot/js/pages/server-tabs.js @@ -1712,6 +1712,21 @@ export const POSTGRES_TABS = [ ctx.label + ", newest first; Sightings counts re-reads of the same report, not repeats", "No deadlock was reported in this window. That is the healthy answer - but it is the same shape as a server whose log cannot be read, which the Plan Capture Readiness panel above reports on because it reads the same file. pg_stat_database's deadlock counter is the independent check." ), + /* #3601 the log, classified. Under the deadlocks because the two are the same log read two ways: + the deadlock grid is one ERROR line's DETAIL graph parsed out whole, this is every classified line + around it - the errors before it, the lock waits that preceded it, the connection churn beside it. + The "check the error log" panel. Newest 50 across every family; the MCP read carries the family and + severity filters, and total_events on its payload is the window's count, so the panel note says + which of the two this grid is. */ + table( + "Log Events", + "get_pg_log_events", + { server, hours: ctx.hours, limit: 50 }, + "events", + PG_LOG_EVENT_COLUMNS, + ctx.label + ", newest 50 across every family; message and detail are redacted at the collector, the statement is never stored; Sightings counts re-reads of the same line, not repeats", + "No classified log event was stored in this window. That is the healthy answer for the error and lock-wait families - and it is also what a target with the relevant log_* setting off looks like (log_connections, log_lock_waits, log_temp_files, log_autovacuum_min_duration), or one whose log cannot be read, is not stamped UTC, or is not written in English: the Plan Capture Readiness panel above reads the same file and reports those three." + ), /* #2663 the regression read: what ONE execution of the busiest statement cost, interval by interval. The statement grid above ranks by total time across the window, which hides a step change - a query that doubled halfway through still ranks where its average puts it. */ @@ -3271,6 +3286,23 @@ const PG_DEADLOCK_COLUMNS = [ { key: "times_seen", label: "Sightings", format: "int", small: true }, ]; +/* #3601 the classified log events. No column for statement text, because none is stored: the fingerprint + is the statement's identity and get_pg_top_queries carries the shape's normalised text. */ +const PG_LOG_EVENT_COLUMNS = [ + { key: "occurred_at", label: "When", format: "time" }, + { key: "family", label: "Family", small: true }, + { key: "severity", label: "Severity", small: true }, + { key: "sqlstate", label: "SQLSTATE", small: true }, + { key: "database_name", label: "Database" }, + { key: "user_name", label: "User" }, + { key: "application_name", label: "Application" }, + { key: "pid", label: "PID", format: "int", small: true }, + { key: "message", label: "Message" }, + { key: "detail", label: "Detail" }, + { key: "statement_fingerprint", label: "Statement Fingerprint", small: true }, + { key: "times_seen", label: "Sightings", format: "int", small: true }, +]; + const PG_SERVER_CONFIG_COLUMNS = [ { key: "name", label: "Setting" }, { key: "setting", label: "Value" }, diff --git a/Darling/PerformanceMonitor.Darling.Storage/DarlingPgLogEventReader.cs b/Darling/PerformanceMonitor.Darling.Storage/DarlingPgLogEventReader.cs new file mode 100644 index 0000000000..dbba17c966 --- /dev/null +++ b/Darling/PerformanceMonitor.Darling.Storage/DarlingPgLogEventReader.cs @@ -0,0 +1,181 @@ +/* + * 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.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; +using Npgsql; + +namespace PerformanceMonitor.Darling.Storage; + +/// +/// Reads collect.pg_log_events (#3601) — the classified PostgreSQL server-log events — for +/// get_pg_log_events and the Viewer's log-events panel. +/// +/// Every read dedupes on raw_line_hash, for 's +/// reason. The pg_read_file transport re-reads an overlapping tail every cycle, so one event +/// arrives again and again until it falls out of the window; DISTINCT ON (raw_line_hash) takes the +/// earliest sighting, and times_seen says how many there were. On the consume-once RDS route an +/// event normally arrives once, so a low count there is the ordinary state rather than a partial one. +/// +/// Windowed on occurred_at, bounded below on collection_time too. The event's +/// own time is what the reader means by "last hour"; a collection-time window would put an event in the +/// wrong bucket and move it every cycle. But the hypertable is chunked on collection_time, and an +/// event is always collected AFTER it occurred, so collection_time >= window start is a bound +/// that is always true of every row the window admits and lets the planner exclude every chunk older +/// than the window. Cheap, and the deadlock reader does not have it because its table is small. +/// +/// The page contract (#3594, #3613). LIMIT is the caller's, bound as a parameter; +/// the tool fetches one more than it will show and OBSERVES truncation; window_total is +/// COUNT(*) OVER () on the same statement, after the distinct and the filters and before the +/// limit, so it counts every distinct event the window holds under the same filters, not the page. +/// +public static class DarlingPgLogEventReader +{ + public readonly record struct PgLogEventRow( + DateTime OccurredAtUtc, + string Family, + string Severity, + string? SqlState, + string? DatabaseName, + string? UserName, + string? ApplicationName, + int? Pid, + string Message, + string? Detail, + string? StatementFingerprint, + string RawLineHash, + int TimesSeen); + + /// The rows plus the window's distinct-event count under the same filters. + public readonly record struct PgLogEventsPage(IReadOnlyList Rows, int WindowTotal); + + /// + /// The seriousness ranking, as SQL. MUST agree with PgLogEntry.RankOf — pinned by test — because + /// the tool turns the caller's min_severity label into a rank with that method and this CASE is + /// what the rank is compared against. Seriousness order, not log_min_messages' order, where LOG + /// ranks above ERROR; the tool's description says so. + /// + public const string SeverityRankSql = """ + CASE e.severity + WHEN 'PANIC' THEN 6 + WHEN 'FATAL' THEN 5 + WHEN 'ERROR' THEN 4 + WHEN 'WARNING' THEN 3 + WHEN 'NOTICE' THEN 2 + WHEN 'INFO' THEN 1 + WHEN 'LOG' THEN 1 + ELSE 0 + END + """; + + /// + /// Events in the window, newest first, one row per distinct event, optionally one family and at least + /// one severity. $4 is the family or NULL for all; $5 is the minimum rank (0 for all). + /// + public static readonly string EventsSql = $$""" + WITH distinct_events AS ( + SELECT DISTINCT ON (e.raw_line_hash) + e.occurred_at, + e.family, + e.severity, + e.sqlstate, + e.database_name, + e.user_name, + e.application_name, + e.pid, + e.message, + e.detail, + e.statement_fingerprint, + e.raw_line_hash, + /* Sightings of the SAME entry, never a count of events -- see the class remarks. Evaluated + before DISTINCT ON, so it counts every sighting the distinct then collapses. */ + COUNT(*) OVER (PARTITION BY e.raw_line_hash)::int AS times_seen + FROM pg_log_events AS e + WHERE e.server_id = $1 + AND e.occurred_at >= $2 + AND e.occurred_at <= $3 + AND e.collection_time >= $2 + AND e.raw_line_hash IS NOT NULL + AND ($4::text IS NULL OR e.family = $4) + AND {{SeverityRankSql}} >= $5 + ORDER BY e.raw_line_hash, e.collection_time + ) + SELECT + d.occurred_at, + d.family, + d.severity, + d.sqlstate, + d.database_name, + d.user_name, + d.application_name, + d.pid, + d.message, + d.detail, + d.statement_fingerprint, + d.raw_line_hash, + d.times_seen, + /* The window's distinct-event count under the SAME filters, on the SAME statement: after the + distinct, before the limit. The page is what LIMIT admits; this is what it was cut from. */ + COUNT(*) OVER ()::int AS window_total + FROM distinct_events AS d + ORDER BY d.occurred_at DESC + LIMIT $6 + """; + + public static async Task GetEventsAsync( + NpgsqlDataSource dataSource, + int serverId, + DateTime startUtc, + DateTime endUtc, + string? family, + int minSeverityRank, + int limit, + CancellationToken cancellationToken = default) + { + var rows = new List(); + var windowTotal = 0; + + await using var command = dataSource.CreateCommand(EventsSql); + command.Parameters.AddWithValue(serverId); + command.Parameters.AddWithValue(DateTime.SpecifyKind(startUtc, DateTimeKind.Unspecified)); + command.Parameters.AddWithValue(DateTime.SpecifyKind(endUtc, DateTimeKind.Unspecified)); + command.Parameters.Add(new NpgsqlParameter + { + TypedValue = string.IsNullOrWhiteSpace(family) ? null : family, + NpgsqlDbType = NpgsqlTypes.NpgsqlDbType.Text, + }); + command.Parameters.AddWithValue(minSeverityRank); + command.Parameters.AddWithValue(limit); + + await using var reader = await command.ExecuteReaderAsync(cancellationToken); + + while (await reader.ReadAsync(cancellationToken)) + { + rows.Add(new PgLogEventRow( + OccurredAtUtc: DateTime.SpecifyKind(reader.GetDateTime(0), DateTimeKind.Utc), + Family: reader.IsDBNull(1) ? PerformanceMonitor.Collectors.PgLogFamilies.Other : reader.GetString(1), + Severity: reader.IsDBNull(2) ? string.Empty : reader.GetString(2), + SqlState: reader.IsDBNull(3) ? null : reader.GetString(3), + DatabaseName: reader.IsDBNull(4) ? null : reader.GetString(4), + UserName: reader.IsDBNull(5) ? null : reader.GetString(5), + ApplicationName: reader.IsDBNull(6) ? null : reader.GetString(6), + Pid: reader.IsDBNull(7) ? null : reader.GetInt32(7), + Message: reader.IsDBNull(8) ? string.Empty : reader.GetString(8), + Detail: reader.IsDBNull(9) ? null : reader.GetString(9), + StatementFingerprint: reader.IsDBNull(10) ? null : reader.GetString(10), + RawLineHash: reader.GetString(11), + TimesSeen: reader.GetInt32(12))); + + windowTotal = reader.GetInt32(13); + } + + return new PgLogEventsPage(rows, windowTotal); + } +} diff --git a/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs b/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs index 4dbec79587..dadccc09ce 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/PgMigrations.cs @@ -208,6 +208,7 @@ holds the ordering. */ V128Sql + "\n" + V54Sql + "\n" + PgSchemaGenerator.GenerateQueryStatsPayloadColumnPreAdds() + "\n" + PgSchemaGenerator.GenerateQueryStatsResolvingView()), + new Migration(129, "pg-log-events", V129Sql), }; /// @@ -854,6 +855,65 @@ tables have no v_ view. */ the regenerated resolving definition after the pre-adds, the V51/V121 idiom. */ DROP VIEW IF EXISTS collect.v_query_stats;"; + /// + /// V129 — collect.pg_log_events, the classified PostgreSQL server-log events (#3601): errors, + /// connections, lock waits, and the recognised-only spill / autovacuum / checkpoint shapes, out of the + /// same log the deadlock (V103) and plan (V99) readers already tail. The keystone for #3602 and #3603, + /// which each add one parser family on the pipeline this table stores. + /// + /// The identity column is the point, for V103's reason. The pg_read_file transport + /// re-reads an OVERLAPPING tail every cycle on purpose, so without raw_line_hash the same event + /// is stored once per cycle for as long as it stays inside the window; every read dedupes on it as the + /// deadlock reads do on deadlock_hash. Over the RAW entry text rather than the redacted columns, + /// because two events that redact alike — the same error for two values, same millisecond, same pid — + /// are two events, and the hash must keep them apart. A hash of the raw text discloses nothing about + /// it. + /// + /// Every text column is REDACTED before it reaches this table, and the statement itself is + /// never stored. message and detail have had quoted literals and unique-violation key + /// values stripped by PgLogTextRedactor, the plan parser's own patterns applied to prose; + /// statement_fingerprint is a hash of the REDACTED STATEMENT companion, so one statement + /// shape recurs to one fingerprint and no literal from the user's SQL exists anywhere in the store. The + /// issue's scope note — the log pipeline must not become where parameter values leak into the store — + /// is enforced at the row constructor rather than by convention. + /// + /// Retention is thirty days, not the deadlock table's ninety (CollectorScheduleDefaults + /// carries the argument): a deadlock is rare by construction and a log event is as common as the + /// target's settings let it be — log_connections on a reconnect-per-statement pool writes three + /// rows per query. Hypertable conversion, one-day chunks, compression segmented by server_id and + /// the retention policy all follow from the catalog entry, as for every collector table. + /// + /// One index, the generated one. The read filters on (server_id, collection_time) + /// first — chunk exclusion — and on family and severity within that window; a (server_id, family, + /// collection_time) index would help a family-filtered read over a long window on a loud target, + /// and it is a SEPARATE rung when it comes, for V104's reason: PgSchemaGeneratorTests requires a + /// collector's rung to be exactly what the generator emits, and the generator emits one index, so a + /// second one in this rung would give the upgraded store an index the fresh store never gets. All + /// value columns nullable, matching the generated schema this must be identical to. + /// + private const string V129Sql = @" +CREATE TABLE IF NOT EXISTS collect.pg_log_events ( + collection_id bigint NOT NULL, + collection_time timestamp NOT NULL, + server_id integer NOT NULL, + server_name text NOT NULL, + occurred_at timestamp, + family text, + severity text, + sqlstate text, + database_name text, + user_name text, + application_name text, + pid integer, + message text, + detail text, + statement_fingerprint text, + raw_line_hash text +); + +CREATE INDEX IF NOT EXISTS idx_pg_log_events_time + ON collect.pg_log_events(server_id, collection_time);"; + /// /// V2 — the service's observability store: the servers registry (upserted on every /// successful connect) and the per-run collection_log. Column names deliberately mirror diff --git a/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs b/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs index f50b18e9e1..2366c61c58 100644 --- a/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs +++ b/Darling/PerformanceMonitor.Darling.Storage/StorageVersion.cs @@ -16,5 +16,5 @@ namespace PerformanceMonitor.Darling.Storage; /// public static class StorageVersion { - public const int SchemaVersion = 128; + public const int SchemaVersion = 129; } diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs index 55770c39d5..8804dbd2b8 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.Postgres.cs @@ -368,6 +368,16 @@ public async Task> GetPgCpuUtilizationHistoryAsync( CancellationToken cancellationToken = default) => DarlingPgDeadlockReader.GetDeadlocksAsync(_dataSource, serverId, startUtc, endUtc, limit, cancellationToken); + /// Activity tab - the classified log events in the window (#3601), newest first, one row per + /// distinct entry, every family, no severity floor: the grid is the glance and the MCP read carries the + /// filters. Windowed on when the line was WRITTEN for the deadlock read's reason. 200 is the grid's cap, + /// stated on the note beside the window's distinct count so a full grid is not read as the window. + public Task GetPgLogEventsAsync( + int serverId, DateTime startUtc, DateTime endUtc, int limit = 200, + CancellationToken cancellationToken = default) => + DarlingPgLogEventReader.GetEventsAsync( + _dataSource, serverId, startUtc, endUtc, family: null, minSeverityRank: 0, limit, cancellationToken); + /// Overview tab - which extensions this target has, could have, or cannot have (#2545). Latest /// state per extension rather than the history: installing one is a rare deliberate act, so the window /// holds the same answer repeated daily. Monitoring-relevant extensions sort first, and within them the diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs index c98e7c9f2c..15922623b8 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerDataService.cs @@ -828,7 +828,11 @@ table existence cannot separate the rungs. The rung adds the same column to four sentinel — only the TABLE differs — which is exactly why the table is part of the predicate. Named only in this probe line, never in prose, per the V71 finding. */ EXISTS (SELECT 1 FROM information_schema.columns WHERE table_name = 'procedure_stats' - AND column_name = 'sample_interval_seconds')"; + AND column_name = 'sample_interval_seconds'), + /* V129 probes a TABLE, which separates the rungs cleanly because the table is new in it — the same + shape as V103 and V106, the two log-reader tables before it. Named only in this probe line, never + in prose, per the V71 finding. */ + EXISTS (SELECT 1 FROM information_schema.tables WHERE table_name = 'pg_log_events')"; /// The store schema version this viewer build requires — the highest migration it knows /// (). The connect-time gate blocks a store below this. @@ -850,7 +854,7 @@ table existence cannot separate the rungs. The rung adds the same column to four await using var reader = await command.ExecuteReaderAsync(cancellationToken); if (await reader.ReadAsync(cancellationToken)) { - return MapProbedSchemaVersion(reader.GetBoolean(0), reader.GetBoolean(1), reader.GetBoolean(2), reader.GetBoolean(3), reader.GetBoolean(4), reader.GetBoolean(5), reader.GetBoolean(6), reader.GetBoolean(7), reader.GetBoolean(8), reader.GetBoolean(9), reader.GetBoolean(10), reader.GetBoolean(11), reader.GetBoolean(12), reader.GetBoolean(13), reader.GetBoolean(14), reader.GetBoolean(15), reader.GetBoolean(16), reader.GetBoolean(17), reader.GetBoolean(18), reader.GetBoolean(19), reader.GetBoolean(20), reader.GetBoolean(21), reader.GetBoolean(22), reader.GetBoolean(23), reader.GetBoolean(24), reader.GetBoolean(25), reader.GetBoolean(26), reader.GetBoolean(27), reader.GetBoolean(28), reader.GetBoolean(29), reader.GetBoolean(30), reader.GetBoolean(31), reader.GetBoolean(32), reader.GetBoolean(33), reader.GetBoolean(34), reader.GetBoolean(35), reader.GetBoolean(36), reader.GetBoolean(37), reader.GetBoolean(38), reader.GetBoolean(39), reader.GetBoolean(40), reader.GetBoolean(41), reader.GetBoolean(42), reader.GetBoolean(43), reader.GetBoolean(44), reader.GetBoolean(45), reader.GetBoolean(46), reader.GetBoolean(47), reader.GetBoolean(48), reader.GetBoolean(49), reader.GetBoolean(50), reader.GetBoolean(51), reader.GetBoolean(52), reader.GetBoolean(53), reader.GetBoolean(54), reader.GetBoolean(55), reader.GetBoolean(56), reader.GetBoolean(57), reader.GetBoolean(58), reader.GetBoolean(59), reader.GetBoolean(60), reader.GetBoolean(61), reader.GetBoolean(62), reader.GetBoolean(63), reader.GetBoolean(64), reader.GetBoolean(65), reader.GetBoolean(66), reader.GetBoolean(67), reader.GetBoolean(68), reader.GetBoolean(69), reader.GetBoolean(70), reader.GetBoolean(71), reader.GetBoolean(72), reader.GetBoolean(73), reader.GetBoolean(74), reader.GetBoolean(75), reader.GetBoolean(76), reader.GetBoolean(77), reader.GetBoolean(78), reader.GetBoolean(79), reader.GetBoolean(80), reader.GetBoolean(81), reader.GetBoolean(82), reader.GetBoolean(83), reader.GetBoolean(84), reader.GetBoolean(85), reader.GetBoolean(86), reader.GetBoolean(87), reader.GetBoolean(88), reader.GetBoolean(89), reader.GetBoolean(90), reader.GetBoolean(91), reader.GetBoolean(92), reader.GetBoolean(93), reader.GetBoolean(94), reader.GetBoolean(95), reader.GetBoolean(96), reader.GetBoolean(97), reader.GetBoolean(98), reader.GetBoolean(99), reader.GetBoolean(100), reader.GetBoolean(101), reader.GetBoolean(102), reader.GetBoolean(103)); + return MapProbedSchemaVersion(reader.GetBoolean(0), reader.GetBoolean(1), reader.GetBoolean(2), reader.GetBoolean(3), reader.GetBoolean(4), reader.GetBoolean(5), reader.GetBoolean(6), reader.GetBoolean(7), reader.GetBoolean(8), reader.GetBoolean(9), reader.GetBoolean(10), reader.GetBoolean(11), reader.GetBoolean(12), reader.GetBoolean(13), reader.GetBoolean(14), reader.GetBoolean(15), reader.GetBoolean(16), reader.GetBoolean(17), reader.GetBoolean(18), reader.GetBoolean(19), reader.GetBoolean(20), reader.GetBoolean(21), reader.GetBoolean(22), reader.GetBoolean(23), reader.GetBoolean(24), reader.GetBoolean(25), reader.GetBoolean(26), reader.GetBoolean(27), reader.GetBoolean(28), reader.GetBoolean(29), reader.GetBoolean(30), reader.GetBoolean(31), reader.GetBoolean(32), reader.GetBoolean(33), reader.GetBoolean(34), reader.GetBoolean(35), reader.GetBoolean(36), reader.GetBoolean(37), reader.GetBoolean(38), reader.GetBoolean(39), reader.GetBoolean(40), reader.GetBoolean(41), reader.GetBoolean(42), reader.GetBoolean(43), reader.GetBoolean(44), reader.GetBoolean(45), reader.GetBoolean(46), reader.GetBoolean(47), reader.GetBoolean(48), reader.GetBoolean(49), reader.GetBoolean(50), reader.GetBoolean(51), reader.GetBoolean(52), reader.GetBoolean(53), reader.GetBoolean(54), reader.GetBoolean(55), reader.GetBoolean(56), reader.GetBoolean(57), reader.GetBoolean(58), reader.GetBoolean(59), reader.GetBoolean(60), reader.GetBoolean(61), reader.GetBoolean(62), reader.GetBoolean(63), reader.GetBoolean(64), reader.GetBoolean(65), reader.GetBoolean(66), reader.GetBoolean(67), reader.GetBoolean(68), reader.GetBoolean(69), reader.GetBoolean(70), reader.GetBoolean(71), reader.GetBoolean(72), reader.GetBoolean(73), reader.GetBoolean(74), reader.GetBoolean(75), reader.GetBoolean(76), reader.GetBoolean(77), reader.GetBoolean(78), reader.GetBoolean(79), reader.GetBoolean(80), reader.GetBoolean(81), reader.GetBoolean(82), reader.GetBoolean(83), reader.GetBoolean(84), reader.GetBoolean(85), reader.GetBoolean(86), reader.GetBoolean(87), reader.GetBoolean(88), reader.GetBoolean(89), reader.GetBoolean(90), reader.GetBoolean(91), reader.GetBoolean(92), reader.GetBoolean(93), reader.GetBoolean(94), reader.GetBoolean(95), reader.GetBoolean(96), reader.GetBoolean(97), reader.GetBoolean(98), reader.GetBoolean(99), reader.GetBoolean(100), reader.GetBoolean(101), reader.GetBoolean(102), reader.GetBoolean(103), reader.GetBoolean(104)); } return null; @@ -875,7 +879,7 @@ table existence cannot separate the rungs. The rung adds the same column to four /// is unit-tested without a live store; any schema bump past the newest arm trips the pinning test that keeps /// this in step with . /// - internal static int MapProbedSchemaVersion(bool hasConfigControlPlane, bool hasAlertDeliveryOverride, bool hasAnalysisState, bool hasAlertTuningKnobs, bool hasDefaultTraceEvents, bool hasIndexObjectStatsLatestIndex, bool hasCollectionLogHypertableOrPlainPg, bool hasJobHistory, bool hasAgentStatus, bool hasGenericWebhook, bool hasDeadlocksDatabaseName, bool hasQueryStoreReplicaRole, bool hasLongQueryCompletions, bool hasWebDashboardConfig, bool hasCustomViews, bool hasServerTags, bool hasConnectionRefireKnobs = false, bool hasAgCollectors = false, bool hasAgAlertKnobs = false, bool hasAgLatencyColumns = false, bool hasAgDisconnectRefire = false, bool hasPayloadDimensions = false, bool hasDimFloorIndexes = false, bool hasBlockingWaitThreshold = false, bool hasQueryStoreIntervalIdentity = false, bool hasPagerDutyWebhook = false, bool hasPagerDutyProxy = false, bool hasCollectorState = false, bool hasPlanCorrection = false, bool hasPvsStats = false, bool hasPvsPressureKnobs = false, bool hasDatabaseStateAlert = false, bool hasServerTagColour = false, bool hasQueryStatsHostObject = false, bool hasFindingDrillDown = false, bool hasStoreMetrics = false, bool hasPlanDimGzip = false, bool hasSelfAlertKnobs = false, bool hasJobMetricsColumns = false, bool hasJobCadenceKnob = false, bool hasBackfillSwitch = false, bool hasCollectorMemoryKnobs = false, bool hasDatabaseStateEdgeMemory = false, bool hasIncidentOccurrences = false, bool hasPlanXmlCompressionKnob = false, bool hasMonitoredServerEngine = false, bool hasPgBlockingEdges = false, bool hasQueryStorePlanMap = false, bool hasPgStatementText = false, bool hasQueryStoreText = false, bool hasPlanContentRetentionKnob = false, bool hasQueryStoreHealth = false, bool hasQueryStoreTextHash = false, bool hasComposeTimeoutKnob = false, bool hasFileGrowthAlert = false, bool hasCollectionLogFanoutRollup = false, bool hasTempDbMaxSize = false, bool hasServerEngineKind = false, bool hasPgDatabaseStats = false, bool hasPgIndexUsageStats = false, bool hasPgTableBloatStats = false, bool hasPgSessionStates = false, bool hasPgPlanCaptureReadiness = false, bool hasPgWriteStats = false, bool hasPgExtensionAvailability = false, bool hasPgLockStats = false, bool hasPgColumnStats = false, bool hasPgReplicationStats = false, bool hasPgBufferUsage = false, bool hasPgIndexBloat = false, bool hasPgPerDatabaseAttribution = false, bool hasPgWaitSampling = false, bool hasPgKernelStats = false, bool hasPgPredicateStats = false, bool hasPgPlanCapture = false, bool hasPgMajorVersion = false, bool hasPg18IoBytes = false, bool hasPgServerConfig = false, bool hasPgDeadlocks = false, bool hasPgDeadlockIdentity = false, bool hasCollectorCost = false, bool hasPgCpuUtilization = false, bool hasPlanForceActions = false, bool hasCollectionLogPhaseSplit = false, bool hasCollectionLogDrainForensics = false, bool hasCollectionLogFetchPhaseSums = false, bool hasStoreLogSelfMonitoring = false, bool hasCollectorStallProbes = false, bool hasRemediationCredentialAndActor = false, bool hasPgIndexBloatEstimate = false, bool hasPgCpuCapacityHeadroom = false, bool hasCustomAlertCore = false, bool hasMuteRuleReloadBeacon = false, bool hasBuiltinAlertPersistence = false, bool hasRetentionHoldRatioKnobs = false, bool hasDeadlockRateBandKnobs = false, bool hasOversizedPlanBacklog = false, bool hasPgAlertCountKnobs = false, bool hasFleetSweepState = false, bool hasFleetSweepCadenceKnobs = false, bool hasCollectorScheduleDatabases = false, bool hasSelfDiskWarnGbFloor = false, bool hasDeltaFamilyIntervalColumns = false, bool hasDeltaFamilyIntervalCompletion = false) + internal static int MapProbedSchemaVersion(bool hasConfigControlPlane, bool hasAlertDeliveryOverride, bool hasAnalysisState, bool hasAlertTuningKnobs, bool hasDefaultTraceEvents, bool hasIndexObjectStatsLatestIndex, bool hasCollectionLogHypertableOrPlainPg, bool hasJobHistory, bool hasAgentStatus, bool hasGenericWebhook, bool hasDeadlocksDatabaseName, bool hasQueryStoreReplicaRole, bool hasLongQueryCompletions, bool hasWebDashboardConfig, bool hasCustomViews, bool hasServerTags, bool hasConnectionRefireKnobs = false, bool hasAgCollectors = false, bool hasAgAlertKnobs = false, bool hasAgLatencyColumns = false, bool hasAgDisconnectRefire = false, bool hasPayloadDimensions = false, bool hasDimFloorIndexes = false, bool hasBlockingWaitThreshold = false, bool hasQueryStoreIntervalIdentity = false, bool hasPagerDutyWebhook = false, bool hasPagerDutyProxy = false, bool hasCollectorState = false, bool hasPlanCorrection = false, bool hasPvsStats = false, bool hasPvsPressureKnobs = false, bool hasDatabaseStateAlert = false, bool hasServerTagColour = false, bool hasQueryStatsHostObject = false, bool hasFindingDrillDown = false, bool hasStoreMetrics = false, bool hasPlanDimGzip = false, bool hasSelfAlertKnobs = false, bool hasJobMetricsColumns = false, bool hasJobCadenceKnob = false, bool hasBackfillSwitch = false, bool hasCollectorMemoryKnobs = false, bool hasDatabaseStateEdgeMemory = false, bool hasIncidentOccurrences = false, bool hasPlanXmlCompressionKnob = false, bool hasMonitoredServerEngine = false, bool hasPgBlockingEdges = false, bool hasQueryStorePlanMap = false, bool hasPgStatementText = false, bool hasQueryStoreText = false, bool hasPlanContentRetentionKnob = false, bool hasQueryStoreHealth = false, bool hasQueryStoreTextHash = false, bool hasComposeTimeoutKnob = false, bool hasFileGrowthAlert = false, bool hasCollectionLogFanoutRollup = false, bool hasTempDbMaxSize = false, bool hasServerEngineKind = false, bool hasPgDatabaseStats = false, bool hasPgIndexUsageStats = false, bool hasPgTableBloatStats = false, bool hasPgSessionStates = false, bool hasPgPlanCaptureReadiness = false, bool hasPgWriteStats = false, bool hasPgExtensionAvailability = false, bool hasPgLockStats = false, bool hasPgColumnStats = false, bool hasPgReplicationStats = false, bool hasPgBufferUsage = false, bool hasPgIndexBloat = false, bool hasPgPerDatabaseAttribution = false, bool hasPgWaitSampling = false, bool hasPgKernelStats = false, bool hasPgPredicateStats = false, bool hasPgPlanCapture = false, bool hasPgMajorVersion = false, bool hasPg18IoBytes = false, bool hasPgServerConfig = false, bool hasPgDeadlocks = false, bool hasPgDeadlockIdentity = false, bool hasCollectorCost = false, bool hasPgCpuUtilization = false, bool hasPlanForceActions = false, bool hasCollectionLogPhaseSplit = false, bool hasCollectionLogDrainForensics = false, bool hasCollectionLogFetchPhaseSums = false, bool hasStoreLogSelfMonitoring = false, bool hasCollectorStallProbes = false, bool hasRemediationCredentialAndActor = false, bool hasPgIndexBloatEstimate = false, bool hasPgCpuCapacityHeadroom = false, bool hasCustomAlertCore = false, bool hasMuteRuleReloadBeacon = false, bool hasBuiltinAlertPersistence = false, bool hasRetentionHoldRatioKnobs = false, bool hasDeadlockRateBandKnobs = false, bool hasOversizedPlanBacklog = false, bool hasPgAlertCountKnobs = false, bool hasFleetSweepState = false, bool hasFleetSweepCadenceKnobs = false, bool hasCollectorScheduleDatabases = false, bool hasSelfDiskWarnGbFloor = false, bool hasDeltaFamilyIntervalColumns = false, bool hasDeltaFamilyIntervalCompletion = false, bool hasPgLogEvents = false) { /* V71 (the PostgreSQL blocking-edges rung): a table-existence sentinel and now the newest-first arm. A collector table would ordinarily get no arm at all — see the V63-V69 note below — but the TOP @@ -1029,9 +1033,9 @@ V71 finding (the coverage ratchet strips information_schema lines but cannot str After this rung every delta family stores the interval, so a restart's fabricated (0, 0) row can be told from a genuinely idle one at EVERY read, and the restart seed can rebuild the one key the store could not reproduce. COLUMN-existence sentinel (the five tables have existed since - V4/V10 and V63/V64, so table existence cannot separate the rungs), newest-first, and the TOP - rung, so a fully-migrated store maps to EXACTLY StorageVersion.SchemaVersion rather than falling - through to the rung below and showing a spurious upgrade banner on a store that is current. + V4/V10 and V63/V64, so table existence cannot separate the rungs), newest-first, one rung + behind the top since V129 landed — a store carrying this and not V129 above maps to 128, which + is the honest answer for it and also what makes the upgrade banner correct in both directions. The gate earns its place beyond that standing invariant: the viewer's procedure duration trend and procedure history reads now name the column (the stored interval is preferred over the LAG @@ -1039,6 +1043,21 @@ and procedure history reads now name the column (the stored interval is preferre Trends and Top Procedures surfaces — the banner has to fire before those do. The column and its tables are named only in the probe line, not this prose, per the V71 finding: the coverage ratchet strips information_schema lines but cannot strip a comment. */ + /* V129 (#3601): collect.pg_log_events, the classified log-event pipeline's table — the third + reader of the PostgreSQL server log and the first to carry more than one family (errors, + connections, lock waits, and the recognised-only spill / autovacuum / checkpoint shapes). + TABLE-existence sentinel, like V103's and V106's before it, newest-first, and the TOP rung, so a + fully-migrated store maps to EXACTLY StorageVersion.SchemaVersion rather than falling through to + the rung below and showing a spurious upgrade banner on a store that is current. + + The gate earns its place beyond that standing invariant: the PostgreSQL Activity tab's log-events + panel reads the table by name, so a viewer pointed below this rung would throw a raw 42P01 on + that tab — the banner has to fire before the tab does. */ + if (hasPgLogEvents) + { + return 129; + } + if (hasDeltaFamilyIntervalCompletion) { return 128; diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs index 86a064d694..1bf9c06418 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerPostgresTabs.cs @@ -97,7 +97,7 @@ appears with the reason it is missing. */ ViewerServerTab.PgActivityInnerTabIndex, "activity", "Activity", - new[] { "pg_blocking", "pg_lock_stats", "pg_statement_stats", "pg_database_stats", "pg_kernel_stats", "pg_plan_capture", "pg_deadlocks" }, + new[] { "pg_blocking", "pg_lock_stats", "pg_statement_stats", "pg_database_stats", "pg_kernel_stats", "pg_plan_capture", "pg_deadlocks", "pg_log_events" }, /* pg_database_stats sits under the statement grid rather than on a tab of its own because it answers the question the statement grid raises and cannot answer: a statement whose time makes no sense from its row count usually spilled, and pg_stat_database's temp counters are diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs index a60c9b952d..96f66eecf8 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.Postgres.cs @@ -335,6 +335,41 @@ reason the read carries capture counts from collection_log. */ await LoadPgKernelStatsAsync(startUtc, endUtc); await LoadPgPlanCaptureAsync(startUtc, endUtc); await LoadPgDeadlocksAsync(startUtc, endUtc); + await LoadPgLogEventsAsync(startUtc, endUtc); + } + + /// + /// The classified log events (#3601), under the deadlocks grid on the Blocking sub-tab: the window's + /// newest 200 distinct entries across every family. The family and severity filters are the MCP read's + /// (get_pg_log_events); this grid is the glance, and the note names which setting a quiet family + /// depends on, because an all-off target looks exactly like a quiet one here. + /// + private async Task LoadPgLogEventsAsync(DateTime startUtc, DateTime endUtc) + { + if (PgCollectorIsGatedOff("pg_log_events")) + { + PgLogEventsGrid.ItemsSource = null; + PgLogEventsNote.Text = PanelNote("pg_log_events", 0, string.Empty); + return; + } + + var page = await _dataService.GetPgLogEventsAsync(_server.ServerId, startUtc, endUtc); + + PgLogEventsGrid.ItemsSource = page.Rows; + + PgLogEventsNote.Text = PanelNote("pg_log_events", page.Rows.Count, + "No classified log event was stored in this window. That is the healthy answer for the error " + + "and lock-wait families, and it is also what a target with the relevant settings off looks " + + "like: connection lines need log_connections / log_disconnections, lock waits need " + + "log_lock_waits, spills need log_temp_files, autovacuum runs need log_autovacuum_min_duration. " + + "It is also what an unreadable log, a non-UTC log_timezone or a non-English lc_messages looks " + + "like — the Vacuum tab's plan-capture readiness panel reads the same file and reports those.") + + (page.Rows.Count == 0 + ? string.Empty + : $" Showing {page.Rows.Count} of {page.WindowTotal} distinct entries in the window, newest " + + "first; message and detail are redacted at the collector and the statement text is never " + + "stored, only fingerprinted. Sightings counts how often the collector saw the SAME line " + + "while it stayed inside the log tail it re-reads."); } /// diff --git a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml index 581c878ccf..fb0effc0c4 100644 --- a/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml +++ b/Darling/PerformanceMonitor.Darling.Viewer/ViewerServerTab.xaml @@ -3795,6 +3795,8 @@ + + @@ -3874,6 +3876,37 @@ + + + + + + + + + + + + + + + + + + + + + + diff --git a/Darling/README.md b/Darling/README.md index de506f185b..06e1cbf1a0 100644 --- a/Darling/README.md +++ b/Darling/README.md @@ -729,7 +729,7 @@ GRANT pg_read_all_data TO darling_monitor; -- PostgreSQL 14+, see below | `pg_server_config` | `pg_settings` | 60 min / 365 d | The configuration history — nothing else in the stack can reconstruct one that was never recorded. Hourly because configuration changes when a person changes it, and a year because "this got slow sometime last quarter" is asked long after the fact; `get_pg_server_config_changes` reads consecutive snapshots, so the change and its timing survive the person who made it. `source` is stored so the read can state which rows are server configuration and which are the collector's own session | | `pg_deadlocks` | the server log via `pg_read_file()`; the RDS log API on Aurora/RDS | 5 min / 90 d | The full deadlock reports PostgreSQL writes to its log — previously only the COUNT (`pg_stat_database.deadlocks`) was collected, a number that goes up. `deadlock_hash` is the identity: the self-hosted route re-reads an overlapping log tail deliberately, so one deadlock lands many times and every read groups on the hash. `graph_text` is stored whole beside the parsed columns, so a lock shape the parser does not break out still arrives readable by a person. Needs nothing enabled at default settings, but `log_error_verbosity = terse` and a non-English `lc_messages` both silently empty it — the readiness collector's `message_locale` facet judges the latter | | `pg_plan_capture` | `auto_explain` JSON in the server log via `pg_read_file()`; the RDS log API on Aurora/RDS | 60 min / 14 d | Captured execution plans, redacted before storage: query text is dropped outright (identity is `query_id`, whose normalised text `pg_statement_stats` carries) and every remaining string literal is scrubbed, with `plan_hash` taken of the REDACTED plan so a shape recurs to one hash whatever values it ran with. The self-hosted read is a fixed 4 MB tail — #2565 measured 772 MB of log in twenty seconds at capture-everything, so no fixed number bounds the worst case — and a server logging faster than the window covers should lower the cadence per server | -| `pg_log_events` | the server log via `pg_read_file()`; the RDS log API on Aurora/RDS | 5 min / 30 d | The log, CLASSIFIED (#3601): every line at WARNING or worse as an `error` event, `log_connections` / `log_disconnections` lines as `connection`, `log_lock_waits` reports as `lock_wait`, and `log_temp_files`, autovacuum and checkpoint lines recognised and stored under their family for the structured tables #3602 / #3603 add. The same 4 MB tail and the same `logging_collector` gate as `pg_deadlocks`, classified in C# by one `PgLogEventClassifier` both transports feed — the body crosses the wire so no family's recogniser is spelled twice. `message` / `detail` are redacted with the plan parser's own patterns and the statement is never stored, only fingerprinted; `raw_line_hash` is the identity every read dedupes on. A family whose `log_*` setting is off on the target is empty by construction; the read names the setting | +| `pg_log_events` | the server log via `pg_read_file()`; the RDS log API on Aurora/RDS | 5 min / 30 d | The log, CLASSIFIED (#3601): every line at WARNING or worse as an `error` event, `log_connections` / `log_disconnections` lines as `connection`, `log_lock_waits` reports as `lock_wait`, and `log_temp_files`, autovacuum and checkpoint lines recognised and stored under their family for the structured tables #3602 / #3603 add. The same 4 MB tail and the same `logging_collector` gate as `pg_deadlocks`, classified in C# by one `PgLogEventClassifier` both transports feed — the body crosses the wire so no family's recogniser is spelled twice. `message` / `detail` / `context` are redacted with the plan parser's own patterns and the statement is never stored, only fingerprinted; `raw_line_hash` is the identity every read dedupes on. A family whose `log_*` setting is off on the target is empty by construction; the read names the setting | | `pg_plan_capture_readiness` | `pg_settings` (the `auto_explain` and logging GUCs) | 60 min / 365 d | Whether the target could capture plans at all, one row per facet in causal order — could it run `auto_explain`, is it loaded, is it capturing, in what format, and can a plan be attributed to a statement — because "no plans" has several unrelated causes and each carries its own remedy on the row. Hourly since every facet is a parameter-group setting; a year because "when did plan capture get turned on" is asked months later | | `pg_write_stats` | `pg_stat_checkpointer`, `pg_stat_bgwriter`, `pg_stat_wal` | 1 min / 30 d | Checkpoints, background writing and WAL as ONE collector because they are one story: a high share of REQUESTED checkpoints means WAL filled `max_wal_size` before the interval elapsed. A union schema with version-conditional columns — PostgreSQL 17 moved the checkpoint counters out of `pg_stat_bgwriter`, so a major that lacks a column reports NULL rather than the collector splitting into per-version twins. PostgreSQL 14+ (`pg_stat_wal`); all three views are cluster-wide singletons, so a snapshot is one row | | `pg_lock_stats` | `pg_locks` | 1 min / 30 d | Lock state by type, mode and relation, granted or waiting. Does NOT duplicate `pg_blocking_edges`, which stores blocked/blocker PAIRS — that answers who is stuck behind whom, and cannot answer what lock, on what object, is being waited on. Aggregated by (database, locktype, mode, granted, relation), so row count is bounded by CONTENTION rather than concurrency — and it is a SAMPLE, so the cadence is the resolution | @@ -830,7 +830,7 @@ The notable rungs are below. For the **complete** current schema, read `Darling/ | **V102** — PostgreSQL server configuration | `collect.pg_server_config` + its time index (#2658): every `pg_settings` row, hourly for a year — SQL Server answers this three ways and PostgreSQL had no answer at all, and no other part of the stack can reconstruct a configuration history that was never recorded. Nothing is filtered at collection: `source` is stored so the READ can state which rows are server configuration and which are the collector's own session, where the rule can be enforced and explained | | **V103/V104** — PostgreSQL deadlocks | `collect.pg_deadlocks` + its time index, then the `deadlock_hash` lookup index as its own rung (#2661): the full reports PostgreSQL writes to its log — we collected the COUNT (`pg_stat_database.deadlocks`) and nothing else. `deadlock_hash` is the identity, because the `pg_read_file` route re-reads an OVERLAPPING tail deliberately so one deadlock lands many times, and every read groups on the hash to answer once per deadlock. `graph_text` is stored whole beside the parsed columns, so a lock shape the parser does not recognise still arrives readable by a person. The index is a separate rung because the schema-generator pin permits exactly one index per collector rung — split out, BOTH fresh and upgraded stores get it | | **V106** — PostgreSQL instance CPU | `collect.pg_cpu_utilization` + its time index (#2719): instance-level CPU for an Aurora target, from the Performance Insights API. This collector has no SQL route at all — PostgreSQL exposes no instance-level CPU signal — so every row arrives through the monitoring host's AWS identity, never a database connection | -| **V129** — PostgreSQL log events | `collect.pg_log_events` + its time index (#3601): the classified server-log events — `occurred_at`, `family`, `severity`, `sqlstate`, `database_name`, `user_name`, `application_name`, `pid`, redacted `message` / `detail`, `statement_fingerprint` (a hash of the REDACTED statement; the text itself is never stored) and `raw_line_hash`, the identity every read dedupes on because the `pg_read_file` route re-reads an overlapping tail. Column-for-column what the generator emits, like every collector rung, which is why the `(server_id, family, collection_time)` index a family-filtered read over a long window would want is a SEPARATE rung when it comes — V104's reason. Thirty-day retention, from the schedule table | +| **V129** — PostgreSQL log events | `collect.pg_log_events` + its time index (#3601): the classified server-log events — `occurred_at`, `family`, `severity`, `sqlstate`, `database_name`, `user_name`, `application_name`, `pid`, redacted `message` / `detail` / `context`, `statement_fingerprint` (a hash of the REDACTED statement; the text itself is never stored) and `raw_line_hash`, the identity every read dedupes on because the `pg_read_file` route re-reads an overlapping tail. Column-for-column what the generator emits, like every collector rung, which is why the `(server_id, family, collection_time)` index a family-filtered read over a long window would want is a SEPARATE rung when it comes — V104's reason. Thirty-day retention, from the schedule table | | **V72** — Query Store plan map | `collect.query_store_plan_map` — `(server_id, database_name, plan_id)` → digest, so Query Store facts can reference plan XML they no longer carry once that content moves into the shared `query_plan_dim`. Plan XML was stored INLINE on `query_store_stats` at roughly 5x redundancy. Not a hypertable: one row per distinct plan per database, so it is dimension-shaped and pruned on `last_seen` rather than by `drop_chunks`. Its `last_seen` is load-bearing — the dimension GC sweeps on timestamps rather than counting references, so ending the re-shipping also ends the liveness signal that used to keep those dim rows alive | | **V73** — PostgreSQL statement text | `collect.pg_statement_text` — `(server_id, queryid)` → statement text, refreshed hourly, so `get_pg_top_queries` returns something readable (#2219). `pg_statement_stats` stores no text because `showtext` is a real per-collection cost and normalized text is highly repetitive; but `queryid` is NOT stable across a major version upgrade, so without this the stored history joins to nothing after one — a list of integers that used to be your slowest queries, unrecoverable because the live view no longer holds the old ids. Text is INLINE rather than a `query_text_dim` digest: the dimension route needs the GC liveness interlock whose failure mode is silently missing text, and inline cannot dangle. Not a hypertable and not a collector table, exactly like V72 — a bespoke upsert path, pruned on `last_seen` with a margin that makes text OUTLIVE the statistics referencing it | | **V76** — Query Store health | `collect.query_store_health` + its index + the `v_query_store_health` passthrough view — the #2319 per-database `sys.database_query_store_options` collector's store table: actual vs desired state (the cap-hit READ_ONLY transition and its readonly_reason), current vs max storage, cleanup thresholds, and the runtime-stats interval length. A fresh store gets the table from V1's generated schema; V76 is what an already-existing store gets | diff --git a/PerformanceMonitor.Collectors/PgLogEvent.cs b/PerformanceMonitor.Collectors/PgLogEvent.cs index c87748192f..5ff3920a41 100644 --- a/PerformanceMonitor.Collectors/PgLogEvent.cs +++ b/PerformanceMonitor.Collectors/PgLogEvent.cs @@ -31,6 +31,10 @@ namespace PerformanceMonitor.Collectors; /// The backend that wrote the line. /// REDACTED prose. /// REDACTED prose, or null. +/// REDACTED prose, or null — the CONTEXT: companion: for a lock wait the tuple +/// and relation the waiter was on (while updating tuple (0,7) in relation "orders"), for an error +/// inside a function the frame (PL/pgSQL function f() line 3 at RAISE). Review caught the first +/// draft parsing it and dropping it while a doc comment claimed it was stored. /// Hash of the REDACTED statement, or null where the entry had none. /// Identity across sightings. See . public readonly record struct PgLogEvent( @@ -44,6 +48,7 @@ public readonly record struct PgLogEvent( int Pid, string Message, string? Detail, + string? Context, string? StatementFingerprint, string RawLineHash) { @@ -80,6 +85,11 @@ public static PgLogEvent From( Pid: entry.Pid, Message: PgLogTextRedactor.RedactMessage(entry.Message) ?? string.Empty, Detail: PgLogTextRedactor.RedactMessage(entry.Detail), + /* Prose-strength redaction, like Detail: a CONTEXT can carry an inner statement — `SQL statement + "UPDATE … WHERE id = 42"` — and that double-quoted run follows no identifier noun, so the + allowlist takes it whole. The HINT companion is deliberately NOT stored: it is advice text, + never evidence, and nothing here claims otherwise. */ + Context: PgLogTextRedactor.RedactMessage(entry.Context), StatementFingerprint: PgLogTextRedactor.Fingerprint(redactedStatement), RawLineHash: PgLogTextRedactor.RawLineHash(entry.RawText)); } diff --git a/PerformanceMonitor.Collectors/PgLogEventsCollector.cs b/PerformanceMonitor.Collectors/PgLogEventsCollector.cs index 3d44c64dde..fbb4538ac6 100644 --- a/PerformanceMonitor.Collectors/PgLogEventsCollector.cs +++ b/PerformanceMonitor.Collectors/PgLogEventsCollector.cs @@ -105,6 +105,8 @@ sibling issues and a CHECK would make each a rung. */ new CollectorColumn("message", CollectorColumnType.Varchar), /* REDACTED. */ new CollectorColumn("detail", CollectorColumnType.Varchar), + /* REDACTED. The CONTEXT companion — for a lock wait, the tuple and relation. */ + new CollectorColumn("context", CollectorColumnType.Varchar), /* Hash of the REDACTED statement; the statement itself is never stored. */ new CollectorColumn("statement_fingerprint", CollectorColumnType.Varchar), /* Identity across sightings — this route re-reads the tail every cycle, so the reads dedupe on it @@ -149,6 +151,7 @@ public override void WritePayload(PgLogEvent row, ICollectorRowWriter writer, Co .Value(row.Pid) .Value(row.Message) .Value(row.Detail) + .Value(row.Context) .Value(row.StatementFingerprint) .Value(row.RawLineHash); } diff --git a/PerformanceMonitor.Collectors/PgLogFamilyParsers.cs b/PerformanceMonitor.Collectors/PgLogFamilyParsers.cs index 920c17be4d..699da65a53 100644 --- a/PerformanceMonitor.Collectors/PgLogFamilyParsers.cs +++ b/PerformanceMonitor.Collectors/PgLogFamilyParsers.cs @@ -120,8 +120,10 @@ public bool TryParse(in PgLogEntry entry, out PgLogEvent logEvent) /// rearranging queue order after N ms, and detected deadlock while waiting for ... after N ms. /// The DETAIL names the holder and the queue (Process holding the lock: 4321. Wait queue: /// 1234.), the STATEMENT is the waiter's SQL, and the CONTEXT — where present — names the -/// tuple and relation. All of that survives redaction because it is pids, modes and identifiers; the -/// statement is fingerprinted. +/// tuple and relation (while updating tuple (0,7) in relation "orders"). The message, detail and +/// context are stored redacted, and survive it because they are pids, modes and identifiers after a noun; +/// the statement is fingerprinted and never stored. (The first draft claimed the context survived while +/// the row had no column for it — review caught the gap, and the column exists because of it.) /// /// What this is beside pg_blocking. That collector SAMPLES pg_blocking_pids() on /// a cadence and can miss a wait that starts and ends between samples; this is the server's own record of diff --git a/PerformanceMonitor.Collectors/PgLogTextRedactor.cs b/PerformanceMonitor.Collectors/PgLogTextRedactor.cs index 8a6ca22dcf..d29057a4f7 100644 --- a/PerformanceMonitor.Collectors/PgLogTextRedactor.cs +++ b/PerformanceMonitor.Collectors/PgLogTextRedactor.cs @@ -109,10 +109,15 @@ sentence PostgreSQL writes after the tuple (`already exists.`, `is duplicated.`, @"\bFailing row contains \(.*\)(?=[^)]*$)", RegexOptions.Compiled | RegexOptions.CultureInvariant | RegexOptions.Singleline); - /* Every remaining double-quoted run, with what precedes it captured so the allowlist can be asked. */ + /* Every remaining double-quoted run, with what precedes it captured so the allowlist can be asked. The + word-and-space lead is tried first so `relation "x"` reaches the allowlist with its noun; the fallback + is ANY single character — a bare space, a newline at the head of a tab-continuation, punctuation — so + every double-quoted run is evaluated and one preceded by nothing recognisable is redacted rather than + skipped. Review found the first draft's fallback matched non-space only, which left a quote after two + spaces or after a newline neither redacted nor allowlisted. */ private static readonly Regex s_doubleQuoted = new( - @"(?(?:[A-Za-z_]+=|\b[A-Za-z_]+\s|^|\S))(?""[^""]*"")", - RegexOptions.Compiled | RegexOptions.CultureInvariant); + @"(?(?:[A-Za-z_]+=|\b[A-Za-z_]+\s|^|.))(?""[^""]*"")", + RegexOptions.Compiled | RegexOptions.CultureInvariant | RegexOptions.Singleline); /* The words PostgreSQL puts before a double-quoted IDENTIFIER. A run preceded by one of these is a name and stays; a run preceded by anything else is treated as a value. Enumerated rather than