diff --git a/docs/release-control/v6/internal/subsystems/alerts.md b/docs/release-control/v6/internal/subsystems/alerts.md index e00fd188b7..1e96e73aae 100644 --- a/docs/release-control/v6/internal/subsystems/alerts.md +++ b/docs/release-control/v6/internal/subsystems/alerts.md @@ -407,9 +407,10 @@ own inline boundary. A wearout arm keyed on `> 0` silently exempts the single worst reading a disk can publish, which let a spent SSD read critical on the Physical Disks surface while raising no alert at all. -Proxmox wearout recovery requires three consecutive reported readings of at -least 10% remaining life. An absent reading does not prove recovery, and a -new low reading resets the recovery run; until recovery is confirmed the +Proxmox wearout recovery requires three consecutive reported readings above +10% remaining life; a reading of exactly 10% still matches the alert. An +absent reading does not prove recovery, and a new low reading resets the +recovery run; until recovery is confirmed the existing alert retains its low-life value and occurrence. This bounds the resolved-then-refired notification loop when endurance data briefly looks healthy (#2112), while a sustained replacement/corrected reading can still @@ -418,6 +419,23 @@ resolve. `TestCheckDiskHealthWearoutFlappingDoesNotRepeatNotifications` and deduplication and confirmed recovery. This is synthetic source proof, not a claim that the reporter's installed image has been repaired. +The Proxmox wearout value is percent life remaining, so its alert message names +it that way (`SSD life remaining is 7%`), matching the host-agent SMART +`wearout_low` summary; the threshold travels in the alert's `Threshold` field, +which the Alerts card and notifications render beside the message. Calling the +number "wearout" read as 7% worn and contradicted the low-life warning. +`CheckDiskHealth` logs a failed disk at error and a worn disk at warn only on +the evaluation that opens the alert (the canonical `activated` transition); +later polls that still find the disk failed or at or below the wearout +threshold, including mock mode's per-tick evaluation, log at debug. Logging on +every evaluation repeated one failed disk's error on every poll for as long as +it stayed failed. `TestCheckDiskHealthLowWearoutCreatesAlert` pins the message +and `TestCheckDiskHealthLogsAlertOpeningOnce` pins the log-once boundary at the +threshold, including a fresh error when a recovered disk fails again. That test +captures logs through a hook installed in the package `TestMain`, because +assigning `log.Logger` inside a test races with managers earlier tests left +running. + Host SMART counter growth is an event boundary rather than a warning on every historical non-zero value. For an agent-only disk, the first reported UDMA CRC error count establishes an in-memory baseline and raises no alert. A later diff --git a/internal/alerts/alerts_test.go b/internal/alerts/alerts_test.go index 677d046d37..f67cbee911 100644 --- a/internal/alerts/alerts_test.go +++ b/internal/alerts/alerts_test.go @@ -25,6 +25,8 @@ import ( unifiedresources "github.com/rcourtman/pulse-go-rewrite/internal/unifiedresources" "github.com/rcourtman/pulse-go-rewrite/internal/utils" "github.com/rcourtman/pulse-go-rewrite/pkg/proxmox" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" ) // testEnvMu protects concurrent access to PULSE_DATA_DIR during parallel tests. @@ -176,6 +178,61 @@ func newTestManager(t *testing.T) *Manager { return m } +// testLogCapture collects log events for captureTestLogs. TestMain installs +// its hook before any test runs: writing log.Logger inside a test would race +// with goroutines of managers that earlier tests left running. +var testLogCapture struct { + mu sync.Mutex + active bool + lines []capturedLogLine +} + +type capturedLogLine struct { + level zerolog.Level + message string +} + +func TestMain(m *testing.M) { + log.Logger = log.Logger.Hook(zerolog.HookFunc(func(_ *zerolog.Event, level zerolog.Level, message string) { + testLogCapture.mu.Lock() + defer testLogCapture.mu.Unlock() + if testLogCapture.active { + testLogCapture.lines = append(testLogCapture.lines, capturedLogLine{level: level, message: message}) + } + })) + os.Exit(m.Run()) +} + +// captureTestLogs records log events, debug included, until the test ends. +// The returned func counts the events seen so far with a level and message. +func captureTestLogs(t *testing.T) func(zerolog.Level, string) int { + t.Helper() + originalLevel := zerolog.GlobalLevel() + zerolog.SetGlobalLevel(zerolog.DebugLevel) + testLogCapture.mu.Lock() + testLogCapture.active = true + testLogCapture.lines = nil + testLogCapture.mu.Unlock() + t.Cleanup(func() { + testLogCapture.mu.Lock() + testLogCapture.active = false + testLogCapture.lines = nil + testLogCapture.mu.Unlock() + zerolog.SetGlobalLevel(originalLevel) + }) + return func(level zerolog.Level, message string) int { + testLogCapture.mu.Lock() + defer testLogCapture.mu.Unlock() + n := 0 + for _, line := range testLogCapture.lines { + if line.level == level && line.message == message { + n++ + } + } + return n + } +} + func TestAcknowledgePersistsThroughCheckMetric(t *testing.T) { m := newTestManager(t) m.ClearActiveAlerts() @@ -4498,6 +4555,10 @@ func TestCheckDiskHealthLowWearoutCreatesAlert(t *testing.T) { if alert.Threshold != 10.0 { t.Errorf("expected threshold 10.0, got %f", alert.Threshold) } + // Wearout is life remaining: the message must not read as 5% worn. + if want := "SSD life remaining is 5%"; alert.Message != want { + t.Errorf("message = %q, want %q", alert.Message, want) + } if got := alert.Metadata["canonicalAlertKind"]; got != "severity-threshold" { t.Fatalf("canonicalAlertKind = %v, want severity-threshold", got) } @@ -4554,6 +4615,56 @@ func TestCheckDiskHealthWearoutAlertUpdatesOnSubsequentChecks(t *testing.T) { if alert.Value != 6 { t.Errorf("expected value to be updated to 6, got %f", alert.Value) } + if want := "SSD life remaining is 6%"; alert.Message != want { + t.Errorf("message = %q, want %q", alert.Message, want) + } +} + +// The physical-disk poller re-evaluates every disk each cycle (and mock mode +// on every alert tick), so a failed or worn disk must log at error/warn once, +// when its alert opens, and at debug on every later poll. +func TestCheckDiskHealthLogsAlertOpeningOnce(t *testing.T) { + count := captureTestLogs(t) + m := newTestManager(t) + m.ClearActiveAlerts() + + // Exactly at the wearout threshold, which still alerts. + disk := proxmox.Disk{ + DevPath: "/dev/sdf", + Model: "Crucial CT500MX500SSD1", + Serial: "2034E4A1B2C3", + Type: "ssd", + Health: "FAILED", + Wearout: 10, + Size: 500107862016, + } + const polls = 3 + for i := 0; i < polls; i++ { + m.CheckDiskHealth("test-instance", "pve-node1", disk) + } + + if got := count(zerolog.ErrorLevel, "Disk health alert created"); got != 1 { + t.Errorf("error-level health log count after %d polls = %d, want 1", polls, got) + } + if got := count(zerolog.DebugLevel, "Disk health check still failing"); got != polls-1 { + t.Errorf("debug-level health log count after %d polls = %d, want %d", polls, got, polls-1) + } + if got := count(zerolog.WarnLevel, "Disk wearout alert created"); got != 1 { + t.Errorf("warn-level wearout log count after %d polls = %d, want 1", polls, got) + } + if got := count(zerolog.DebugLevel, "Disk life remaining still at or below wearout threshold"); got != polls-1 { + t.Errorf("debug-level wearout log count after %d polls = %d, want %d", polls, got, polls-1) + } + + // A disk that passes and then fails again opens a new alert, which logs + // at error again. + disk.Health = "PASSED" + m.CheckDiskHealth("test-instance", "pve-node1", disk) + disk.Health = "FAILED" + m.CheckDiskHealth("test-instance", "pve-node1", disk) + if got := count(zerolog.ErrorLevel, "Disk health alert created"); got != 2 { + t.Errorf("error-level health log count after the disk failed again = %d, want 2", got) + } } func TestCheckDiskHealthWearoutRecoveryAlertCleared(t *testing.T) { diff --git a/internal/alerts/disk_health.go b/internal/alerts/disk_health.go index 4afe7de5c4..5864403747 100644 --- a/internal/alerts/disk_health.go +++ b/internal/alerts/disk_health.go @@ -26,6 +26,10 @@ func proxmoxDiskAlertMetadata(disk proxmox.Disk) map[string]interface{} { } } +// proxmoxDiskWearoutThreshold is the percent life remaining at or below +// which a Proxmox SSD raises a wearout alert. +const proxmoxDiskWearoutThreshold = 10 + // CheckDiskHealth checks disk health and creates alerts if needed func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { // Create unique alert ID for this disk @@ -84,7 +88,7 @@ func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { metadata := proxmoxDiskAlertMetadata(disk) metadata["disk_health"] = disk.Health - _, _ = m.evaluateCanonicalStatefulAlert(canonicalStatefulAlertParams{ + result, _ := m.evaluateCanonicalStatefulAlert(canonicalStatefulAlertParams{ Spec: spec, Evidence: alertspecs.AlertEvidence{ ObservedAt: time.Now(), @@ -106,12 +110,22 @@ func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { AddToHistory: true, }) - log.Error(). - Str("node", node). - Str("disk", disk.DevPath). - Str("model", disk.Model). - Str("health", disk.Health). - Msg("Disk health alert created") + // Every disk poll re-evaluates a failed disk, so log at error + // only when the alert opens, not on each poll after it. + if diskAlertOpened(result) { + log.Error(). + Str("node", node). + Str("disk", disk.DevPath). + Str("model", disk.Model). + Str("health", disk.Health). + Msg("Disk health alert created") + } else { + log.Debug(). + Str("node", node). + Str("disk", disk.DevPath). + Str("health", disk.Health). + Msg("Disk health check still failing") + } } } else { // Disk is healthy, clear alert if it exists @@ -122,8 +136,11 @@ func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { // cannot prove recovery; 0 from an SSD is a real, fully spent reading, // whereas -1 and rotational 0 are absent evidence. if storagehealth.WearoutReported(disk.Wearout, disk.Type) { - message := fmt.Sprintf("SSD has less than 10%% life remaining (%d%% wearout)", disk.Wearout) - spec, err := buildCanonicalSeverityThresholdSpecWithDirection(canonicalResourceID+"-wearout", canonicalResourceID, resourceName, resourceType, "wearout-remaining", alertspecs.ThresholdDirectionBelow, 10, 0, false) + // Wearout is percent life remaining, not percent worn, so the + // message names it as life remaining, in the host-agent SMART + // wording. The threshold travels in the alert's Threshold field. + message := fmt.Sprintf("SSD life remaining is %d%%", disk.Wearout) + spec, err := buildCanonicalSeverityThresholdSpecWithDirection(canonicalResourceID+"-wearout", canonicalResourceID, resourceName, resourceType, "wearout-remaining", alertspecs.ThresholdDirectionBelow, proxmoxDiskWearoutThreshold, 0, false) if err != nil { log.Warn(). Err(err). @@ -134,7 +151,7 @@ func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { metadata := proxmoxDiskAlertMetadata(disk) metadata["disk_wearout"] = disk.Wearout - _, _ = m.evaluateCanonicalStatefulAlert(canonicalStatefulAlertParams{ + result, _ := m.evaluateCanonicalStatefulAlert(canonicalStatefulAlertParams{ Spec: spec, // Endurance cannot normally improve on the same disk. Require // sustained healthy-looking polls before resolving a worn-disk @@ -156,20 +173,33 @@ func (m *Manager) CheckDiskHealth(instance, node string, disk proxmox.Disk) { Instance: instance, Message: message, Value: float64(disk.Wearout), - Threshold: 10.0, + Threshold: proxmoxDiskWearoutThreshold, Metadata: metadata, AddToRecent: true, AddToHistory: true, }) - if disk.Wearout < 10 { + if diskAlertOpened(result) { log.Warn(). Str("node", node). Str("disk", disk.DevPath). Str("model", disk.Model). - Int("wearout", disk.Wearout). - Msg("Disk wearout alert observed") + Int("lifeRemaining", disk.Wearout). + Msg("Disk wearout alert created") + } else if disk.Wearout <= proxmoxDiskWearoutThreshold { + log.Debug(). + Str("node", node). + Str("disk", disk.DevPath). + Int("lifeRemaining", disk.Wearout). + Msg("Disk life remaining still at or below wearout threshold") } } } } + +// diskAlertOpened reports whether this evaluation opened the alert, as +// opposed to re-evaluating one that is already active, pending, or +// suppressed. +func diskAlertOpened(result alertspecs.EvaluationResult) bool { + return result.Transition != nil && result.Transition.Kind == alertspecs.EvaluationTransitionActivated +}