diff --git a/internal/daemon/reconciler.go b/internal/daemon/reconciler.go index 6bf422b3..cb253ea7 100644 --- a/internal/daemon/reconciler.go +++ b/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 := "" + 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 { diff --git a/internal/daemon/reconciler_test.go b/internal/daemon/reconciler_test.go index 3ea02aec..757c9307 100644 --- a/internal/daemon/reconciler_test.go +++ b/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) diff --git a/test/e2e/bootcnode_test.go b/test/e2e/bootcnode_test.go index aa6fe401..f01ffb94 100644 --- a/test/e2e/bootcnode_test.go +++ b/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 := "" + if bn.Status.Booted != nil { + booted = fmt.Sprintf("image=%s digest=%s", bn.Status.Booted.Image, bn.Status.Booted.ImageDigest) + } + staged := "" + if bn.Status.Staged != nil { + staged = fmt.Sprintf("image=%s digest=%s", bn.Status.Staged.Image, bn.Status.Staged.ImageDigest) + } + rollback := "" + if bn.Status.Rollback != nil { + rollback = fmt.Sprintf("image=%s digest=%s", bn.Status.Rollback.Image, bn.Status.Rollback.ImageDigest) + } + + idle := "" + 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.