controller v0.271.0: automatic app updates — the update leg after the off-site copy, the backup gate waits, the switch (09 6.4 part 7; R-680, R-678, R-643)

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
2026-09-24 22:07:24 +02:00
parent 1495ca43fb
commit 9cf13a3add
33 changed files with 1672 additions and 14 deletions
@@ -0,0 +1,510 @@
+package stacks
+
+import (
+	"context"
+	"errors"
+	"fmt"
+	"path/filepath"
+	"sort"
+	"strings"
+	"sync"
+	"time"
+
+	"gitea.dooplex.hu/admin/felhom-controller/internal/backupwindow"
+)
+
+// ── The automatic update leg (`09` §3 decisions 11, 12, 14, 15, 20; §6.4 part 7; controller v0.271.0) ──
+//
+// WHAT IT IS. One more leg of the nightly chain: after the off-site copy, before the full-system backup.
+// It presses the SAME public guarded Update a person presses (StartGuardedUpdate) — no second update
+// path — one app at a time, ONE tested step per app per night, and never:
+//   - an app whose installed version has no ladder entry (older than the ladder, or no test record);
+//   - a step whose verdict is not `proven`, or that carries the `needs_person` mark;
+//   - a `files_may_change` step unless a fresh WHOLE copy of the app exists on the box (decision 25/26);
+//   - the step that was undone or held last time, while the catalog's ladder is unchanged (R-680);
+//   - a held app, an app that is current, ahead, or unorderable.
+// It starts no step at or after W+5h (decision 20); a step already running finishes.
+//
+// WHERE IT IS CALLED FROM. The `offbox-backup` scheduler job, after the off-site copy, on EVERY path —
+// configured, not configured, failed, skipped, panicked (cmd/controller chainUpdateLeg, pinned by
+// TestChainUpdateLeg_*). The full-system backup's gate asks UpdateLegState and waits while the leg runs,
+// until W+5h (quiesce.Options.UpdateLegFn).
+//
+// WHAT THE HOUSEHOLD HEARS. Nothing new: an undone or held step already sends app_update_undone /
+// app_update_held from the update itself. A successful automatic step sends NO mail; the app page shows
+// one line from app.yaml's last_auto_update. The operator gets one summary line per night in the log and
+// in the hub report (LastUpdateLegSummary).
+
+// Leg skip reasons — stable keys for the log, the summary and tests.
+const (
+	LegSkipHeld            = "held"
+	LegSkipUnpinned        = "unpinned"
+	LegSkipUnknownOrder    = "order_unknown"
+	LegSkipAhead           = "ahead"
+	LegSkipNoTestRecord    = "no_test_record"
+	LegSkipOlderThanLadder = "older_than_ladder"
+	LegSkipNotProven       = "not_proven"
+	LegSkipNeedsPerson     = "needs_person"
+	LegSkipFilesNoCopy     = "files_may_change_no_whole_copy"
+	LegSkipFailedBefore    = "failed_before"
+	LegSkipWindowEnd       = "window_end"
+	LegSkipSwitchedOff     = "switched_off"
+	LegSkipCancelled       = "cancelled"
+	legCurrent             = "current" // not a skip: nothing to do
+
+	LegOutcomeDone    = "done"
+	LegOutcomeUndone  = "undone"
+	LegOutcomeHeld    = "held"
+	LegOutcomeFailed  = "failed"
+	LegOutcomeSkipped = "skipped"
+)
+
+// legTransient are the refusals a later press may not meet (R-609's split): retried ONCE later in the leg.
+var legTransient = map[string]bool{"busy": true, "updating": true, "deploying": true, "migrating": true, "self_updating": true}
+
+// UpdateLegOptions wires the leg (main.go). INIT-ONLY via SetUpdateLeg.
+type UpdateLegOptions struct {
+	// Enabled is the per-box switch `app_update.unattended` (decision 12, default ON). Read at the start
+	// and before every press, so switching it off stops the leg before its next step.
+	Enabled func() bool
+	// WindowStart is the effective backup window start W "HH:MM" — the leg starts no step at or after W+5h.
+	WindowStart func() string
+	// FreshWholeCopy answers decision 13's `files_may_change` mark: is there a fresh copy on this box that
+	// brings the app back WHOLE (decision 25/26's truth table)? nil = no → such a step is always skipped.
+	FreshWholeCopy func(ctx context.Context, name string) (bool, string)
+	// Location is the wall clock W is read in (Europe/Budapest); nil = time.Local.
+	Location *time.Location
+	// Poll is how often the leg looks whether its step has ended (default 5 s).
+	Poll time.Duration
+	// RetryWait is how long the leg waits before its one retry of transient refusals (default 2 min).
+	RetryWait time.Duration
+	// Now is the clock (tests); nil = time.Now.
+	Now func() time.Time
+}
+
+// LegStep is one app's line in the night's summary.
+type LegStep struct {
+	App     string            `json:"app"`
+	Outcome string            `json:"outcome"` // done | undone | held | failed | skipped
+	Reason  string            `json:"reason,omitempty"`
+	From    map[string]string `json:"from,omitempty"`
+	To      map[string]string `json:"to,omitempty"`
+	Seconds float64           `json:"seconds,omitempty"`
+}
+
+// UpdateLegSummary is one night's leg — the operator's summary line and the hub report's `update_leg`.
+type UpdateLegSummary struct {
+	Trigger   string    `json:"trigger"`
+	StartedAt time.Time `json:"started_at"`
+	EndedAt   time.Time `json:"ended_at"`
+	Deadline  time.Time `json:"deadline"`
+	Enabled   bool      `json:"enabled"`
+	Done      int       `json:"done"`
+	Undone    int       `json:"undone"`
+	Held      int       `json:"held"`
+	Failed    int       `json:"failed"`
+	Skipped   int       `json:"skipped"`
+	// Stopped says why the leg ended early: window_end | switched_off | cancelled | "" (it ran through).
+	Stopped string    `json:"stopped,omitempty"`
+	Steps   []LegStep `json:"steps"`
+}
+
+// Line is the one operator-English summary line.
+func (s *UpdateLegSummary) Line() string {
+	var skips []string
+	for _, st := range s.Steps {
+		if st.Outcome == LegOutcomeSkipped {
+			skips = append(skips, st.App+"="+st.Reason)
+		}
+	}
+	stop := ""
+	if s.Stopped != "" {
+		stop = " stopped=" + s.Stopped
+	}
+	return fmt.Sprintf("update leg (%s): done=%d undone=%d held=%d failed=%d skipped=%d%s in %s [skipped: %s]",
+		s.Trigger, s.Done, s.Undone, s.Held, s.Failed, s.Skipped, stop,
+		s.EndedAt.Sub(s.StartedAt).Round(time.Second), strings.Join(skips, ", "))
+}
+
+func (s *UpdateLegSummary) add(st LegStep) {
+	s.Steps = append(s.Steps, st)
+	switch st.Outcome {
+	case LegOutcomeDone:
+		s.Done++
+	case LegOutcomeUndone:
+		s.Undone++
+	case LegOutcomeHeld:
+		s.Held++
+	case LegOutcomeFailed:
+		s.Failed++
+	default:
+		s.Skipped++
+	}
+}
+
+type updateLegState struct {
+	run         sync.Mutex // single-flight: one leg at a time
+	mu          sync.Mutex // guards the fields below
+	opts        *UpdateLegOptions
+	active      bool
+	stepRunning bool
+	last        *UpdateLegSummary
+}
+
+// SetUpdateLeg wires the leg. INIT-ONLY (main.go). Without it RunUpdateLeg does nothing and says so.
+func (m *Manager) SetUpdateLeg(o UpdateLegOptions) {
+	if o.Poll <= 0 {
+		o.Poll = 5 * time.Second
+	}
+	if o.RetryWait <= 0 {
+		o.RetryWait = 2 * time.Minute
+	}
+	if o.Location == nil {
+		o.Location = time.Local
+	}
+	if o.Now == nil {
+		o.Now = time.Now
+	}
+	m.leg.mu.Lock()
+	m.leg.opts = &o
+	m.leg.mu.Unlock()
+}
+
+// UpdateLegState is what the full-system backup's gate asks (decision 20): is the leg running, and is one
+// of its steps in flight right now.
+func (m *Manager) UpdateLegState() (active, stepRunning bool) {
+	m.leg.mu.Lock()
+	defer m.leg.mu.Unlock()
+	return m.leg.active, m.leg.stepRunning
+}
+
+// LastUpdateLegSummary is the last leg's summary, or nil when none ran since the controller started.
+func (m *Manager) LastUpdateLegSummary() *UpdateLegSummary {
+	m.leg.mu.Lock()
+	defer m.leg.mu.Unlock()
+	if m.leg.last == nil {
+		return nil
+	}
+	c := *m.leg.last
+	c.Steps = append([]LegStep(nil), m.leg.last.Steps...)
+	return &c
+}
+
+func (m *Manager) setLegFlags(active, step bool) {
+	m.leg.mu.Lock()
+	m.leg.active, m.leg.stepRunning = active, step
+	m.leg.mu.Unlock()
+}
+
+// LegDeadline is the instant the leg starts no more steps: W+5h of the night that contains `now` (the
+// most recent W at or before now). An unparseable W falls back to the default window.
+func LegDeadline(now time.Time, window string, loc *time.Location) time.Time {
+	if loc == nil {
+		loc = time.Local
+	}
+	startMin, err := backupwindow.ParseHHMM(window)
+	if err != nil {
+		startMin, _ = backupwindow.ParseHHMM(backupwindow.DefaultWindow)
+	}
+	n := now.In(loc)
+	w := time.Date(n.Year(), n.Month(), n.Day(), startMin/60, startMin%60, 0, 0, loc)
+	if w.After(n) {
+		w = w.AddDate(0, 0, -1)
+	}
+	return w.Add(time.Duration(backupwindow.UpdateLegStopOffsetMin) * time.Minute)
+}
+
+// RunUpdateLeg runs one night's leg and returns its summary (nil when another leg is running or the leg
+// is not wired). trigger names the caller for the log ("after-offsite").
+func (m *Manager) RunUpdateLeg(ctx context.Context, trigger string) *UpdateLegSummary {
+	if !m.leg.run.TryLock() {
+		m.logger.Printf("[WARN] [update-leg] a leg is already running — this call (%s) does nothing", trigger)
+		return nil
+	}
+	defer m.leg.run.Unlock()
+	m.leg.mu.Lock()
+	o := m.leg.opts
+	m.leg.mu.Unlock()
+	if o == nil {
+		m.logger.Printf("[WARN] [update-leg] not wired (SetUpdateLeg) — no automatic app updates")
+		return nil
+	}
+	sum := &UpdateLegSummary{Trigger: trigger, StartedAt: o.Now(), Steps: []LegStep{}}
+	finish := func() *UpdateLegSummary {
+		sum.EndedAt = o.Now()
+		m.logger.Printf("[INFO] [update-leg] %s", sum.Line())
+		m.leg.mu.Lock()
+		m.leg.last = sum
+		m.leg.mu.Unlock()
+		return sum
+	}
+	sum.Enabled = o.Enabled == nil || o.Enabled()
+	if !sum.Enabled {
+		sum.Stopped = LegSkipSwitchedOff
+		m.logger.Printf("[INFO] [update-leg] automatic app updates are switched OFF on this box (app_update.unattended=false) — no app is pressed tonight")
+		return finish()
+	}
+	window := ""
+	if o.WindowStart != nil {
+		window = o.WindowStart()
+	}
+	sum.Deadline = LegDeadline(sum.StartedAt, window, o.Location)
+	m.setLegFlags(true, false)
+	defer m.setLegFlags(false, false)
+	m.logger.Printf("[INFO] [update-leg] started (%s): window %s, no step starts at or after %s", trigger, window, sum.Deadline.In(o.Location).Format("15:04"))
+
+	// The freshest view of the catalog and the pins — a sync may have landed since the last scan.
+	if err := m.ScanStacks(); err != nil {
+		m.logger.Printf("[WARN] [update-leg] rescan before the leg failed: %v — using the last scan", err)
+	}
+	var names []string
+	for _, st := range m.GetStacks() {
+		if st.Deployed && !st.Protected && !m.cfg.IsProtectedStack(st.Name) {
+			names = append(names, st.Name)
+		}
+	}
+	sort.Strings(names)
+
+	var retry []string
+	for pass := 0; pass < 2 && sum.Stopped == ""; pass++ {
+		list := names
+		if pass == 1 {
+			list, retry = retry, nil
+			if len(list) == 0 {
+				break
+			}
+			m.logger.Printf("[INFO] [update-leg] %d app(s) were refused for a passing reason — one retry in %s: %v", len(list), o.RetryWait, list)
+			select {
+			case <-ctx.Done():
+			case <-time.After(o.RetryWait):
+			}
+		}
+		for i, name := range list {
+			if stop := m.legStop(ctx, o, sum); stop != "" {
+				sum.Stopped = stop
+				for _, rest := range list[i:] {
+					sum.add(LegStep{App: rest, Outcome: LegOutcomeSkipped, Reason: stop})
+				}
+				if pass == 0 {
+					for _, rest := range retry {
+						sum.add(LegStep{App: rest, Outcome: LegOutcomeSkipped, Reason: stop})
+					}
+				}
+				break
+			}
+			entry, reason := m.legCandidate(ctx, name, o)
+			if reason == legCurrent {
+				continue
+			}
+			if reason != "" {
+				m.logger.Printf("[INFO] [update-leg] %s: skipped — %s", name, reason)
+				sum.add(LegStep{App: name, Outcome: LegOutcomeSkipped, Reason: reason})
+				continue
+			}
+			t0 := o.Now()
+			if err := m.StartGuardedUpdate(name); err != nil {
+				why := "refused"
+				var ref *UpdateRefusal
+				if errors.As(err, &ref) {
+					why = ref.Reason
+				}
+				if legTransient[why] && pass == 0 {
+					m.logger.Printf("[INFO] [update-leg] %s: refused (%s) — a passing reason, retried once later tonight", name, why)
+					retry = append(retry, name)
+					continue
+				}
+				m.logger.Printf("[INFO] [update-leg] %s: skipped — the update refused (%s)", name, why)
+				sum.add(LegStep{App: name, Outcome: LegOutcomeSkipped, Reason: "refused:" + why})
+				continue
+			}
+			m.logger.Printf("[INFO] [update-leg] %s: step pressed %s → %s", name, summarisePin(entry.From), summarisePin(entry.To))
+			m.setLegFlags(true, true)
+			outcome := m.legWait(ctx, o, name)
+			m.setLegFlags(true, false)
+			step := LegStep{App: name, Outcome: outcome, From: entry.From, To: entry.To, Seconds: o.Now().Sub(t0).Round(100 * time.Millisecond).Seconds()}
+			sum.add(step)
+			m.recordAutoUpdate(name, &AutoUpdateRecord{At: t0.UTC().Format(time.RFC3339), Outcome: outcome, From: entry.From, To: entry.To})
+			m.logger.Printf("[INFO] [update-leg] %s: step ended %s after %.1f s", name, outcome, step.Seconds)
+		}
+	}
+	return finish()
+}
+
+// legStop is the leg's own stop check before every press: cancelled, switched off, or W+5h reached.
+func (m *Manager) legStop(ctx context.Context, o *UpdateLegOptions, sum *UpdateLegSummary) string {
+	switch {
+	case ctx.Err() != nil:
+		m.logger.Printf("[WARN] [update-leg] cancelled (the controller is stopping) — the remaining apps wait for the next night")
+		return LegSkipCancelled
+	case o.Enabled != nil && !o.Enabled():
+		m.logger.Printf("[INFO] [update-leg] the switch was turned OFF during the leg — no further step tonight")
+		return LegSkipSwitchedOff
+	case !o.Now().Before(sum.Deadline):
+		m.logger.Printf("[INFO] [update-leg] W+5h reached (%s) — no new step starts; the full-system backup keeps its hour, the rest waits for the next night", sum.Deadline.In(o.Location).Format("15:04"))
+		return LegSkipWindowEnd
+	}
+	return ""
+}
+
+// legWait waits until the pressed step has ended and returns its outcome. A cancelled context stops the
+// WAIT only — the update job itself runs on, and its journal finishes it after a restart.
+func (m *Manager) legWait(ctx context.Context, o *UpdateLegOptions, name string) string {
+	for m.IsUpdating(name) {
+		select {
+		case <-ctx.Done():
+			return LegOutcomeFailed
+		case <-time.After(o.Poll):
+		}
+	}
+	st, ok := m.GetStack(name)
+	if !ok {
+		return LegOutcomeFailed
+	}
+	switch {
+	case st.UpdatePhase == UpdatePhaseDone:
+		return LegOutcomeDone
+	case st.UpdatePhase == UpdatePhaseUndone:
+		return LegOutcomeUndone
+	case st.updateHeld || st.UpdateErrorKey == UpdateErrorKeyHeld || st.HoldReason != "":
+		return LegOutcomeHeld
+	}
+	return LegOutcomeFailed
+}
+
+// legCandidate decides whether the leg may press this app tonight, and which step it would take. It
+// returns ("", entry) to press, legCurrent when there is nothing to do, or a skip reason.
+func (m *Manager) legCandidate(ctx context.Context, name string, o *UpdateLegOptions) (LadderEntry, string) {
+	st, ok := m.GetStack(name)
+	if !ok || !st.Deployed {
+		return LadderEntry{}, legCurrent
+	}
+	if st.HoldReason != "" || st.updateHeld {
+		return LadderEntry{}, LegSkipHeld
+	}
+	if g := m.guards(); g != nil {
+		if held, _ := g.HoldFor(name); held {
+			return LadderEntry{}, LegSkipHeld
+		}
+	}
+	switch CatalogOrder(*st) {
+	case UpdateOrderCurrent:
+		return LadderEntry{}, legCurrent
+	case UpdateOrderAhead:
+		return LadderEntry{}, LegSkipAhead
+	case UpdateOrderBehind:
+	default:
+		return LadderEntry{}, LegSkipUnknownOrder
+	}
+	if st.AppConfig == nil || len(st.AppConfig.PinnedImages) == 0 {
+		return LadderEntry{}, LegSkipUnpinned
+	}
+	pinned := st.AppConfig.PinnedImages
+	tplDir := filepath.Dir(m.CatalogTemplatePath(name, "docker-compose.yml"))
+	ladder, err := LoadLadder(filepath.Join(tplDir, ".felhom.yml"))
+	if err != nil || len(ladder) == 0 {
+		return LadderEntry{}, LegSkipNoTestRecord
+	}
+	idx := -1
+	for i := len(ladder) - 1; i >= 0; i-- { // the SAME choice nextLadderStep makes
+		if sameRefs(ladder[i].From, pinned) {
+			idx = i
+			break
+		}
+	}
+	if idx < 0 {
+		if sameRefs(ladder[len(ladder)-1].To, pinned) {
+			return LadderEntry{}, LegSkipNoTestRecord // at the head, behind only by something no step records
+		}
+		m.logger.Printf("[INFO] [update-leg] %s: the installed version %s matches no update_ladder entry — an app older than the ladder is never pressed by the leg (a person can)", name, summarisePin(pinned))
+		return LadderEntry{}, LegSkipOlderThanLadder
+	}
+	e := ladder[idx]
+	if e.Verdict != "proven" {
+		return e, LegSkipNotProven
+	}
+	if e.Marks.NeedsPerson != nil && strings.TrimSpace(*e.Marks.NeedsPerson) != "" {
+		return e, LegSkipNeedsPerson
+	}
+	if fs := st.AppConfig.FailedStep; fs != nil && sameRefs(fs.To, e.To) && fs.Ladder == LadderPrint(ladder) {
+		return e, LegSkipFailedBefore
+	}
+	if e.Marks.FilesMayChange {
+		whole, why := false, "no whole-copy check wired"
+		if o.FreshWholeCopy != nil {
+			whole, why = o.FreshWholeCopy(ctx, name)
+		}
+		if !whole {
+			m.logger.Printf("[INFO] [update-leg] %s: the step may change the app's files and no fresh whole copy exists (%s)", name, why)
+			return e, LegSkipFilesNoCopy
+		}
+	}
+	return e, ""
+}
+
+// ── The records the leg and the update write into app.yaml ─────────────────────────────────────────
+
+// FailedStep is R-680's record: the step whose update was undone or held.
+type FailedStep struct {
+	To      map[string]string `yaml:"to" json:"to"`
+	Ladder  string            `yaml:"ladder" json:"ladder"` // LadderPrint of the ladder it failed on
+	At      string            `yaml:"at" json:"at"`
+	Outcome string            `yaml:"outcome" json:"outcome"` // undone | held
+}
+
+// AutoUpdateRecord is the leg's last step on an app — the page's line.
+type AutoUpdateRecord struct {
+	At      string            `yaml:"at" json:"at"`
+	Outcome string            `yaml:"outcome" json:"outcome"`
+	From    map[string]string `yaml:"from,omitempty" json:"from,omitempty"`
+	To      map[string]string `yaml:"to,omitempty" json:"to,omitempty"`
+}
+
+// mutateAppConfig loads app.yaml, applies fn (false = nothing to write), saves it and mirrors the
+// in-memory copy. A failed write is logged and never fails the caller — these are records.
+func (m *Manager) mutateAppConfig(name, dir, what string, fn func(cfg *AppConfig) bool) {
+	cfg := LoadAppConfig(dir)
+	if cfg == nil || !fn(cfg) {
+		return
+	}
+	meta := LoadMetadata(dir)
+	if err := SaveAppConfig(dir, cfg, m.encKey, SensitiveEnvVars(&meta)); err != nil {
+		m.logger.Printf("[ERROR] [stacks] %s: recording %s failed: %v", name, what, err)
+		return
+	}
+	m.mu.Lock()
+	if st, ok := m.stacks[name]; ok && st.AppConfig != nil {
+		fn(st.AppConfig)
+	}
+	m.mu.Unlock()
+}
+
+// recordFailedStep writes R-680's record for the step `to` (undone or held), tied to the ladder the
+// catalog carries now.
+func (m *Manager) recordFailedStep(name, dir string, to map[string]string, outcome string) {
+	if len(to) == 0 {
+		return
+	}
+	ladder, _ := LoadLadder(m.CatalogTemplatePath(name, ".felhom.yml"))
+	rec := &FailedStep{To: to, Ladder: LadderPrint(ladder), At: m.now().UTC().Format(time.RFC3339), Outcome: outcome}
+	m.mutateAppConfig(name, dir, "failed_update_step", func(cfg *AppConfig) bool { cfg.FailedStep = rec; return true })
+	m.logger.Printf("[INFO] [stacks] update %s: step %s recorded as %s — the automatic leg will not press it again until the catalog's ladder changes (ladder %s)", name, summarisePin(to), outcome, rec.Ladder)
+}
+
+// clearFailedStep drops R-680's record after a successful update.
+func (m *Manager) clearFailedStep(name, dir string) {
+	m.mutateAppConfig(name, dir, "failed_update_step", func(cfg *AppConfig) bool {
+		if cfg.FailedStep == nil {
+			return false
+		}
+		cfg.FailedStep = nil
+		return true
+	})
+}
+
+func (m *Manager) recordAutoUpdate(name string, rec *AutoUpdateRecord) {
+	st, ok := m.GetStack(name)
+	if !ok {
+		return
+	}
+	m.mutateAppConfig(name, filepath.Dir(st.ComposePath), "last_auto_update", func(cfg *AppConfig) bool { cfg.LastAutoUpdate = rec; return true })
+}