From 209426c609045e18304b0e519cf74130914fd785 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 | 82 +++++++++++++++++++++++++++++++++-- 2 files changed, 94 insertions(+), 4 deletions(-) diff --git a/internal/daemon/reconciler.go b/internal/daemon/reconciler.go index 7a873336..a151b9b1 100644 --- a/internal/daemon/reconciler.go +++ b/internal/daemon/reconciler.go @@ -204,13 +204,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 70317d43..851978ba 100644 --- a/test/e2e/bootcnode_test.go +++ b/test/e2e/bootcnode_test.go @@ -414,6 +414,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() @@ -427,10 +441,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") @@ -456,6 +489,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, @@ -524,6 +562,44 @@ 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 28c87cb76e44871c0d976e7b9420a34ae1026206 Mon Sep 17 00:00:00 2001 From: Alice Frosi Date: Fri, 30 Oct 2026 13:10:20 +0000 Subject: [PATCH 2/2] hack: read host journal in gather-logs.sh The daemon image does not ship journalctl, so the per-node journal artifact only contained "executable file `journalctl` not found". Enter the host mount namespace via nsenter, as getBootCount already does, so the full host journal across all boots is collected. Also save `journalctl --list-boots` to map boot ids to timestamps. Assisted-by: AI Signed-off-by: Alice Frosi --- hack/gather-logs.sh | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/hack/gather-logs.sh b/hack/gather-logs.sh index a580b12a..474d1318 100755 --- a/hack/gather-logs.sh +++ b/hack/gather-logs.sh @@ -55,8 +55,12 @@ for node in "${nodes[@]}"; do -o jsonpath='{.items[0].metadata.name}' 2>/dev/null || true) if [[ -n "${daemon_pod}" ]]; then - run "journal-${node}.txt" kubectl exec -n bootc-operator "${daemon_pod}" -- \ - journalctl --no-pager + # The daemon image has no journalctl; enter the host mount namespace + # to read the host journal (all boots). + host_exec=(kubectl exec -n bootc-operator "${daemon_pod}" -- \ + nsenter -m/proc/1/ns/mnt --) + run "journal-${node}.txt" "${host_exec[@]}" journalctl --no-pager + run "journal-list-boots-${node}.txt" "${host_exec[@]}" journalctl --no-pager --list-boots fi done