DNM e2e: fix flaky TestMidRolloutImageChange boot count assertion

internal/daemon/reconciler.go

@@ -202,13 +202,27 @@ func (r *BootcNodeReconciler) reconcileBootcNode(
 		}, nil
 	}
 
+	desiredDigest := digested.Digest().String()
+
 	// Nothing to do the desired image matches the booted ones.
 	// Reset the stage backoff to start from a clean state.
-	if image.InfoMatchesDigest(bn.Status.Booted, digested.Digest().String()) {
+	if image.InfoMatchesDigest(bn.Status.Booted, desiredDigest) {
 		r.inflight.reset()
 		return reconcileResult{}, nil
 	}
 
+	// XXX: temporary debug logging for https://github.com/bootc-dev/bootc-operator/pull/251
+	stagedImg := "<nil>"
+	if bn.Status.Staged != nil {
+		stagedImg = bn.Status.Staged.Image
+	}
+	log.Info("XXX booted image mismatch",
+		"bootedImage", bn.Status.Booted.Image,
+		"bootedDigest", bn.Status.Booted.ImageDigest,
+		"desiredDigest", desiredDigest,
+		"stagedImage", stagedImg,
+	)
+
 	stageErr := r.inflight.takeErr()
 
 	if stageErr != nil {

internal/daemon/reconciler_test.go

@@ -12,6 +12,7 @@ import (
 	. "github.com/onsi/gomega"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"sigs.k8s.io/controller-runtime/pkg/client"
+	"sigs.k8s.io/controller-runtime/pkg/event"
 
 	bootcv1alpha1 "github.com/bootc-dev/bootc-operator/api/v1alpha1"
 	"github.com/bootc-dev/bootc-operator/internal/bootc"
@@ -383,6 +384,63 @@ func TestRollback(t *testing.T) {
 	g.Expect(fake.getRebooted()).To(BeFalse())
 }
 
+// TestStaleCacheSpuriousRestage demonstrates that a stale StatusWatcher
+// cache can cause the reconciler to spuriously re-stage an image that is
+// already booted. This reproduces the mid-rollout bug where a node reboots
+// into v2 but the cached bootc status still shows the pre-reboot state,
+// causing the daemon to stage v2 again.
+func TestStaleCacheSpuriousRestage(t *testing.T) {
+	g := NewWithT(t)
+	ctx := context.Background()
+
+	// Post-reboot reality: node is booted on image C, nothing staged.
+	fake := &fakeExecutor{}
+	fake.status = newBootcStatus(testutil.DigestC)
+
+	// Stale cache: still believes the node is booted on image A.
+	staleStatus := newBootcStatus(testutil.DigestA)
+	watcher := &StatusWatcher{
+		Events:   make(chan event.GenericEvent, 1),
+		NodeName: testNodeName,
+		Executor: fake,
+	}
+	watcher.cached = &staleStatus
+	watcher.started = true
+
+	r := &BootcNodeReconciler{
+		NodeName:      testNodeName,
+		Executor:      fake,
+		StatusWatcher: watcher,
+		stageDone:     make(chan event.GenericEvent, 1),
+	}
+	t.Cleanup(func() {
+		r.inflight.mu.Lock()
+		if r.inflight.cancel != nil {
+			r.inflight.cancel()
+		}
+		r.inflight.mu.Unlock()
+	})
+
+	// Desired image is C, which matches what's actually booted.
+	bn := testutil.NewNode(testNodeName, testutil.ImageDigestRefC)
+
+	res, err := r.reconcileBootcNode(ctx, bn)
+	g.Expect(err).NotTo(HaveOccurred())
+	g.Expect(res.needsReboot).To(BeFalse(), "should not trigger reboot")
+
+	// populateBootcFields fills bn.Status from the watcher cache.
+	// With a fresh cache this would show DigestC (correct); with stale
+	// cache it shows DigestA, causing the mismatch.
+	g.Expect(bn.Status.Booted.ImageDigest).To(Equal(testutil.DigestC),
+		"stale cache returned wrong booted digest")
+
+	// After reconcileBootcNode, acquire() sets inflight.image synchronously
+	// before the stage goroutine starts. A non-empty value means a spurious
+	// stage was triggered.
+	g.Expect(r.inflight.isInFlight(testutil.ImageDigestRefC)).To(BeFalse(),
+		"stale cache caused spurious re-stage of already-booted image")
+}
+
 func TestCancelInflightStage(t *testing.T) {
 	g := NewWithT(t)
 	g.SetDefaultEventuallyTimeout(pollTimeout)

test/e2e/bootcnode_test.go

@@ -413,6 +413,20 @@ func TestMidRolloutImageChange(t *testing.T) {
 
 	t.Logf("Node %q is Rebooting, node %q is the other node", rebootingNode, otherNode)
 
+	// Record boot count on the other node (the rebooting node's kubelet
+	// may already be down, so skip it to avoid a connection-refused error).
+	bc := getBootCount(t, env, ctx, otherNode)
+	t.Logf("Node %q boot count at Rebooting detection: %s (before: %s)",
+		otherNode, bc, bootCountBefore[otherNode])
+
+	// Log BootcNode status for both nodes at the moment of detection.
+	for _, nodeName := range []string{rebootingNode, otherNode} {
+		var bn bootcv1alpha1.BootcNode
+		if err := env.Client.Get(ctx, client.ObjectKey{Name: nodeName}, &bn); err == nil {
+			logBootcNodeStatus(t, &bn)
+		}
+	}
+
 	// Phase 5: Immediately switch target to second update image.
 	updateRef2 := env.NodeImageUpdate2DigestedPullSpec()
 
@@ -426,10 +440,29 @@ func TestMidRolloutImageChange(t *testing.T) {
 	// Phase 6: Wait for both nodes to be Idle with the second update image.
 	// Reboots are serialized: wait for the node already rebooting first so
 	// the other node's timeout does not include waiting for its reboot slot.
+	// Log state transitions to capture the daemon's decisions after each reboot.
 	for _, nodeName := range []string{rebootingNode, otherNode} {
-		testutil.WaitForNodeIdle(t, g, ctx, env.Client, nodeName, 8*time.Minute,
-			HaveField("Booted", HaveField("ImageDigest", Equal(env.NodeImageUpdate2Digest()))),
-		)
+		lastReason := ""
+		g.Eventually(func(g Gomega) string {
+			var bn bootcv1alpha1.BootcNode
+			g.Expect(env.Client.Get(ctx, client.ObjectKey{Name: nodeName}, &bn)).To(Succeed())
+
+			cond := meta.FindStatusCondition(bn.Status.Conditions, bootcv1alpha1.NodeIdle)
+			var reason string
+			if cond != nil {
+				reason = fmt.Sprintf("%s:%s", cond.Status, cond.Reason)
+			}
+			if reason != lastReason {
+				logBootcNodeStatus(t, &bn)
+				lastReason = reason
+			}
+
+			g.Expect(cond).NotTo(BeNil())
+			g.Expect(cond.Status).To(Equal(metav1.ConditionTrue), "waiting for Idle")
+			g.Expect(bn.Status.Booted).NotTo(BeNil())
+			g.Expect(bn.Status.Booted.ImageDigest).To(Equal(env.NodeImageUpdate2Digest()))
+			return reason
+		}).WithTimeout(8 * time.Minute).WithPolling(pollInterval).ShouldNot(BeEmpty())
 	}
 
 	t.Logf("Both nodes are Idle with second update image")
@@ -455,6 +488,11 @@ func TestMidRolloutImageChange(t *testing.T) {
 			"an extra reboot means it wastefully booted into the first update image",
 		otherNode, beforeCount, afterCount)
 
+	// Dump bootc status on the other node for post-mortem analysis.
+	bootcStatus := execOnNode(t, g, env, ctx, otherNode,
+		"nsenter", "-m/proc/1/ns/mnt", "--", "bootc", "status", "--json")
+	t.Logf("Node %q bootc status:\n%s", otherNode, bootcStatus)
+
 	t.Logf(
 		"Verified node %q rebooted exactly once (no wasteful reboot into first image)",
 		otherNode,
@@ -523,6 +561,32 @@ func getBootCount(t *testing.T, env *e2eutil.Env, ctx context.Context, nodeName
 	return fmt.Sprintf("%d", count)
 }
 
+func logBootcNodeStatus(t *testing.T, bn *bootcv1alpha1.BootcNode) {
+	t.Helper()
+
+	booted := "<nil>"
+	if bn.Status.Booted != nil {
+		booted = fmt.Sprintf("image=%s digest=%s", bn.Status.Booted.Image, bn.Status.Booted.ImageDigest)
+	}
+	staged := "<nil>"
+	if bn.Status.Staged != nil {
+		staged = fmt.Sprintf("image=%s digest=%s", bn.Status.Staged.Image, bn.Status.Staged.ImageDigest)
+	}
+	rollback := "<nil>"
+	if bn.Status.Rollback != nil {
+		rollback = fmt.Sprintf("image=%s digest=%s", bn.Status.Rollback.Image, bn.Status.Rollback.ImageDigest)
+	}
+
+	idle := "<not set>"
+	if cond := meta.FindStatusCondition(bn.Status.Conditions, bootcv1alpha1.NodeIdle); cond != nil {
+		idle = fmt.Sprintf("%s:%s", cond.Status, cond.Reason)
+	}
+
+	t.Logf("BootcNode %q: idle=%s desired=%s desiredState=%s booted=[%s] staged=[%s] rollback=[%s]",
+		bn.Name, idle, bn.Spec.DesiredImage, bn.Spec.DesiredImageState,
+		booted, staged, rollback)
+}
+
 // TestPauseResume provisions a worker node, starts an update with the
 // pool paused, verifies the node stages but does not reboot, then resumes
 // and verifies the update completes.