From 4a2bd7ab20be5520287c9add75df99cfaefba7fa Mon Sep 17 00:00:00 2001 From: Alice Frosi Date: Thu, 22 Oct 2026 12:01:10 +0000 Subject: [PATCH 1/2] DNM: instrument TestMidRolloutImageChange and daemon for debugging Add temporary debug logging to investigate the spurious re-stage after a cancelled bootc switch. The daemon logs the exact booted and desired digests when InfoMatchesDigest returns false, and the test logs BootcNode status at each state transition plus raw bootc status on the other node after convergence. Assisted-by: AI --- internal/daemon/reconciler.go | 16 +++++++- test/e2e/bootcnode_test.go | 70 +++++++++++++++++++++++++++++++++-- 2 files changed, 82 insertions(+), 4 deletions(-) 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/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. From fdeb8b199cf680a6473bc9ef5aecd053bcb795f2 Mon Sep 17 00:00:00 2001 From: Alice Frosi Date: Thu, 22 Oct 2026 12:51:25 +0000 Subject: [PATCH 2/2] DNM: add unit test for stale cache spurious re-stage Assisted-by: AI --- internal/daemon/reconciler_test.go | 58 ++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) 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)