diff --git a/CHANGELOG.md b/CHANGELOG.md index 1f21191d..2794a392 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -42,6 +42,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **Darling: a suspended secondary that is falling behind now raises the sync alert** ([#1700]) - the "AG Sync Fell Behind" lag trigger shipped in [#1692] made its seconds check ABSTAIN on a suspended row, written to MS Learn's statement that `secondary_lag_seconds` "shows as 0 if the data movement is suspended" - abstaining looked like the careful reading, since a zero would otherwise report the database that is furthest behind as caught up. **The documentation is wrong.** Measured against a live Availability Group (SQL Server 2022 16.0.4265.3, clusterless AG, write load, sampled across a `SUSPEND_FROM_USER` on the secondary), lag ACCRUES monotonically at wall-clock rate while suspended - 3993, 4005, 4017, 4029, 4041 across four 12-second intervals - and returns to 0 on resume. So the abstention was not caution, it was silencing the alert on suspended data movement: the single most common way a secondary falls behind, and the case an operator most needs paging for. A suspended secondary could drift arbitrarily far behind while only "AG Database Suspended" fired once, on the edge. Replaced with an asymmetry - **a suspended row may raise an alarm but may never clear one** - which is deliberately correct under BOTH behaviors rather than betting on the measurement: if lag accrues it crosses the threshold and fires, and if it ever did read 0 that zero is under the threshold and yields "not measurable" rather than "caught up", so it still cannot resolve a standing alert. The same rule now protects the redo-queue trigger, whose value FREEZES at its last reading while suspended (also measured): frozen and over the threshold is a real backlog worth firing on, frozen and under it is stale data that must not clear anything - previously a small frozen queue could resolve a live alert. Two more measured behaviors are documented rather than coded around: `log_send_queue_size` reads NULL while suspended instead of growing, so it is useless as a fell-behind signal (this evaluator never used it), and on RESUME the secondary has a genuine backlog to drain (388,620 KB after a 60-second suspend under load), so a single-sample redo threshold fires during legitimate catch-up - not wrong, since the data-loss window really is open until it drains, but it is why that trigger ships off. Evidence from the Docker AG fixture; the suspend/resume cycle was re-run independently before the shipped logic was changed. - **Darling: the Availability Group store reads are now executed against a real Postgres in CI** ([#1697]) - the two AG reads added in [#1692] had no test that ran their SQL, and that was the one gap that mattered: the defect they were corrected for during review is invisible to a unit test. Both grains were briefly read as two statements over a SINGLE command to save a round trip, which PostgreSQL rejects - Npgsql only splits multi-statement text into a batch when it parses the SQL for NAMED placeholders, so with the positional (`$1`) parameters those reads use it sends one extended-protocol `Parse` and the server answers `cannot insert multiple commands into a prepared statement`. Every AG path is failure-isolated, so it would not have crashed anything; it would have logged one error per server per sweep with the whole alert family silently dead, which is the worst failure mode a monitoring product has - the thing that is broken is the thing that tells you something is broken. The new `DARLING_TEST_PG`-gated test seeds both collector tables and asserts what only real SQL can prove: that each query executes, that the newest-snapshot predicate excludes an older one, that a row with a NULL identity column is dropped rather than keyed under a placeholder, that NULL lag and suspend-reason columns round-trip, and that the path reaches the sweep entry point and fires exactly one alert off freshly seeded rows. - **Lite + Darling: recovery notices were being styled and counted as live alerts in Alert History and the Daily Summary** ([#1692]) - `AlertMetricClassifier.IsResolution` is the shared source of truth for "this row is good news, not something to act on", and it recognized only the `Cleared` / `Resolved` / `Restored` suffixes. Darling's self-alert recoveries have been emitting `Collection Resumed`, `Agent Restarted` and `Compression Job Recovered` - written by the very same recovery path as the recognized `Capture Restored` - and every one of them landed in BOTH apps' Alert History grids styled as an actionable alert, and was counted as one in the Daily Summary's per-day alert totals. This is the same drift #1225 fixed one layer up, recurring one layer down. Widened the suffix set to `Resumed` / `Restarted` / `Recovered` / `Reconnected` (no actionable metric name in either app contains those words, so nothing real turns green), and widened both hand-maintained SQL copies of that list - Darling's `DailySummarySql` and Lite's `LocalDataService.DailySummary` - which is where the miscount came from. @@ -1668,6 +1669,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 [#1691]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1691 [#1692]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1692 [#1697]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1697 +[#1700]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1700 [#1690]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1690 [#1693]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1693 [#1694]: https://github.com/erikdarlingdata/PerformanceMonitor/pull/1694 diff --git a/Darling/Darling.Tests/DarlingSelfAlertTests.cs b/Darling/Darling.Tests/DarlingSelfAlertTests.cs index 2f87c0c6..7d411995 100644 --- a/Darling/Darling.Tests/DarlingSelfAlertTests.cs +++ b/Darling/Darling.Tests/DarlingSelfAlertTests.cs @@ -1000,32 +1000,39 @@ distinction matters because only a measured CaughtUp resolves a standing alert. } [Fact] - public void JudgeAgSync_SuspendedDatabase_AbstainsOnSeconds_ButStillJudgesTheRedoQueue() + public void JudgeAgSync_SuspendedDatabase_MayFire_ButMayNeverResolve() { - /* THE TRAP: MS Learn documents secondary_lag_seconds reading 0 — not NULL — while movement is - SUSPENDED, so the database that is furthest behind reports as caught up. The seconds trigger - therefore abstains, and with only that trigger enabled the row is NOT MEASURABLE — emphatically not - CaughtUp, which would resolve the standing alert at the exact moment things got worse. */ + /* Measured against a live AG: secondary_lag_seconds ACCRUES while suspended, it does not read 0 the + way MS Learn documents. A suspended secondary drifting past the threshold is the single most common + way a secondary falls behind, so it MUST fire — an earlier rule that abstained on suspended rows + silenced exactly that case. */ Assert.Equal( - DarlingSelfAlertEvaluator.AgSyncJudgement.NotMeasurable, - Judge(DatabaseRow(lagSeconds: 0, suspended: true), 300, 0)); + DarlingSelfAlertEvaluator.AgSyncJudgement.Behind, + Judge(DatabaseRow(lagSeconds: 9999, suspended: true), 300, 0)); - /* Even a NON-zero lag reading is ignored while suspended — the column is not trustworthy in that - state at all, so the rule is "suspended means the seconds trigger abstains", not "suspended plus - zero". */ + /* The other half of the asymmetry, and the reason this is not simply "judge suspended rows normally": + a suspended reading UNDER the threshold is not evidence of recovery. Were the documented zero-lag + behavior ever real, this is the row it would produce, and calling it CaughtUp would resolve a + standing alert at the exact moment things got worse. NotMeasurable is correct under both behaviors. */ Assert.Equal( DarlingSelfAlertEvaluator.AgSyncJudgement.NotMeasurable, - Judge(DatabaseRow(lagSeconds: 9999, suspended: true), 300, 0)); + Judge(DatabaseRow(lagSeconds: 0, suspended: true), 300, 0)); - /* The redo queue keeps judging while suspended: that backlog is real and still growing. */ + /* The redo queue fires while suspended too — a frozen queue over the threshold is a real backlog. */ Assert.Equal( DarlingSelfAlertEvaluator.AgSyncJudgement.Behind, Judge(DatabaseRow(lagSeconds: 0, redoKb: 8192, suspended: true), 300, 4096)); - /* ...and a suspended row with a SMALL redo queue is genuinely measured, so it may resolve. */ + /* ...but a frozen queue UNDER the threshold is stale data, not a recovery: redo_queue_size freezes at + its last value while suspended (measured), so it cannot clear anything either. */ Assert.Equal( - DarlingSelfAlertEvaluator.AgSyncJudgement.CaughtUp, + DarlingSelfAlertEvaluator.AgSyncJudgement.NotMeasurable, Judge(DatabaseRow(lagSeconds: 0, redoKb: 8, suspended: true), 300, 4096)); + + /* Once movement resumes, the same small readings are a real measurement and DO resolve. */ + Assert.Equal( + DarlingSelfAlertEvaluator.AgSyncJudgement.CaughtUp, + Judge(DatabaseRow(lagSeconds: 0, redoKb: 8, suspended: false), 300, 4096)); } [Fact] @@ -1279,6 +1286,42 @@ than starting a fresh episode from a phantom recovery. The resume itself is a hi Assert.Equal("AG Data Movement Resumed", Assert.Single(h.History.Records).MetricName); } + [Fact] + public async Task AgSyncFellBehind_SuspendedSecondaryDriftingPastTheThreshold_Fires() + { + var h = new Harness(); + var e = h.Build(); + + /* Healthy baseline, then movement is suspended. The suspend edge fires on its own. */ + await e.ApplyAgDatabaseHealthAsync(ServerId, Name, new[] { DatabaseRow(lagSeconds: 0) }, Ct); + await e.ApplyAgDatabaseHealthAsync( + ServerId, Name, new[] { DatabaseRow(lagSeconds: 12, suspended: true, suspendReason: "SUSPEND_FROM_USER") }, Ct); + Assert.Single(h.Deliverer.Outcomes); + Assert.Equal("AG Database Suspended", h.Deliverer.Outcomes[0].MetricName); + + /* Time passes and the lag accrues past the threshold while still suspended. This is the case the + product exists to catch, and the rule this test guards used to silence it: lag really does climb + while suspended (measured on a live AG), so the sync alert has to fire on its own rather than + trusting the suspend alert to have said everything. */ + await e.ApplyAgDatabaseHealthAsync( + ServerId, Name, new[] { DatabaseRow(lagSeconds: 600, suspended: true, suspendReason: "SUSPEND_FROM_USER") }, Ct); + + Assert.Equal(2, h.Deliverer.Outcomes.Count); + Assert.Equal("AG Sync Fell Behind", h.Deliverer.Outcomes[1].MetricName); + Assert.Contains("600 seconds behind", h.Deliverer.Outcomes[1].DetailText, StringComparison.Ordinal); + + /* Still suspended, still behind, inside the cooldown: no spam. */ + await e.ApplyAgDatabaseHealthAsync( + ServerId, Name, new[] { DatabaseRow(lagSeconds: 700, suspended: true) }, Ct); + Assert.Equal(2, h.Deliverer.Outcomes.Count); + + /* Resumed and genuinely caught up: NOW it resolves, off a measurement taken while movement was + running. Both the resume and the sync recovery are history rows. */ + await e.ApplyAgDatabaseHealthAsync(ServerId, Name, new[] { DatabaseRow(lagSeconds: 0) }, Ct); + Assert.Contains(h.History.Records, r => r.MetricName == "AG Sync Recovered"); + Assert.Contains(h.History.Records, r => r.MetricName == "AG Data Movement Resumed"); + } + [Fact] public async Task AgSyncFellBehind_NullReadingsUnderQuorumLoss_DoNotResolveTheStandingAlert() { diff --git a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs index 6092de56..e30b3661 100644 --- a/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs +++ b/Darling/PerformanceMonitor.Darling.Service/DarlingSelfAlertEvaluator.cs @@ -54,6 +54,10 @@ namespace PerformanceMonitor.Darling.Service; /// a replica changed role ("AG Failover"), a replica lost or regained its connection to the primary /// ("AG Replica Disconnected"/"AG Replica Reconnected"), a secondary fell behind by lag seconds or redo /// queue ("AG Sync Fell Behind"), and data movement for a database was suspended ("AG Database Suspended"). +/// VANTAGE MATTERS: sys.dm_hadr_* on a SECONDARY carries only that replica's own rows, so a +/// monitored secondary yields a one-row self-view of its AG rather than the whole topology (measured on a +/// clusterless AG). Nothing here assumes it can see every replica from any node — the rules simply judge +/// whatever rows arrive, keyed per ag+replica — but full AG coverage requires monitoring the primary. /// Gated on the V35 notify_ag_health master switch, with the two thresholds /// (ag_lag_alert_seconds, ag_redo_queue_alert_kb) store-backed alongside it. Keyed per AG /// grain rather than per server, because a server hosts many replicas and databases. @@ -666,10 +670,10 @@ internal readonly record struct AgDatabaseReading( /// very event that made it worse. internal enum AgSyncJudgement { - /// No enabled trigger had a usable reading — both thresholds off, the columns NULL (the - /// primary's own row, or WSFC quorum loss), or the only enabled trigger is the seconds one on a - /// SUSPENDED row. No signal: neither fire nor clear, the discipline - /// uses for a stale agent_status reading. + /// Nothing trustworthy to judge on — both thresholds off, the columns NULL (the primary's own + /// row, or WSFC quorum loss), or a SUSPENDED row that is not over any threshold. No signal: neither + /// fire nor clear, the discipline uses for a stale + /// agent_status reading. NotMeasurable, /// Measured, and within threshold. @@ -687,23 +691,34 @@ internal enum AgSyncJudgement /// Lag seconds — secondary_lag_seconds >= ag_lag_alert_seconds. /// Redo queue — redo_queue_size >= ag_redo_queue_alert_kb (KB). /// - /// THE TRAP this method exists to encode: MS Learn documents secondary_lag_seconds reading - /// 0 — not NULL — while data movement is SUSPENDED. So the database that is furthest behind, the - /// suspended one, reports as perfectly caught up, and a naive seconds check would clear right when it - /// should page. The seconds trigger therefore ABSTAINS on a suspended row and "AG Database Suspended" owns - /// that state. The redo-queue trigger keeps judging while suspended, because that backlog is real and keeps - /// growing. - /// Abstaining has to be its OWN answer rather than a false, or the caller reads it as recovery: - /// a lagging database that becomes suspended (or whose columns go NULL under quorum loss) would emit - /// "AG Sync Recovered — has caught up with the primary" in the same sweep that reports it suspended. That - /// is why this returns three states and not a bool. + /// SUSPENDED ROWS MAY RAISE AN ALARM BUT MAY NEVER CLEAR ONE. That asymmetry replaces an earlier rule + /// that made the seconds trigger abstain entirely while suspended, which was written to MS Learn's claim + /// that secondary_lag_seconds "shows as 0 if the data movement is suspended". THE DOCUMENTATION IS + /// WRONG. Measured against a live AG (SQL Server 2022 16.0.4265.3, clusterless AG, write load, sampled + /// across a SUSPEND_FROM_USER): lag ACCRUES monotonically at wall-clock rate while suspended + /// (…3993 → 4005 → 4017 → 4029 → 4041 over four 12-second intervals) and returns to 0 on resume. Abstaining + /// therefore silenced the lag alert on a suspended secondary — the single most common way a secondary falls + /// behind, and the case an operator most needs paged for. + /// The alarm/clear asymmetry is deliberately correct under BOTH behaviors, so this does not have to + /// bet on one: if lag accrues (measured), a suspended secondary crosses the threshold and fires; if it ever + /// did read 0 (documented), that 0 is below threshold and yields NotMeasurable rather than + /// CaughtUp, so it still cannot resolve a standing alert. The same rule protects the redo trigger, whose + /// value FREEZES at its last reading while suspended (also measured) — a frozen value over the threshold is + /// a real backlog worth firing on, while a frozen value under it is stale data that must not clear + /// anything. + /// Not clearing has to be its OWN answer rather than a false, or the caller reads it as + /// recovery: a lagging database that becomes suspended (or whose columns go NULL under quorum loss) would + /// emit "AG Sync Recovered — has caught up with the primary" in the same sweep that reports it suspended. + /// That is why this returns three states and not a bool. + /// One consequence worth knowing when tuning the redo trigger: on RESUME the secondary has a real, + /// large backlog to drain (measured at 388,620 KB after a 60-second suspend under load), so a single-sample + /// redo threshold will fire during legitimate catch-up. That firing is not wrong — the data-loss window is + /// genuinely open until the queue drains — but it is why the redo trigger ships OFF. /// internal static AgSyncJudgement JudgeAgSync( AgDatabaseReading reading, int lagThresholdSeconds, long redoThresholdKb, out string reason) { - bool secondsUsable = lagThresholdSeconds > 0 - && reading.IsSuspended != true - && reading.SecondaryLagSeconds.HasValue; + bool secondsUsable = lagThresholdSeconds > 0 && reading.SecondaryLagSeconds.HasValue; bool redoUsable = redoThresholdKb > 0 && reading.RedoQueueSizeKb.HasValue; if (secondsUsable && reading.SecondaryLagSeconds!.Value >= lagThresholdSeconds) @@ -725,6 +740,16 @@ internal static AgSyncJudgement JudgeAgSync( } reason = ""; + + /* Under no threshold. A SUSPENDED row stops here rather than clearing: while movement is suspended the + lag reading cannot be trusted downward and the redo reading is frozen, so "not over the line" is not + evidence of recovery. "AG Database Suspended" is the alert that owns that state, and the sync alert + resolves only once movement is running again and a real measurement says so. */ + if (reading.IsSuspended == true) + { + return AgSyncJudgement.NotMeasurable; + } + return secondsUsable || redoUsable ? AgSyncJudgement.CaughtUp : AgSyncJudgement.NotMeasurable; }