v0.303.0 (code): after a restart, a backup capture waits for the drive's bind (R-897)

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS

controller/internal/backup/backup.go

@@ -25,6 +25,14 @@ import (
 // moved out of the controller into the host agent (slice 8C). This Manager now
 // only owns the app-data domain.
 type Manager struct {
+	// R-897: when this controller started, and the seams of the post-boot drive wait (driveready.go). Zero
+	// startedAt = no wait (a Manager built outside NewManager, e.g. a test that does not ask for it).
+	startedAt      time.Time
+	driveLive      func(root string) bool
+	driveWaitPoll  func(time.Duration)
+	nowFn          func() time.Time
+	driveWarned    map[string]bool
+	driveMu        sync.Mutex // its own lock: the capture sweep may run while m.mu is held elsewhere
 	cfg            *config.Config
 	logger         *log.Logger
 	settings       *settings.Settings
@@ -370,6 +378,7 @@ func NewManager(cfg *config.Config, sett *settings.Settings, logger *log.Logger)
 		logger:         logger,
 		settings:       sett,
 		systemDataPath: cfg.Paths.SystemDataPath,
+		startedAt:      time.Now(),
 	}
 	// R-166: its OWN file next to quiesce-state.json, never inside it — one file, one writer.
 	m.appStop = NewAppStopGuard(filepath.Join(cfg.Paths.DataDir, "appstop-state.json"), logger)

controller/internal/backup/driveready.go

@@ -0,0 +1,103 @@
+package backup
+
+import (
+	"os"
+	"strings"
+	"time"
+)
+
+// R-897 (2026-10-07): after a host restart the agent binds each drive under /mnt/felhom-drives, and when the guest
+// started after that first bind it NORMALIZES it once more (umount + mount, felhom-agent localapi/intermediary.go). A
+// recovery-unit capture that ran in that second failed — `mkdir /mnt/felhom-drives/hdd_1/backups: permission
+// denied` — and the operator got a backup failure for a healthy app. The kernel lane restarts boxes at night, so this
+// would have come after every kernel step.
+//
+// The rule: for DriveWaitWindow after the controller starts, a capture for an app on a drive runs only once that
+// drive's bind is LIVE in this process's mount namespace (the same signal the startup app gate uses,
+// web/intermediary.go driveBindLive). A periodic refresh skips the app until then (it runs every 5 minutes anyway);
+// a data run waits for it. After the window the capture runs whatever the bind says, and says so once at WARN. The
+// agent's bind order is unchanged. Pinned by driveready_test.go.
+
+// DriveWaitWindow is how long after the controller starts a capture waits for a drive's bind.
+const DriveWaitWindow = 10 * time.Minute
+
+const drivesParent = "/mnt/felhom-drives/"
+
+// driveRootOf is "/mnt/felhom-drives/<name>" for a path under it, "" for any other path (the system-data SSD).
+func driveRootOf(p string) string {
+	if !strings.HasPrefix(p, drivesParent) {
+		return ""
+	}
+	name := strings.SplitN(strings.TrimPrefix(p, drivesParent), "/", 2)[0]
+	if name == "" {
+		return ""
+	}
+	return drivesParent + name
+}
+
+// mountinfoHasTarget reports whether root is a mount target in this process's own mount namespace.
+func mountinfoHasTarget(root string) bool {
+	data, err := os.ReadFile("/proc/self/mountinfo")
+	if err != nil {
+		return false
+	}
+	for _, line := range strings.Split(string(data), "\n") {
+		if f := strings.Fields(line); len(f) >= 5 && f[4] == root {
+			return true
+		}
+	}
+	return false
+}
+
+func (m *Manager) now() time.Time {
+	if m.nowFn != nil {
+		return m.nowFn()
+	}
+	return time.Now()
+}
+
+// driveReady says whether a capture for an app at drivePath may run now (true outside the post-boot window, for a
+// non-drive path, or once the bind is live). dataRun: wait (poll) for the bind until the window ends instead of
+// skipping.
+func (m *Manager) driveReady(drivePath string, dataRun bool) bool {
+	root := driveRootOf(drivePath)
+	if root == "" || m.startedAt.IsZero() {
+		return true
+	}
+	live := m.driveLive
+	if live == nil {
+		live = mountinfoHasTarget
+	}
+	deadline := m.startedAt.Add(DriveWaitWindow)
+	for {
+		if live(root) {
+			return true
+		}
+		if !m.now().Before(deadline) {
+			m.driveMu.Lock()
+			warned := m.driveWarned[root]
+			if m.driveWarned == nil {
+				m.driveWarned = map[string]bool{}
+			}
+			m.driveWarned[root] = true
+			m.driveMu.Unlock()
+			if !warned {
+				m.logger.Printf("[WARN] [backup] %s is still not bound live %s after the controller started — capturing anyway (R-897)",
+					root, DriveWaitWindow)
+			}
+			return true
+		}
+		if !dataRun {
+			if m.isDebug() {
+				m.logger.Printf("[DEBUG] [backup] recovery-unit refresh waits for %s — its bind is not live yet after the start (R-897)", root)
+			}
+			return false
+		}
+		sleep := m.driveWaitPoll
+		if sleep == nil {
+			sleep = time.Sleep
+		}
+		m.logger.Printf("[INFO] [backup] waiting for %s to be bound live before the capture (post-boot, R-897)", root)
+		sleep(5 * time.Second)
+	}
+}

controller/internal/backup/driveready_test.go

@@ -0,0 +1,78 @@
+package backup
+
+import (
+	"testing"
+	"time"
+)
+
+// drivePathProvider puts every app on /mnt/felhom-drives/hdd_1 (the measured R-897 case).
+type drivePathProvider struct{ unitFailProvider }
+
+func (p *drivePathProvider) GetStackHDDPath(string) string { return "/mnt/felhom-drives/hdd_1" }
+
+// R-897: right after a boot, a capture for an app on a drive waits until the drive's bind is LIVE. The drive reads
+// not-bound, then bound → the capture (here a capture that fails, so it is visible as a unit event) starts only after.
+// COMPANION RED-PROOF (observed): remove the driveReady call in captureAllRecoveryUnits → "captured while the drive
+// was not bound".
+func TestDriveReady_RefreshWaitsForTheBindThenCaptures(t *testing.T) {
+	m, got := newUnitNotifyManager(t, []string{"calibre-web"}, map[string]bool{"calibre-web": true})
+	base := m.stackProvider.(*unitFailProvider)
+	m.stackProvider = &drivePathProvider{*base}
+	now := time.Date(2026, 10, 7, 15, 16, 28, 0, time.UTC)
+	m.startedAt, m.nowFn = now.Add(-20*time.Second), func() time.Time { return now }
+	bound := false
+	var asked []string
+	m.driveLive = func(root string) bool { asked = append(asked, root); return bound }
+
+	m.captureAllRecoveryUnits(false)
+	if len(*got) != 0 {
+		t.Fatalf("captured while the drive was not bound: %+v", *got)
+	}
+	if len(asked) == 0 || asked[0] != "/mnt/felhom-drives/hdd_1" {
+		t.Fatalf("the drive root asked = %v", asked)
+	}
+	bound = true
+	m.captureAllRecoveryUnits(false)
+	if len(*got) != 1 {
+		t.Fatalf("after the bind the capture must run: %+v", *got)
+	}
+}
+
+// After the window the capture runs whatever the bind says (and says so).
+func TestDriveReady_AfterTheWindowItRunsAnyway(t *testing.T) {
+	m, got := newUnitNotifyManager(t, []string{"calibre-web"}, map[string]bool{"calibre-web": true})
+	base := m.stackProvider.(*unitFailProvider)
+	m.stackProvider = &drivePathProvider{*base}
+	now := time.Date(2026, 10, 7, 15, 30, 0, 0, time.UTC)
+	m.startedAt, m.nowFn = now.Add(-DriveWaitWindow), func() time.Time { return now }
+	m.driveLive = func(string) bool { return false }
+	m.captureAllRecoveryUnits(false)
+	if len(*got) != 1 {
+		t.Fatalf("after %s the capture must run anyway: %+v", DriveWaitWindow, *got)
+	}
+}
+
+// A data run WAITS (polls) instead of skipping; a non-drive path and a Manager without a start time never wait.
+func TestDriveReady_DataRunPollsAndOthersNeverWait(t *testing.T) {
+	m, _ := newUnitNotifyManager(t, nil, nil)
+	now := time.Date(2026, 10, 7, 15, 16, 28, 0, time.UTC)
+	m.startedAt, m.nowFn = now, func() time.Time { return now }
+	n := 0
+	m.driveLive = func(string) bool { n++; return n >= 3 }
+	polls := 0
+	m.driveWaitPoll = func(d time.Duration) { polls++; now = now.Add(d) }
+	if !m.driveReady("/mnt/felhom-drives/hdd_1/x", true) || polls != 2 {
+		t.Fatalf("data run: polls=%d", polls)
+	}
+	if !m.driveReady("/var/lib/felhom/system-data", false) {
+		t.Fatal("the system SSD never waits")
+	}
+	m2, _ := newUnitNotifyManager(t, nil, nil)
+	m2.driveLive = func(string) bool { return false }
+	if !m2.driveReady("/mnt/felhom-drives/hdd_1", false) {
+		t.Fatal("no start time → no wait")
+	}
+	if driveRootOf("/mnt/felhom-drives/") != "" || driveRootOf("/mnt/felhom-drives/hdd_2/a/b") != "/mnt/felhom-drives/hdd_2" {
+		t.Fatal("driveRootOf")
+	}
+}

controller/internal/backup/recovery_unit.go

@@ -450,6 +450,11 @@ func (m *Manager) captureAllRecoveryUnits(dataRun bool) {
 		if m.settings != nil && (m.settings.IsDisconnected(drivePath) || m.settings.IsDecommissioned(drivePath)) {
 			continue // drive not writable — skip, the existing unit stays as-is
 		}
+		// R-897: right after a boot the agent may still be (re)binding the drive; a capture in that second failed
+		// with "permission denied" (measured on demo-hp 2026-10-07). Wait for the bind — bounded (driveready.go).
+		if !m.driveReady(drivePath, dataRun) {
+			continue
+		}
 		// Slice 4: a HELD app's unit is its RESTORE POINT, and the hold text names that copy's date.
 		// Re-capturing it would write the definition the app is held ON (after a failed update: the new
 		// version that would not start) into the unit, and the next Tier-2 run would mirror it over the