From d8f6069b4606367422aef8eaa14cc49371b746ec Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sun, 12 Jul 2026 10:07:47 +0200 Subject: [PATCH] controller: fix-3 dead-app alerting + fix-6 ring cap/spill/spam (WIP, pre-build) Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_017CDMFpFx84pfviCTVuGGhf --- controller/cmd/controller/main.go | 64 +++++++++- controller/internal/notify/deadapp_test.go | 68 +++++++++++ controller/internal/notify/notifier.go | 66 ++++++++++ controller/internal/scheduler/scheduler.go | 11 +- controller/internal/stacks/downstate_test.go | 23 ++++ controller/internal/stacks/manager.go | 19 ++- controller/internal/web/alerts.go | 71 ++++++++++- controller/internal/web/deadapp_alert_test.go | 44 +++++++ controller/internal/web/logbuffer.go | 114 +++++++++++++++++- .../internal/web/logbuffer_spill_test.go | 111 +++++++++++++++++ 10 files changed, 581 insertions(+), 10 deletions(-) create mode 100644 controller/internal/notify/deadapp_test.go create mode 100644 controller/internal/stacks/downstate_test.go create mode 100644 controller/internal/web/deadapp_alert_test.go create mode 100644 controller/internal/web/logbuffer_spill_test.go diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 33579a2..d173a6e 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -24,7 +24,6 @@ import ( "gitea.dooplex.hu/admin/felhom-controller/internal/appexport" "gitea.dooplex.hu/admin/felhom-controller/internal/assets" "gitea.dooplex.hu/admin/felhom-controller/internal/backup" - "gitea.dooplex.hu/admin/felhom-controller/internal/offsiteapply" "gitea.dooplex.hu/admin/felhom-controller/internal/bootstrap" "gitea.dooplex.hu/admin/felhom-controller/internal/channelhealth" cf "gitea.dooplex.hu/admin/felhom-controller/internal/cloudflare" @@ -35,6 +34,7 @@ import ( "gitea.dooplex.hu/admin/felhom-controller/internal/metrics" "gitea.dooplex.hu/admin/felhom-controller/internal/monitor" "gitea.dooplex.hu/admin/felhom-controller/internal/notify" + "gitea.dooplex.hu/admin/felhom-controller/internal/offsiteapply" "gitea.dooplex.hu/admin/felhom-controller/internal/quiesce" "gitea.dooplex.hu/admin/felhom-controller/internal/recovery" "gitea.dooplex.hu/admin/felhom-controller/internal/report" @@ -86,6 +86,11 @@ func main() { } logger, logBuffer := setupLogger(cfg) + // fix-6 (CAMPAIGN-3): load the pre-restart debug-ring window back immediately, so a controller + // restart / container recreation no longer wipes the exact evidence an operator needs. The spill + // lives on the SSD state dir (DataDir — holds settings.json, survives recreation), NEVER a NAS path. + ringSpillPath := filepath.Join(cfg.Paths.DataDir, "debug-ring.log") + logBuffer.LoadFrom(ringSpillPath) // v0.116.0: the debug ring is the controller_log_tail source (report self-tail channel). report.SetControllerLogSource(logBuffer.Lines) @@ -390,6 +395,29 @@ func main() { return nil }) + // fix-3 (CAMPAIGN-3): a deployed app that is not running must be LOUD, not silent (the campaign's + // CWA sat dead 4 h; F11 then produced 4 silently-dead NAS apps per reboot). Runs on its own short + // cadence (faster than the 5-min health cycle) so a dead app surfaces quickly. Logs nothing on the + // quiet path (no ring spam — fix-6 friendly); the dashboard banner is state-based (self-clears) and + // the hub event fires once per running→down transition (notifier tracks it). A boot grace skips the + // controller's own startup settle so apps that legitimately take 30–60 s to come up don't alert. + sched.Every("deadapp-check", 30*time.Second, func(ctx context.Context) error { + if time.Since(startTime) < deadAppBootGrace { + return nil // still inside the startup settle window + } + dead, states := scanDeployedAppRunStates(stackMgr) + alertMgr.SetDeadAppAlerts(dead) + notifier.NotifyAppStartFailures(states) + return nil + }) + + // fix-6 (CAMPAIGN-3): periodically spill the debug ring to the SSD state dir so a HARD crash loses + // at most ~60 s of the window (a clean shutdown spills too). ≤30s interval → auto-quiet (no + // per-cycle scheduler line). SpillTo is atomic (tmp+rename) so it can never corrupt the ring file. + sched.Every("ring-spill", 30*time.Second, func(ctx context.Context) error { + return logBuffer.SpillTo(ringSpillPath) + }) + // --- Central hub pusher (declared early so backup closure can reference it) --- var hubPusher *report.Pusher if cfg.Hub.URL != "" && cfg.Hub.APIKey != "" { @@ -936,6 +964,11 @@ func main() { go func() { sig := <-sigCh logger.Printf("[INFO] Received signal %v, shutting down...", sig) + // fix-6: spill the debug ring on a clean shutdown so a `systemctl restart` / container recreate + // preserves the pre-restart window (the periodic spill already covers a hard crash to ≤60 s). + if err := logBuffer.SpillTo(ringSpillPath); err != nil { + logger.Printf("[WARN] debug-ring spill on shutdown failed: %v", err) + } cancel() if mailShim != nil { mailShim.Close() @@ -958,6 +991,30 @@ func main() { } // selfUpdateAuthMiddleware allows access via session auth (normal UI) OR hub API key bearer token (external). +// deadAppBootGrace is the startup settle window before fix-3 evaluates deployed-app run states — apps +// legitimately take 30–60 s to come up, so a shorter grace would false-alarm during the controller's +// own boot. After the grace, an app that still isn't running alerts (the F11 dead-at-boot case). +const deadAppBootGrace = 90 * time.Second + +// scanDeployedAppRunStates returns the fix-3 view of the deployed apps: the DEAD ones (for the +// state-based dashboard banner) and EVERY deployed app's run state (for the notifier's one-event-per- +// transition tracking). Deploying apps are skipped (mid-deploy is not a fault). Pure over GetStacks(). +func scanDeployedAppRunStates(mgr *stacks.Manager) ([]web.DeadApp, []notify.AppRunState) { + var dead []web.DeadApp + var states []notify.AppRunState + for _, st := range mgr.GetStacks() { + if !st.Deployed || st.Deploying { + continue + } + down := stacks.IsDownState(st.State) + states = append(states, notify.AppRunState{Name: st.Name, DisplayName: st.Meta.DisplayName, Down: down}) + if down { + dead = append(dead, web.DeadApp{Name: st.Name, DisplayName: st.Meta.DisplayName, State: string(st.State)}) + } + } + return dead, states +} + func selfUpdateAuthMiddleware(cfg *config.Config, webServer *web.Server, next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { // Check bearer token first (for external API calls: hub, build scripts) @@ -978,7 +1035,10 @@ func selfUpdateAuthMiddleware(cfg *config.Config, webServer *web.Server, next ht // exist without a config flip), while stdout (docker logs) keeps respecting // logging.level via the level filter. Lshortfile stays debug-only (unchanged). func setupLogger(cfg *config.Config) (*log.Logger, *web.LogBuffer) { - logBuffer := web.NewLogBuffer(1000) + // fix-6 (CAMPAIGN-3): 1000 wrapped in ~6.5 min under the campaign's ~2.6 entries/s load — the exact + // post-incident window an operator needs was the first thing lost. 5000 gives ≈32 min at that raw + // rate, and ≈50+ min now that the periodic-scheduler TRACE noise no longer enters the ring (2b). + logBuffer := web.NewLogBuffer(5000) flags := log.LstdFlags if cfg.Logging.Level == "debug" { flags |= log.Lshortfile diff --git a/controller/internal/notify/deadapp_test.go b/controller/internal/notify/deadapp_test.go new file mode 100644 index 0000000..a1af278 --- /dev/null +++ b/controller/internal/notify/deadapp_test.go @@ -0,0 +1,68 @@ +package notify + +import ( + "log" + "testing" +) + +// fix-3: app_start_failed fires ONCE per running→down transition. down→down cycles are silent (the +// anti-spam guarantee); down→running clears the tracker so a later re-failure re-notifies. +func TestNotifyAppStartFailures_OneEventPerTransition(t *testing.T) { + n := New("http://hub", "key", "cust", nil, log.New(nil, "", 0), false) + var events []string + n.pushFn = func(eventType, _, msg string, _ interface{}) { + if eventType == "app_start_failed" { + events = append(events, msg) + } + } + + up := []AppRunState{{Name: "radarr", DisplayName: "Radarr", Down: false}} + down := []AppRunState{{Name: "radarr", DisplayName: "Radarr", Down: true}} + + // running → down: exactly one event. + n.NotifyAppStartFailures(up) + n.NotifyAppStartFailures(down) + if len(events) != 1 { + t.Fatalf("running→down must fire exactly one event, got %d: %v", len(events), events) + } + // down → down (two more cycles): SILENT (companion: drop the n.appDown tracking → fires each cycle → fail). + n.NotifyAppStartFailures(down) + n.NotifyAppStartFailures(down) + if len(events) != 1 { + t.Fatalf("down→down must be silent, got %d events: %v", len(events), events) + } + // down → running → down: a fresh transition re-notifies. + n.NotifyAppStartFailures(up) + n.NotifyAppStartFailures(down) + if len(events) != 2 { + t.Fatalf("a fresh down transition must re-notify, got %d: %v", len(events), events) + } +} + +// An app that is down on the FIRST evaluation (the F11 dead-at-boot case, after the boot grace) still +// fires — it is a running→down transition from the tracker's empty initial state. +func TestNotifyAppStartFailures_FirstSeenDownFires(t *testing.T) { + n := New("http://hub", "key", "cust", nil, log.New(nil, "", 0), false) + var count int + n.pushFn = func(eventType, _, _ string, _ interface{}) { + if eventType == "app_start_failed" { + count++ + } + } + n.NotifyAppStartFailures([]AppRunState{{Name: "jellyfin", DisplayName: "Jellyfin", Down: true}}) + if count != 1 { + t.Fatalf("a first-seen dead app (dead-at-boot) must fire once, got %d", count) + } +} + +// A deployed app that is up never fires. +func TestNotifyAppStartFailures_HealthyNeverFires(t *testing.T) { + n := New("http://hub", "key", "cust", nil, log.New(nil, "", 0), false) + var count int + n.pushFn = func(string, string, string, interface{}) { count++ } + n.NotifyAppStartFailures([]AppRunState{{Name: "radarr", Down: false}}) + n.NotifyAppStartFailures([]AppRunState{{Name: "radarr", Down: false}}) + if count != 0 { + t.Fatalf("a healthy app must never fire, got %d", count) + } +} diff --git a/controller/internal/notify/notifier.go b/controller/internal/notify/notifier.go index e828b09..3dfc656 100644 --- a/controller/internal/notify/notifier.go +++ b/controller/internal/notify/notifier.go @@ -39,6 +39,16 @@ type Notifier struct { mu sync.Mutex prevHealthStatus string // tracks previous health check status for change detection + // appDown tracks which deployed apps are currently in the DOWN state so app_start_failed fires + // ONCE per running→down transition, not every health cycle (fix-3 anti-spam). In-memory: a + // controller restart re-notifies once (acceptable — better than missing). The hub owns the real + // cooldown; the controller must not add its own timer. + appDown map[string]bool + + // pushFn is a test seam for the transition-emitting notifiers (fix-3). nil → the real async + // PushEvent; tests inject a synchronous recorder. + pushFn func(eventType, severity, message string, details interface{}) + // Event history ring buffer (debug page) historyMu sync.RWMutex history [50]EventHistoryEntry @@ -362,6 +372,62 @@ func (n *Notifier) NotifyAppDeployed(stackName, displayName string) { AppDetails{StackName: stackName, DisplayName: displayName}) } +// AppRunState is one deployed app's running state for the fix-3 start-failure notifier: Down=true +// when the app is deployed but its containers are not running. +type AppRunState struct { + Name string + DisplayName string + Down bool +} + +// NotifyAppStartFailures fires an `app_start_failed` hub event ONCE per running→down transition +// (fix-3). It is called each health cycle with the CURRENT deployed-app run states; the per-app +// transition tracking (n.appDown) makes down→down cycles silent, so a persistently-dead app does not +// spam. down→running clears the tracker (no event — the dashboard banner self-clears; a recovery +// event is deliberately omitted to keep the operator inbox quiet). The hub applies its own cooldown. +func (n *Notifier) NotifyAppStartFailures(apps []AppRunState) { + n.mu.Lock() + if n.appDown == nil { + n.appDown = map[string]bool{} + } + var newlyDown []AppRunState + seen := map[string]bool{} + for _, a := range apps { + seen[a.Name] = true + was := n.appDown[a.Name] + if a.Down && !was { + newlyDown = append(newlyDown, a) // running→down (or first-seen-down after the boot grace) + } + n.appDown[a.Name] = a.Down + } + // Forget apps no longer reported (removed/undeployed) so a later redeploy re-notifies cleanly. + for name := range n.appDown { + if !seen[name] { + delete(n.appDown, name) + } + } + n.mu.Unlock() + + for _, a := range newlyDown { + name := a.DisplayName + if name == "" { + name = a.Name + } + n.emit("app_start_failed", "warn", + fmt.Sprintf("Telepített alkalmazás nem fut: %s", name), + AppDetails{StackName: a.Name, DisplayName: a.DisplayName}) + } +} + +// emit sends an event through the test seam if set, else the real async PushEvent. +func (n *Notifier) emit(eventType, severity, message string, details interface{}) { + if n.pushFn != nil { + n.pushFn(eventType, severity, message, details) + return + } + n.PushEvent(eventType, severity, message, details) +} + // NotifyAppRemoved sends an app removal event. func (n *Notifier) NotifyAppRemoved(stackName, displayName string) { n.PushEvent("app_removed", "info", diff --git a/controller/internal/scheduler/scheduler.go b/controller/internal/scheduler/scheduler.go index 2d86be4..bb22ce1 100644 --- a/controller/internal/scheduler/scheduler.go +++ b/controller/internal/scheduler/scheduler.go @@ -64,6 +64,13 @@ func (s *Scheduler) dbg(format string, args ...interface{}) { } } +// trace logs a periodic-job routine line at [TRACE] — below the debug ring's capture threshold, so +// the every-cycle "job finished" noise never eats the post-incident window (fix-6, CAMPAIGN-3). Job +// FAILURES are logged at [ERROR] (never here), so this never hides a problem. +func (s *Scheduler) trace(format string, args ...interface{}) { + s.logger.Printf("[TRACE] [scheduler] "+format, args...) +} + // New creates a new Scheduler. func New(logger *log.Logger) *Scheduler { return &Scheduler{ @@ -295,7 +302,9 @@ func (s *Scheduler) executeJob(job *Job, quiet bool) { } else if !quiet { s.logger.Printf("[INFO] [scheduler] Job %s completed (took %s)", job.Name, elapsed.Round(time.Millisecond)) } - s.dbg("job %s: finished in %s (err=%v)", job.Name, elapsed.Round(time.Millisecond), err) + // Routine per-cycle timing line → TRACE (dropped from the ring; the completed/failed lines above + // carry the outcome). This was the biggest ring filler under load (fix-6). + s.trace("job %s: finished in %s (err=%v)", job.Name, elapsed.Round(time.Millisecond), err) } // parseDailyTime parses "HH:MM" and returns hour and minute. diff --git a/controller/internal/stacks/downstate_test.go b/controller/internal/stacks/downstate_test.go new file mode 100644 index 0000000..9998b2a --- /dev/null +++ b/controller/internal/stacks/downstate_test.go @@ -0,0 +1,23 @@ +package stacks + +import "testing" + +// fix-3: only stopped/exited count as "down" for a deployed app. starting/unhealthy (running), +// restarting/deploying (transient), paused (deliberate), unknown (ambiguous) must NOT alert. +func TestIsDownState(t *testing.T) { + down := []ContainerState{StateStopped, StateExited} + for _, s := range down { + if !IsDownState(s) { + t.Errorf("IsDownState(%q) = false, want true", s) + } + } + notDown := []ContainerState{ + StateRunning, StateStarting, StateUnhealthy, StateRestarting, + StateDeploying, StatePaused, StateUnknown, StateNotDeployed, StateOrphaned, + } + for _, s := range notDown { + if IsDownState(s) { + t.Errorf("IsDownState(%q) = true, want false (must not manufacture a dead-app alert)", s) + } + } +} diff --git a/controller/internal/stacks/manager.go b/controller/internal/stacks/manager.go index d78819e..0fdfcfb 100644 --- a/controller/internal/stacks/manager.go +++ b/controller/internal/stacks/manager.go @@ -37,6 +37,16 @@ const ( StateOrphaned ContainerState = "orphaned" ) +// IsDownState reports whether a container state means a DEPLOYED app is not running and won't recover +// on its own (fix-3, CAMPAIGN-3). Only `stopped` and `exited` qualify — a Docker "created"/"dead" +// container (a failed-at-boot app, the F11 case) resolves to `stopped`. Deliberately NOT `starting` +// / `unhealthy` (running, with their own health handling), `restarting` (self-recovering), +// `deploying` (mid-deploy), `paused` (a deliberate user action), or `unknown` (ambiguous — fail-open, +// never manufacture a dead-app alert from an inconclusive read). +func IsDownState(s ContainerState) bool { + return s == StateStopped || s == StateExited +} + // ContainerInfo holds status info about a single container within a stack. type ContainerInfo struct { Name string `json:"name"` @@ -444,9 +454,10 @@ func (m *Manager) refreshStatusLocked() error { totalContainers++ } - if m.isDebug() { - m.logger.Printf("[DEBUG] [stacks] refreshStatusLocked: docker ps returned %d containers across %d projects", totalContainers, len(projectContainers)) - } + // fix-6: refreshStatusLocked runs every 10s (the status-refresh job) — its per-cycle enumeration + // lines are TRACE (dropped from the debug ring) so they don't eat the post-incident window. A real + // state change is logged elsewhere at INFO; a docker error returns up the stack. + m.logger.Printf("[TRACE] [stacks] refreshStatusLocked: docker ps returned %d containers across %d projects", totalContainers, len(projectContainers)) m.logger.Printf("[INFO] [stacks] Status refresh: %d containers across %d stacks", totalContainers, len(m.stacks)) @@ -473,7 +484,7 @@ func (m *Manager) refreshStatusLocked() error { } if m.isDebug() { - m.logger.Printf("[DEBUG] [stacks] refreshStatusLocked: stack %q → state=%s containers=%d", name, stack.State, len(stack.Containers)) + m.logger.Printf("[TRACE] [stacks] refreshStatusLocked: stack %q → state=%s containers=%d", name, stack.State, len(stack.Containers)) } stack.LastUpdated = time.Now() diff --git a/controller/internal/web/alerts.go b/controller/internal/web/alerts.go index cfcbf43..78168db 100644 --- a/controller/internal/web/alerts.go +++ b/controller/internal/web/alerts.go @@ -37,6 +37,11 @@ type AlertManager struct { // is health-report-driven). nil = channel up. It is prepended in GetAlerts so a dead controller→ // agent link (disk/storage UI broken) is always visible regardless of the health-report cycle. agentChannelAlert *Alert + // deadAppAlerts (fix-3, CAMPAIGN-3) is set each cycle by the health loop from the deployed-app + // running-state view (which is NOT in the health report — it comes from the stack manager). Same + // out-of-band, state-based, self-clearing model as agentChannelAlert: passing an empty slice when + // every deployed app is running clears the banner with no manual dismissal. + deadAppAlerts []Alert } // NewAlertManager creates a new AlertManager. @@ -72,6 +77,63 @@ func (am *AlertManager) SetAgentChannelAlert(down bool, msg string) { } } +// DeadApp is a deployed app the health loop found not-running (fix-3). State is the container-state +// string for the display (e.g. "stopped"/"exited"). +type DeadApp struct { + Name string + DisplayName string + State string +} + +// deadAppGroupThreshold: above this many dead apps, collapse to ONE grouped alert (a reboot storm +// with many NAS apps down should not paper the dashboard with a wall of banners — fix-3). +const deadAppGroupThreshold = 3 + +// buildDeadAppAlerts turns the dead-app list into dashboard alerts (WARN). ≤ threshold → one per app; +// more → a single grouped alert. Pure → unit-tested. Empty list → nil (clears the banner). +func buildDeadAppAlerts(dead []DeadApp) []Alert { + if len(dead) == 0 { + return nil + } + if len(dead) > deadAppGroupThreshold { + return []Alert{{ + ID: "deadapp-group", + Level: "warning", + Message: fmt.Sprintf("%d telepített alkalmazás nem fut — nézze meg a rendszermonitort", len(dead)), + Link: "/monitoring", + LinkText: "Rendszermonitor", + }} + } + alerts := make([]Alert, 0, len(dead)) + for _, d := range dead { + name := d.DisplayName + if name == "" { + name = d.Name + } + msg := "Telepített alkalmazás nem fut: " + name + if d.State != "" { + msg += " (" + d.State + ")" + } + alerts = append(alerts, Alert{ + ID: "deadapp-" + simpleHash(d.Name), + Level: "warning", + Message: msg, + Link: "/monitoring", + LinkText: "Rendszermonitor", + }) + } + return alerts +} + +// SetDeadAppAlerts stores the current deployed-not-running banner set (fix-3). State-based: called +// each health cycle with the live dead-app list (empty clears it). Included in GetAlerts. +func (am *AlertManager) SetDeadAppAlerts(dead []DeadApp) { + alerts := buildDeadAppAlerts(dead) + am.mu.Lock() + am.deadAppAlerts = alerts + am.mu.Unlock() +} + // Refresh regenerates alerts from the latest health check report and config state. // Called after each health check cycle (every 5 minutes) and on storage state changes. func (am *AlertManager) Refresh(report *monitor.HealthReport, cfg *config.Config, backupMgr *backup.Manager, updateAvailable bool, latestVersion string, storagePaths ...[]settings.StoragePath) { @@ -182,7 +244,7 @@ func (am *AlertManager) GetAlerts(excludeIDs ...string) []Alert { am.mu.RLock() defer am.mu.RUnlock() - if len(am.alerts) == 0 && am.agentChannelAlert == nil { + if len(am.alerts) == 0 && am.agentChannelAlert == nil && len(am.deadAppAlerts) == 0 { return nil } @@ -196,6 +258,13 @@ func (am *AlertManager) GetAlerts(excludeIDs ...string) []Alert { if am.agentChannelAlert != nil && !exclude[am.agentChannelAlert.ID] { result = append(result, *am.agentChannelAlert) } + // Dead-app banners (fix-3) — prepended after the channel alert: a deployed app being down is a + // high-signal state the operator/customer must see immediately. + for _, a := range am.deadAppAlerts { + if !exclude[a.ID] { + result = append(result, a) + } + } for _, a := range am.alerts { if exclude[a.ID] { continue diff --git a/controller/internal/web/deadapp_alert_test.go b/controller/internal/web/deadapp_alert_test.go new file mode 100644 index 0000000..0fa17d2 --- /dev/null +++ b/controller/internal/web/deadapp_alert_test.go @@ -0,0 +1,44 @@ +package web + +import ( + "log" + "strings" + "testing" +) + +// fix-3: a deployed-not-running app produces a self-clearing WARN dashboard banner; an empty list +// clears it. COMPANION red-proof: skip SetDeadAppAlerts entirely (the pre-fix-3 silence) → GetAlerts +// has no dead-app banner → the "not fut" assertion fails. +func TestDeadAppAlerts_PresentAndSelfClearing(t *testing.T) { + am := NewAlertManager(log.New(nil, "", 0)) + + am.SetDeadAppAlerts([]DeadApp{{Name: "cwa", DisplayName: "Calibre-Web", State: "stopped"}}) + got := am.GetAlerts() + if len(got) != 1 || got[0].Level != "warning" || !strings.Contains(got[0].Message, "Telepített alkalmazás nem fut: Calibre-Web") { + t.Fatalf("expected a WARN dead-app banner, got %+v", got) + } + if !strings.Contains(got[0].Message, "stopped") { + t.Errorf("banner should carry the state: %q", got[0].Message) + } + + // The app recovers → an empty set clears the banner (state-based, no manual dismissal). + am.SetDeadAppAlerts(nil) + if got := am.GetAlerts(); len(got) != 0 { + t.Fatalf("dead-app banner must self-clear when the app recovers, got %+v", got) + } +} + +// Above the group threshold, many dead apps collapse to ONE grouped banner (a reboot storm must not +// paper the dashboard). +func TestDeadAppAlerts_GroupedAboveThreshold(t *testing.T) { + am := NewAlertManager(log.New(nil, "", 0)) + var many []DeadApp + for _, n := range []string{"radarr", "jellyfin", "navidrome", "calibre", "seerr"} { + many = append(many, DeadApp{Name: n, DisplayName: n, State: "stopped"}) + } + am.SetDeadAppAlerts(many) + got := am.GetAlerts() + if len(got) != 1 || !strings.Contains(got[0].Message, "5 telepített alkalmazás nem fut") { + t.Fatalf("expected one grouped banner for %d dead apps, got %+v", len(many), got) + } +} diff --git a/controller/internal/web/logbuffer.go b/controller/internal/web/logbuffer.go index b0b7ef1..a53bd6b 100644 --- a/controller/internal/web/logbuffer.go +++ b/controller/internal/web/logbuffer.go @@ -1,6 +1,9 @@ package web import ( + "bufio" + "encoding/json" + "os" "strings" "sync" "time" @@ -9,9 +12,9 @@ import ( // LogEntry represents a single parsed log line. type LogEntry struct { Timestamp time.Time `json:"timestamp"` - Level string `json:"level"` // "DEBUG", "INFO", "WARN", "ERROR" + Level string `json:"level"` // "DEBUG", "INFO", "WARN", "ERROR" Message string `json:"message"` - Source string `json:"source"` // "file.go:123" if Lshortfile enabled + Source string `json:"source"` // "file.go:123" if Lshortfile enabled } // LogBuffer is a thread-safe ring buffer that captures log output. @@ -44,6 +47,14 @@ func (lb *LogBuffer) Write(p []byte) (n int, err error) { entry := parseLine(line) + // fix-6 (CAMPAIGN-3): TRACE lines (periodic-job routine success — the every-cycle scheduler + + // refreshStatusLocked noise) are DROPPED from the ring so the finite capacity holds SIGNAL, not + // "nothing happened, again". They still reach stdout if the configured level allows. Failures and + // state changes are never TRACE, so this never loses them. + if levelPriority(entry.Level) < levelPriority("DEBUG") { + return len(p), nil + } + lb.mu.Lock() lb.entries[lb.pos] = entry lb.pos = (lb.pos + 1) % lb.size @@ -144,6 +155,101 @@ func (lb *LogBuffer) Lines(maxBytes int) []string { return lines[keepFrom:] } +// snapshot returns the held entries in chronological order (oldest→newest). +func (lb *LogBuffer) snapshot() []LogEntry { + lb.mu.RLock() + defer lb.mu.RUnlock() + total := lb.size + start := 0 + if !lb.full { + total = lb.pos + } else { + start = lb.pos + } + out := make([]LogEntry, 0, total) + for i := 0; i < total; i++ { + out = append(out, lb.entries[(start+i)%lb.size]) + } + return out +} + +// SpillTo persists the ring to path as JSON-lines (one entry per line), newest-last, via an atomic +// tmp+rename so a crash mid-write never corrupts the on-disk ring (fix-6, CAMPAIGN-3). The path MUST +// be on the SSD/state dir — NEVER a NAS/HDD path (a ring that dies with the NAS is worse than none). +func (lb *LogBuffer) SpillTo(path string) error { + entries := lb.snapshot() + tmp := path + ".tmp" + f, err := os.Create(tmp) + if err != nil { + return err + } + w := bufio.NewWriter(f) + enc := json.NewEncoder(w) + for _, e := range entries { + if err := enc.Encode(e); err != nil { + f.Close() + os.Remove(tmp) + return err + } + } + if err := w.Flush(); err != nil { + f.Close() + os.Remove(tmp) + return err + } + if err := f.Sync(); err != nil { + f.Close() + os.Remove(tmp) + return err + } + if err := f.Close(); err != nil { + os.Remove(tmp) + return err + } + return os.Rename(tmp, path) +} + +// LoadFrom seeds the ring from a spill file written by SpillTo, keeping the newest `size` entries so +// the pre-restart window is present in the viewer immediately (fix-6). Corruption-safe: a truncated +// or partially-written line simply fails to parse and is SKIPPED — the ring loads what is valid and +// NEVER panics or errors fatally (a missing file is a clean no-op). Call once at startup, before the +// logger writes anything. +func (lb *LogBuffer) LoadFrom(path string) { + f, err := os.Open(path) + if err != nil { + return // no prior spill (fresh box / first boot) — clean no-op + } + defer f.Close() + var loaded []LogEntry + sc := bufio.NewScanner(f) + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) // tolerate long lines + for sc.Scan() { + var e LogEntry + if err := json.Unmarshal(sc.Bytes(), &e); err != nil { + continue // skip a corrupt/truncated line — never fatal + } + loaded = append(loaded, e) + } + if len(loaded) == 0 { + return + } + if len(loaded) > lb.size { + loaded = loaded[len(loaded)-lb.size:] // keep the newest `size` + } + lb.mu.Lock() + defer lb.mu.Unlock() + for i, e := range loaded { + lb.entries[i] = e + } + if len(loaded) == lb.size { + lb.pos = 0 + lb.full = true + } else { + lb.pos = len(loaded) + lb.full = false + } +} + // parseLine parses a single log line into a LogEntry. func parseLine(line string) LogEntry { entry := LogEntry{ @@ -195,6 +301,8 @@ func extractLevel(s string) (string, string) { msg := strings.TrimSpace(s[end+1:]) switch tag { + case "TRACE": + return "TRACE", msg case "DEBUG": return "DEBUG", msg case "INFO": @@ -214,6 +322,8 @@ func extractLevel(s string) (string, string) { // levelPriority returns numeric priority for log levels. func levelPriority(level string) int { switch strings.ToUpper(level) { + case "TRACE": + return -1 // below DEBUG — dropped from the ring (fix-6 periodic-noise policy) case "DEBUG": return 0 case "INFO": diff --git a/controller/internal/web/logbuffer_spill_test.go b/controller/internal/web/logbuffer_spill_test.go new file mode 100644 index 0000000..e913066 --- /dev/null +++ b/controller/internal/web/logbuffer_spill_test.go @@ -0,0 +1,111 @@ +package web + +import ( + "os" + "path/filepath" + "strconv" + "strings" + "testing" + "time" +) + +var timeZeroVal time.Time + +func timeZero() time.Time { return timeZeroVal } +func itoa(i int) string { return strconv.Itoa(i) } + +// fix-6: a periodic-job routine line at [TRACE] is DROPPED from the ring (protecting the +// post-incident window), while a [WARN]/[ERROR] failure on the same job IS kept. COMPANION red-proof: +// demote too broadly (a failure at TRACE) → the failure vanishes from the ring → an operator loses it. +func TestLogBuffer_TraceDropped_FailureKept(t *testing.T) { + lb := NewLogBuffer(100) + lb.Write([]byte("2026/07/12 09:00:00 [TRACE] [scheduler] job status-refresh: finished in 2ms (err=)\n")) + lb.Write([]byte("2026/07/12 09:00:01 [DEBUG] [stacks] refreshStatusLocked: stack \"radarr\" → state=running\n")) + lb.Write([]byte("2026/07/12 09:00:02 [WARN] [backup] volume dump failed for radarr\n")) + + entries, _ := lb.Entries("DEBUG", 100, timeZero()) + var kept []string + for _, e := range entries { + kept = append(kept, e.Level+" "+e.Message) + } + joined := strings.Join(kept, "|") + if strings.Contains(joined, "finished in 2ms") { + t.Errorf("a TRACE periodic line was kept in the ring (fix-6): %q", joined) + } + if !strings.Contains(joined, "volume dump failed") { + t.Errorf("a WARN failure line was DROPPED from the ring — must be kept: %q", joined) + } + if !strings.Contains(joined, "refreshStatusLocked") { + t.Errorf("a DEBUG line should still be captured (only TRACE is dropped): %q", joined) + } +} + +// fix-6: the ring spills to disk and loads back the newest entries — a controller restart preserves +// the pre-restart window. Round-trip through SpillTo → LoadFrom. +func TestLogBuffer_SpillLoadRoundTrip(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug-ring.log") + src := NewLogBuffer(100) + for _, m := range []string{"alpha", "beta", "gamma"} { + src.Write([]byte("2026/07/12 09:00:00 [INFO] [x] " + m + "\n")) + } + if err := src.SpillTo(path); err != nil { + t.Fatalf("spill: %v", err) + } + + dst := NewLogBuffer(100) + dst.LoadFrom(path) + entries, _ := dst.Entries("INFO", 100, timeZero()) + if len(entries) != 3 { + t.Fatalf("loaded %d entries, want 3", len(entries)) + } + if entries[0].Message != "alpha" || entries[2].Message != "gamma" { + t.Errorf("round-trip order/content wrong: %+v", entries) + } +} + +// Load keeps only the NEWEST `size` entries when the spill holds more than the ring cap. +func TestLogBuffer_LoadKeepsNewest(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug-ring.log") + src := NewLogBuffer(1000) + for i := 0; i < 20; i++ { + src.Write([]byte("2026/07/12 09:00:00 [INFO] [x] msg" + itoa(i) + "\n")) + } + if err := src.SpillTo(path); err != nil { + t.Fatal(err) + } + small := NewLogBuffer(5) // smaller ring + small.LoadFrom(path) + entries, total := small.Entries("INFO", 100, timeZero()) + if total != 5 || len(entries) != 5 { + t.Fatalf("small ring should hold the newest 5, got total=%d len=%d", total, len(entries)) + } + if entries[len(entries)-1].Message != "msg19" { + t.Errorf("newest entry should be msg19, got %q", entries[len(entries)-1].Message) + } +} + +// A corrupt/truncated spill file loads what is valid and NEVER panics (crash-during-spill safety). +func TestLogBuffer_LoadCorruptFileSafe(t *testing.T) { + path := filepath.Join(t.TempDir(), "debug-ring.log") + // One valid JSON line, then a truncated/garbage line (a crash mid-write). + content := `{"timestamp":"2026-07-12T09:00:00Z","level":"INFO","message":"valid","source":""}` + "\n" + + `{"timestamp":"2026-07-12T09:00:01Z","level":"WARN","messa` // truncated + if err := os.WriteFile(path, []byte(content), 0644); err != nil { + t.Fatal(err) + } + lb := NewLogBuffer(100) + lb.LoadFrom(path) // must not panic + entries, _ := lb.Entries("INFO", 100, timeZero()) + if len(entries) != 1 || entries[0].Message != "valid" { + t.Fatalf("corrupt spill should load the 1 valid entry, got %+v", entries) + } +} + +// A missing spill file is a clean no-op. +func TestLogBuffer_LoadMissingFileNoOp(t *testing.T) { + lb := NewLogBuffer(100) + lb.LoadFrom(filepath.Join(t.TempDir(), "does-not-exist.log")) // must not panic + if entries, total := lb.Entries("DEBUG", 100, timeZero()); total != 0 || len(entries) != 0 { + t.Fatalf("missing spill must leave an empty ring, got total=%d", total) + } +}