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 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.