Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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
Expand Down
71 changes: 57 additions & 14 deletions Darling/Darling.Tests/DarlingSelfAlertTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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()
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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: <c>sys.dm_hadr_*</c> 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 <c>notify_ag_health</c> master switch, with the two thresholds
/// (<c>ag_lag_alert_seconds</c>, <c>ag_redo_queue_alert_kb</c>) store-backed alongside it. Keyed per AG
/// grain rather than per server, because a server hosts many replicas and databases.</item>
Expand Down Expand Up @@ -666,10 +670,10 @@ internal readonly record struct AgDatabaseReading(
/// very event that made it worse.</summary>
internal enum AgSyncJudgement
{
/// <summary>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
/// <see cref="ApplyAgentNotRunningAsync"/> uses for a stale agent_status reading.</summary>
/// <summary>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 <see cref="ApplyAgentNotRunningAsync"/> uses for a stale
/// agent_status reading.</summary>
NotMeasurable,

/// <summary>Measured, and within threshold.</summary>
Expand All @@ -687,23 +691,34 @@ internal enum AgSyncJudgement
/// <item><b>Lag seconds</b> — <c>secondary_lag_seconds &gt;= ag_lag_alert_seconds</c>.</item>
/// <item><b>Redo queue</b> — <c>redo_queue_size &gt;= ag_redo_queue_alert_kb</c> (KB).</item>
/// </list>
/// <para>THE TRAP this method exists to encode: MS Learn documents <c>secondary_lag_seconds</c> reading
/// <c>0</c> — 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.</para>
/// <para>Abstaining has to be its OWN answer rather than a <c>false</c>, 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.</para>
/// <para>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 <c>secondary_lag_seconds</c> "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.</para>
/// <para>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 <c>0</c> (documented), that <c>0</c> 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.</para>
/// <para>Not clearing has to be its OWN answer rather than a <c>false</c>, 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.</para>
/// <para>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.</para>
/// </summary>
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)
Expand All @@ -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;
}

Expand Down
Loading