diff --git a/pkg/pillar/cmd/zedkube/pendingvmi.go b/pkg/pillar/cmd/zedkube/pendingvmi.go index 888c54da571..5297294ffc2 100644 --- a/pkg/pillar/cmd/zedkube/pendingvmi.go +++ b/pkg/pillar/cmd/zedkube/pendingvmi.go @@ -242,15 +242,19 @@ func (z *zedkube) virtLauncherActiveOnThisNode(appKubeName string) bool { // podHasContainerError returns true if any container in the pod is in a // waiting state with an error-indicating reason (CrashLoopBackOff, -// ImagePullBackOff, ErrImagePull, CreateContainerError, RunContainerError) -// or has terminated with a non-zero exit code. These surface as "Error" or -// similar in kubectl's STATUS column even when Pod.Status.Phase=Running. +// ImagePullBackOff, ErrImagePull, CreateContainerError, +// CreateContainerConfigError, RunContainerError) or has terminated with a +// non-zero exit code. These surface as "Error" or similar in kubectl's STATUS +// column even when Pod.Status.Phase=Running. CreateContainerConfigError in +// particular covers a pod blocked on a missing Secret/ConfigMap (e.g. an +// orphaned CDI upload pod whose TLS secret was deleted), which must not be +// mistaken for a volume-mount wedge. func podHasContainerError(p corev1.Pod) bool { for _, cs := range p.Status.ContainerStatuses { if w := cs.State.Waiting; w != nil { switch w.Reason { case "CrashLoopBackOff", "ImagePullBackOff", "ErrImagePull", - "CreateContainerError", "RunContainerError": + "CreateContainerError", "CreateContainerConfigError", "RunContainerError": return true } } diff --git a/pkg/pillar/cmd/zedkube/pendingvmi_test.go b/pkg/pillar/cmd/zedkube/pendingvmi_test.go index 70c7eb34516..34b676c0022 100644 --- a/pkg/pillar/cmd/zedkube/pendingvmi_test.go +++ b/pkg/pillar/cmd/zedkube/pendingvmi_test.go @@ -34,6 +34,46 @@ func TestVMIPhaseIsPreRunning(t *testing.T) { } } +func TestPodHasContainerError(t *testing.T) { + mk := func(state corev1.ContainerState) corev1.Pod { + return corev1.Pod{Status: corev1.PodStatus{ + ContainerStatuses: []corev1.ContainerStatus{{State: state}}, + }} + } + waiting := func(reason string) corev1.ContainerState { + return corev1.ContainerState{Waiting: &corev1.ContainerStateWaiting{Reason: reason}} + } + + tests := []struct { + name string + pod corev1.Pod + want bool + }{ + {"CrashLoopBackOff", mk(waiting("CrashLoopBackOff")), true}, + {"ImagePullBackOff", mk(waiting("ImagePullBackOff")), true}, + {"ErrImagePull", mk(waiting("ErrImagePull")), true}, + {"CreateContainerError", mk(waiting("CreateContainerError")), true}, + // A pod blocked on a deleted Secret/ConfigMap, e.g. an orphaned CDI + // upload pod: Pending forever, but not a volume-mount wedge. + {"CreateContainerConfigError", mk(waiting("CreateContainerConfigError")), true}, + {"RunContainerError", mk(waiting("RunContainerError")), true}, + {"ContainerCreating", mk(waiting("ContainerCreating")), false}, + {"PodInitializing", mk(waiting("PodInitializing")), false}, + {"empty reason", mk(waiting("")), false}, + {"running", mk(corev1.ContainerState{Running: &corev1.ContainerStateRunning{}}), false}, + {"terminated ok", mk(corev1.ContainerState{ + Terminated: &corev1.ContainerStateTerminated{ExitCode: 0}}), false}, + {"terminated non-zero", mk(corev1.ContainerState{ + Terminated: &corev1.ContainerStateTerminated{ExitCode: 1}}), true}, + {"no containers", corev1.Pod{}, false}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + assert.Equal(t, tc.want, podHasContainerError(tc.pod)) + }) + } +} + func TestVirtLauncherPodIsActiveOnNode(t *testing.T) { const node = "andrew-cherry" const appKubeName = "enc-a2-84c66" diff --git a/pkg/pillar/cmd/zedkube/stuckmount.go b/pkg/pillar/cmd/zedkube/stuckmount.go new file mode 100644 index 00000000000..3f8de7402db --- /dev/null +++ b/pkg/pillar/cmd/zedkube/stuckmount.go @@ -0,0 +1,309 @@ +// Copyright (c) 2026 Zededa, Inc. +// SPDX-License-Identifier: Apache-2.0 + +//go:build k + +package zedkube + +import ( + "context" + "fmt" + "os" + "path/filepath" + "strconv" + "strings" + "syscall" + "time" + + "github.com/lf-edge/eve/pkg/pillar/kubeapi" + corev1 "k8s.io/api/core/v1" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/client-go/kubernetes" +) + +const ( + // stuckMountThreshold is how long a pod must sit Pending with an attached + // but unmounted volume before we treat it as a kubelet mount wedge. Node + // staging normally completes in seconds, so minutes means wedged. + stuckMountThreshold = 5 * time.Minute + // stuckMountMaxRecover caps recovery attempts within one wedge episode; + // reset once a tick observes no wedged pod. + stuckMountMaxRecover = 3 + // stuckMountSuppressWindow is the cooldown after a recovery attempt, so the + // detector cannot thrash a k3s restart faster than kubelet can recover. + stuckMountSuppressWindow = 15 * time.Minute + // stuckMountDevPath is where the Longhorn CSI node plugin materializes the + // block device once the volume is attached to this node. + stuckMountDevPath = "/dev/longhorn" + // stuckMountRecoveryMarker is a distinctive, greppable string emitted on + // every recovery so operators can spot mount-wedge restarts in the logs. + stuckMountRecoveryMarker = "MOUNT-WEDGE-RECOVERY" + // procRootDir is where the host PID namespace's process list is mounted. + procRootDir = "/proc" +) + +var ( + // stuckMountDryRun gates the recovery action. When true the detector only + // logs what it would do and takes NO action; when false it restarts k3s to + // give kubelet a fresh volume manager. + stuckMountDryRun = false + // stuckMountK3sStartFlag is cluster-init.sh's manual-start flag + // (K3S_MANUAL_START_FLAG in cluster-utils.sh). Touching it resets the + // supervisor's exponential restart backoff so k3s is relaunched promptly + // after we terminate it. It lives on the /run bind shared with the kube + // container. + stuckMountK3sStartFlag = "/run/kube/k3s-start" + // The cluster and host lookups the wedge signature and the recovery action + // depend on, indirected so tests can drive both without a live cluster and + // without signaling a real k3s. Overridden only in tests. + pvcGet = kubeapi.PVCGet + volumeAttachmentAttached = kubeapi.GetVolumeAttachmentAttached + devicePresent = longhornDevicePresent + signalK3s = signalK3sServer +) + +// checkStuckVolumeMount detects the kubelet volume-mount wedge: a pod scheduled +// on this node sits Pending past stuckMountThreshold with no container-level +// error, yet at least one of its Longhorn PVCs is attached to this node +// (VolumeAttachment reports Attached and /dev/longhorn/ exists) — meaning +// attach succeeded but kubelet never issued NodeStage, so the pod never starts. +// Longhorn, CDI and image pull are not at fault; the stall is in kubelet's +// volume manager, and only a fresh kubelet clears it. +// +// Recovery (see recoverKubeletMountWedge) restarts k3s so kubelet comes back +// with a fresh volume manager, rate-limited by stuckMountMaxRecover and +// stuckMountSuppressWindow. Set stuckMountDryRun to disable the action and only +// log. +func (z *zedkube) checkStuckVolumeMount() { + if z.nodeName == "" { + return + } + clientset, err := getKubeClientSet() + if err != nil { + log.Errorf("checkStuckVolumeMount: get clientset: %v", err) + return + } + z.checkStuckVolumeMountWithClient(clientset, time.Now()) +} + +// checkStuckVolumeMountWithClient is the body of one detector tick: it collects +// the wedged pods this node currently has and, subject to the per-episode +// attempt cap and cooldown, triggers recovery. now is passed in so the episode +// rate limiting is exercisable without a wall clock. +func (z *zedkube) checkStuckVolumeMountWithClient(clientset kubernetes.Interface, now time.Time) { + ctx, cancel := context.WithTimeout(context.Background(), kubeAPITimeout) + defer cancel() + // Restrict the LIST server-side: only Pending pods on this node can exhibit + // the wedge, and a multi-node cluster's other nodes are none of our business. + pods, err := clientset.CoreV1().Pods(kubeapi.EVEKubeNameSpace).List(ctx, metav1.ListOptions{ + FieldSelector: "spec.nodeName=" + z.nodeName + + ",status.phase=" + string(corev1.PodPending), + }) + if err != nil { + log.Errorf("checkStuckVolumeMount: list pods: %v", err) + return + } + + var wedged []string + for i := range pods.Items { + if desc, ok := z.podMountWedge(pods.Items[i], now); ok { + wedged = append(wedged, desc) + } + } + + if len(wedged) == 0 { + z.stuckMountRecoverCount = 0 + return + } + + if now.Before(z.stuckMountSuppressUntil) { + log.Functionf("checkStuckVolumeMount: %d wedged pod(s); recovery in cooldown until %v: %s", + len(wedged), z.stuckMountSuppressUntil, strings.Join(wedged, "; ")) + return + } + if z.stuckMountRecoverCount >= stuckMountMaxRecover { + log.Errorf("checkStuckVolumeMount: %d wedged pod(s) after %d recovery attempts; giving up until they clear: %s", + len(wedged), stuckMountMaxRecover, strings.Join(wedged, "; ")) + return + } + + z.stuckMountRecoverCount++ + z.stuckMountSuppressUntil = now.Add(stuckMountSuppressWindow) + z.recoverKubeletMountWedge(wedged) +} + +// podMountWedge reports whether pod p on this node exhibits the mount wedge and, +// if so, returns a human-readable description. It matches a Pending, non- +// terminating pod aged past stuckMountThreshold that has no container- or +// init-container error (image pull / crashloop are excluded as different +// failures) and at least one Longhorn PVC that is attached to this node yet +// still unmounted. +func (z *zedkube) podMountWedge(p corev1.Pod, now time.Time) (string, bool) { + if p.Spec.NodeName != z.nodeName { + return "", false + } + if p.Status.Phase != corev1.PodPending || isPodTerminating(p) { + return "", false + } + if podHasContainerError(p) || podHasInitContainerError(p) { + return "", false + } + age := now.Sub(p.CreationTimestamp.Time) + if age < stuckMountThreshold { + return "", false + } + for _, vol := range p.Spec.Volumes { + if vol.PersistentVolumeClaim == nil { + continue + } + pvc, err := pvcGet(vol.PersistentVolumeClaim.ClaimName, log) + if err != nil || pvc.Spec.VolumeName == "" { + continue + } + pvName := pvc.Spec.VolumeName + attached, err := volumeAttachmentAttached(pvName, z.nodeName, log) + if err != nil || !attached { + continue + } + if !devicePresent(pvName) { + continue + } + return fmt.Sprintf("pod=%s pv=%s attached+device-present but unmounted, Pending %v", + p.Name, pvName, age.Round(time.Second)), true + } + return "", false +} + +// longhornDevicePresent reports whether the Longhorn block device for pvName +// exists on this node, i.e. the volume is attached at the node level. +func longhornDevicePresent(pvName string) bool { + _, err := os.Stat(stuckMountDevPath + "/" + pvName) + return err == nil +} + +// podHasInitContainerError mirrors podHasContainerError over init containers: +// true if any init container is waiting on an error reason (image pull / +// create / run) or terminated non-zero. Used to exclude image-pull failures +// (e.g. a boot-image init container) from the mount-wedge signature. +func podHasInitContainerError(p corev1.Pod) bool { + for _, cs := range p.Status.InitContainerStatuses { + if w := cs.State.Waiting; w != nil { + switch w.Reason { + case "CrashLoopBackOff", "ImagePullBackOff", "ErrImagePull", + "CreateContainerError", "CreateContainerConfigError", "RunContainerError": + return true + } + } + if t := cs.State.Terminated; t != nil && t.ExitCode != 0 { + return true + } + } + return false +} + +// recoverKubeletMountWedge is the recovery action for the mount wedge. The only +// known remedy is a fresh kubelet, which we get by terminating k3s and letting +// cluster-init.sh's supervisor relaunch it. Because pillar runs in the host PID +// namespace and shares the /run bind with the kube container, zedkube can both +// reset the supervisor's restart backoff (touch K3S_MANUAL_START_FLAG) and send +// SIGTERM to the k3s server process directly. Every attempt logs a distinctive +// marker so a restart is easy to spot in the device logs. While stuckMountDryRun +// is true it takes NO action and only logs. +func (z *zedkube) recoverKubeletMountWedge(wedged []string) { + detail := strings.Join(wedged, "; ") + if stuckMountDryRun { + log.Noticef("%s: DRY-RUN would restart kubelet/k3s to clear the volume-mount wedge (attempt %d/%d): %s", + stuckMountRecoveryMarker, z.stuckMountRecoverCount, stuckMountMaxRecover, detail) + return + } + + log.Warnf("%s: restarting kubelet/k3s to clear the volume-mount wedge (attempt %d/%d): %s", + stuckMountRecoveryMarker, z.stuckMountRecoverCount, stuckMountMaxRecover, detail) + + // Reset the supervisor's exponential restart backoff so k3s is relaunched + // promptly rather than after a multi-minute wait. + if err := os.MkdirAll(filepath.Dir(stuckMountK3sStartFlag), 0755); err != nil { + log.Errorf("%s: cannot create %s dir: %v", stuckMountRecoveryMarker, stuckMountK3sStartFlag, err) + } else if f, err := os.Create(stuckMountK3sStartFlag); err != nil { + log.Errorf("%s: cannot touch %s: %v", stuckMountRecoveryMarker, stuckMountK3sStartFlag, err) + } else { + f.Close() + } + + pids, err := signalK3s() + if err != nil { + log.Errorf("%s: attempt %d/%d FAILED to enumerate k3s: %v; wedge: %s", + stuckMountRecoveryMarker, z.stuckMountRecoverCount, stuckMountMaxRecover, err, detail) + return + } + if len(pids) == 0 { + log.Errorf("%s: attempt %d/%d found no 'k3s server' process to signal; wedge: %s", + stuckMountRecoveryMarker, z.stuckMountRecoverCount, stuckMountMaxRecover, detail) + return + } + log.Warnf("%s: sent SIGTERM to k3s server pid(s) %v; cluster-init.sh will relaunch. attempt %d/%d, wedge: %s", + stuckMountRecoveryMarker, pids, z.stuckMountRecoverCount, stuckMountMaxRecover, detail) +} + +// signalK3sServer sends SIGTERM to every running "k3s server" process and +// returns the PIDs signaled. zedkube shares the host PID namespace, so the k3s +// process started in the kube container is visible and signalable here; the +// cluster-init.sh supervisor relaunches k3s once it exits, yielding a fresh +// kubelet volume manager. A PID whose signal fails is left out of the returned +// set, so an empty return means nothing was actually terminated. +func signalK3sServer() ([]int, error) { + pids, err := k3sServerPids(procRootDir) + if err != nil { + return nil, err + } + var signaled []int + for _, pid := range pids { + if err := syscall.Kill(pid, syscall.SIGTERM); err != nil { + log.Errorf("%s: SIGTERM pid %d failed: %v", stuckMountRecoveryMarker, pid, err) + continue + } + signaled = append(signaled, pid) + } + return signaled, nil +} + +// k3sServerPids returns the PIDs of the "k3s server" processes visible under +// procRoot. A process that disappears mid-scan, or whose cmdline is unreadable, +// is skipped; only an unreadable procRoot is an error. +func k3sServerPids(procRoot string) ([]int, error) { + entries, err := os.ReadDir(procRoot) + if err != nil { + return nil, err + } + var pids []int + for _, e := range entries { + pid, err := strconv.Atoi(e.Name()) + if err != nil { + continue // not a PID directory + } + raw, err := os.ReadFile(filepath.Join(procRoot, e.Name(), "cmdline")) + if err != nil { + continue // process gone or unreadable + } + if !isK3sServerCmdline(raw) { + continue + } + pids = append(pids, pid) + } + return pids, nil +} + +// isK3sServerCmdline reports whether a raw /proc//cmdline belongs to the +// k3s server process. +// +// k3s rewrites its process title to the single string "k3s server", so cmdline +// is one NUL-terminated token "k3s server" rather than the separate +// "k3s"/"server" argv elements exec would leave. Tokenizing the whole cmdline on +// whitespace therefore matches both that retitled form and a path-launched +// "/k3s server ...", while excluding a shell that merely mentions the +// string in a later argument (its first token is the shell). +func isK3sServerCmdline(raw []byte) bool { + cmdline := strings.ReplaceAll(strings.TrimRight(string(raw), "\x00"), "\x00", " ") + fields := strings.Fields(cmdline) + return len(fields) >= 2 && filepath.Base(fields[0]) == "k3s" && fields[1] == "server" +} diff --git a/pkg/pillar/cmd/zedkube/stuckmount_test.go b/pkg/pillar/cmd/zedkube/stuckmount_test.go new file mode 100644 index 00000000000..50d9bc5b2df --- /dev/null +++ b/pkg/pillar/cmd/zedkube/stuckmount_test.go @@ -0,0 +1,573 @@ +// Copyright (c) 2026 Zededa, Inc. +// SPDX-License-Identifier: Apache-2.0 + +//go:build k + +package zedkube + +import ( + "errors" + "os" + "path/filepath" + "testing" + "time" + + "github.com/lf-edge/eve/pkg/pillar/base" + "github.com/lf-edge/eve/pkg/pillar/kubeapi" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" + corev1 "k8s.io/api/core/v1" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/runtime" + "k8s.io/client-go/kubernetes/fake" + k8stesting "k8s.io/client-go/testing" +) + +// stuckMountFakes drives the cluster and host lookups the detector makes. +// claims binds a PVC name to its PV; attachedPVs and presentPVs are the PVs +// this node reports as attached and as having a /dev/longhorn device. +type stuckMountFakes struct { + claims map[string]string + attachedPVs map[string]bool + presentPVs map[string]bool + pvcErr map[string]error + attachErr map[string]error + + signalPids []int + signalErr error + signalCalls int + + flagPath string +} + +// installStuckMountFakes points the detector's lookups at f and its k3s-start +// flag at a temporary path, restoring the real ones when the test ends. +func installStuckMountFakes(t *testing.T, f *stuckMountFakes) { + t.Helper() + log = base.NewSourceLogObject(logrus.StandardLogger(), "test-zedkube", 0) + + origPVCGet, origAttached := pvcGet, volumeAttachmentAttached + origDevice, origSignal := devicePresent, signalK3s + origFlag, origDryRun := stuckMountK3sStartFlag, stuckMountDryRun + t.Cleanup(func() { + pvcGet, volumeAttachmentAttached = origPVCGet, origAttached + devicePresent, signalK3s = origDevice, origSignal + stuckMountK3sStartFlag, stuckMountDryRun = origFlag, origDryRun + }) + + f.flagPath = filepath.Join(t.TempDir(), "kube", "k3s-start") + stuckMountK3sStartFlag = f.flagPath + + pvcGet = func(pvcName string, _ *base.LogObject) (*corev1.PersistentVolumeClaim, error) { + if err := f.pvcErr[pvcName]; err != nil { + return nil, err + } + return &corev1.PersistentVolumeClaim{ + ObjectMeta: metav1.ObjectMeta{Name: pvcName}, + Spec: corev1.PersistentVolumeClaimSpec{VolumeName: f.claims[pvcName]}, + }, nil + } + volumeAttachmentAttached = func(pvName, nodeName string, _ *base.LogObject) (bool, error) { + if err := f.attachErr[pvName]; err != nil { + return false, err + } + return f.attachedPVs[pvName] && nodeName == testNodeName, nil + } + devicePresent = func(pvName string) bool { return f.presentPVs[pvName] } + signalK3s = func() ([]int, error) { + f.signalCalls++ + return f.signalPids, f.signalErr + } +} + +// wedgeFakes is the all-green setup: pvc-a is bound to pv-a, which is attached +// to this node and has its device present, so a stale Pending pod referencing +// pvc-a is wedged. +func wedgeFakes(t *testing.T) *stuckMountFakes { + t.Helper() + f := &stuckMountFakes{ + claims: map[string]string{"pvc-a": "pv-a"}, + attachedPVs: map[string]bool{"pv-a": true}, + presentPVs: map[string]bool{"pv-a": true}, + signalPids: []int{4242}, + } + installStuckMountFakes(t, f) + return f +} + +// pendingPod builds a Pending pod on this node, created age ago relative to now, +// referencing the named PVCs. +func pendingPod(name string, now time.Time, age time.Duration, claims ...string) corev1.Pod { + p := corev1.Pod{ + ObjectMeta: metav1.ObjectMeta{ + Name: name, + Namespace: kubeapi.EVEKubeNameSpace, + CreationTimestamp: metav1.NewTime(now.Add(-age)), + }, + Spec: corev1.PodSpec{NodeName: testNodeName}, + Status: corev1.PodStatus{Phase: corev1.PodPending}, + } + for i, claim := range claims { + p.Spec.Volumes = append(p.Spec.Volumes, corev1.Volume{ + Name: "vol" + string(rune('a'+i)), + VolumeSource: corev1.VolumeSource{ + PersistentVolumeClaim: &corev1.PersistentVolumeClaimVolumeSource{ClaimName: claim}, + }, + }) + } + return p +} + +func waitingPod(p corev1.Pod, reason string) corev1.Pod { + p.Status.ContainerStatuses = []corev1.ContainerStatus{ + {State: corev1.ContainerState{Waiting: &corev1.ContainerStateWaiting{Reason: reason}}}, + } + return p +} + +func waitingInitPod(p corev1.Pod, reason string) corev1.Pod { + p.Status.InitContainerStatuses = []corev1.ContainerStatus{ + {State: corev1.ContainerState{Waiting: &corev1.ContainerStateWaiting{Reason: reason}}}, + } + return p +} + +func TestIsK3sServerCmdline(t *testing.T) { + tests := []struct { + name string + cmdline string + want bool + }{ + // k3s rewrites its process title to one string, so the whole cmdline + // arrives as a single NUL-terminated token. + {"retitled single token", "k3s server\x00", true}, + {"argv form with flags", "k3s\x00server\x00--flannel-backend=none\x00", true}, + {"path launched retitled", "/var/lib/rancher/k3s/data/abc/bin/k3s server\x00", true}, + {"path launched argv", "/usr/bin/k3s\x00server\x00", true}, + {"no trailing NUL", "k3s server", true}, + // A shell that merely mentions the string must not be signaled. + {"shell mentioning k3s server", "/bin/sh\x00-c\x00k3s server\x00", false}, + {"eve-k cluster-init wrapper", "/bin/sh\x00/usr/bin/cluster-init.sh\x00", false}, + {"k3s agent", "k3s\x00agent\x00", false}, + {"k3s alone", "k3s\x00", false}, + {"killall script", "k3s-killall.sh\x00", false}, + {"basename must be exact", "k3ss\x00server\x00", false}, + {"other binary", "kubelet\x00--config\x00", false}, + {"kernel thread empty cmdline", "", false}, + {"only NULs", "\x00\x00", false}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + assert.Equal(t, tc.want, isK3sServerCmdline([]byte(tc.cmdline))) + }) + } +} + +func TestK3sServerPids(t *testing.T) { + log = base.NewSourceLogObject(logrus.StandardLogger(), "test-zedkube", 0) + procRoot := t.TempDir() + + write := func(dir, cmdline string) { + t.Helper() + assert.NoError(t, os.MkdirAll(filepath.Join(procRoot, dir), 0755)) + assert.NoError(t, os.WriteFile(filepath.Join(procRoot, dir, "cmdline"), []byte(cmdline), 0644)) + } + write("123", "k3s\x00server\x00--foo\x00") + write("456", "/var/lib/rancher/k3s/data/abc/bin/k3s server\x00") + write("789", "/bin/sh\x00-c\x00k3s server\x00") + // Non-numeric entries are not processes, even when their cmdline matches. + write("self", "k3s server\x00") + // A process that exited between the readdir and the read has no cmdline. + assert.NoError(t, os.MkdirAll(filepath.Join(procRoot, "999"), 0755)) + // Plain files at the top of /proc (uptime, meminfo, …) are not PIDs. + assert.NoError(t, os.WriteFile(filepath.Join(procRoot, "uptime"), []byte("1 1"), 0644)) + + pids, err := k3sServerPids(procRoot) + assert.NoError(t, err) + assert.Equal(t, []int{123, 456}, pids) + + _, err = k3sServerPids(filepath.Join(procRoot, "no-such-dir")) + assert.Error(t, err) +} + +func TestPodHasInitContainerError(t *testing.T) { + mk := func(state corev1.ContainerState) corev1.Pod { + return corev1.Pod{Status: corev1.PodStatus{ + InitContainerStatuses: []corev1.ContainerStatus{{State: state}}, + }} + } + waiting := func(reason string) corev1.ContainerState { + return corev1.ContainerState{Waiting: &corev1.ContainerStateWaiting{Reason: reason}} + } + + tests := []struct { + name string + pod corev1.Pod + want bool + }{ + {"CrashLoopBackOff", mk(waiting("CrashLoopBackOff")), true}, + {"ImagePullBackOff", mk(waiting("ImagePullBackOff")), true}, + {"ErrImagePull", mk(waiting("ErrImagePull")), true}, + {"CreateContainerError", mk(waiting("CreateContainerError")), true}, + {"CreateContainerConfigError", mk(waiting("CreateContainerConfigError")), true}, + {"RunContainerError", mk(waiting("RunContainerError")), true}, + // A normally-progressing init container is not an error. + {"PodInitializing", mk(waiting("PodInitializing")), false}, + {"ContainerCreating", mk(waiting("ContainerCreating")), false}, + {"empty reason", mk(waiting("")), false}, + {"running", mk(corev1.ContainerState{Running: &corev1.ContainerStateRunning{}}), false}, + {"terminated ok", mk(corev1.ContainerState{ + Terminated: &corev1.ContainerStateTerminated{ExitCode: 0}}), false}, + {"terminated non-zero", mk(corev1.ContainerState{ + Terminated: &corev1.ContainerStateTerminated{ExitCode: 1}}), true}, + {"no init containers", corev1.Pod{}, false}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + assert.Equal(t, tc.want, podHasInitContainerError(tc.pod)) + }) + } +} + +func TestPodMountWedge(t *testing.T) { + now := time.Now() + stale := 2 * stuckMountThreshold + + tests := []struct { + name string + pod func(*stuckMountFakes) corev1.Pod + mutate func(*stuckMountFakes) + want bool + wantPV string + wantPod string + }{ + { + name: "attached, device present, stale Pending", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("cdi-upload", now, stale, "pvc-a") }, + want: true, + wantPV: "pv-a", + wantPod: "cdi-upload", + }, + { + name: "pod on another node", + pod: func(*stuckMountFakes) corev1.Pod { + p := pendingPod("elsewhere", now, stale, "pvc-a") + p.Spec.NodeName = "other-node" + return p + }, + }, + { + name: "pod not yet scheduled", + pod: func(*stuckMountFakes) corev1.Pod { + p := pendingPod("unscheduled", now, stale, "pvc-a") + p.Spec.NodeName = "" + return p + }, + }, + { + name: "pod already Running", + pod: func(*stuckMountFakes) corev1.Pod { + p := pendingPod("running", now, stale, "pvc-a") + p.Status.Phase = corev1.PodRunning + return p + }, + }, + { + name: "pod terminating", + pod: func(*stuckMountFakes) corev1.Pod { + p := pendingPod("terminating", now, stale, "pvc-a") + ts := metav1.NewTime(now) + p.DeletionTimestamp = &ts + return p + }, + }, + { + name: "image pull failure is a different wedge", + pod: func(*stuckMountFakes) corev1.Pod { + return waitingPod(pendingPod("badimage", now, stale, "pvc-a"), "ImagePullBackOff") + }, + }, + { + // The orphaned CDI upload pod whose TLS secret was deleted: it sits + // Pending on an attached volume forever, but a kubelet restart will + // not help it. + name: "missing secret is a different wedge", + pod: func(*stuckMountFakes) corev1.Pod { + return waitingPod(pendingPod("nosecret", now, stale, "pvc-a"), "CreateContainerConfigError") + }, + }, + { + name: "init container image pull failure", + pod: func(*stuckMountFakes) corev1.Pod { + return waitingInitPod(pendingPod("badinit", now, stale, "pvc-a"), "ErrImagePull") + }, + }, + { + name: "container merely creating is not an error", + pod: func(*stuckMountFakes) corev1.Pod { + return waitingPod(pendingPod("creating", now, stale, "pvc-a"), "ContainerCreating") + }, + want: true, + wantPV: "pv-a", + wantPod: "creating", + }, + { + name: "just under the threshold", + pod: func(*stuckMountFakes) corev1.Pod { + return pendingPod("young", now, stuckMountThreshold-time.Second, "pvc-a") + }, + }, + { + name: "just over the threshold", + pod: func(*stuckMountFakes) corev1.Pod { + return pendingPod("old", now, stuckMountThreshold+time.Second, "pvc-a") + }, + want: true, + wantPV: "pv-a", + wantPod: "old", + }, + { + name: "no PVC volumes", + pod: func(*stuckMountFakes) corev1.Pod { + p := pendingPod("configonly", now, stale) + p.Spec.Volumes = []corev1.Volume{{ + Name: "cfg", + VolumeSource: corev1.VolumeSource{EmptyDir: &corev1.EmptyDirVolumeSource{}}, + }} + return p + }, + }, + { + name: "PVC lookup fails", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("pvcerr", now, stale, "pvc-a") }, + mutate: func(f *stuckMountFakes) { f.pvcErr = map[string]error{"pvc-a": errors.New("nope")} }, + }, + { + name: "PVC not yet bound to a PV", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("unbound", now, stale, "pvc-a") }, + mutate: func(f *stuckMountFakes) { f.claims = map[string]string{} }, + }, + { + name: "VolumeAttachment lookup fails", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("vaerr", now, stale, "pvc-a") }, + mutate: func(f *stuckMountFakes) { f.attachErr = map[string]error{"pv-a": errors.New("nope")} }, + }, + { + // Attach requested but not complete: kubelet is not at fault yet. + name: "attach still in progress", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("attaching", now, stale, "pvc-a") }, + mutate: func(f *stuckMountFakes) { f.attachedPVs = map[string]bool{} }, + }, + { + name: "attached but no device on this node", + pod: func(*stuckMountFakes) corev1.Pod { return pendingPod("nodev", now, stale, "pvc-a") }, + mutate: func(f *stuckMountFakes) { f.presentPVs = map[string]bool{} }, + }, + { + name: "second volume is the wedged one", + pod: func(*stuckMountFakes) corev1.Pod { + return pendingPod("multivol", now, stale, "pvc-unbound", "pvc-a") + }, + want: true, + wantPV: "pv-a", + wantPod: "multivol", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + f := wedgeFakes(t) + if tc.mutate != nil { + tc.mutate(f) + } + z := &zedkube{nodeName: testNodeName} + desc, got := z.podMountWedge(tc.pod(f), now) + assert.Equal(t, tc.want, got) + if !tc.want { + assert.Empty(t, desc) + return + } + // The description is what lands in the operator-facing recovery log. + assert.Contains(t, desc, "pod="+tc.wantPod) + assert.Contains(t, desc, "pv="+tc.wantPV) + }) + } +} + +// TestCheckStuckVolumeMountEpisode walks one wedge episode through the attempt +// cap and the cooldown, then confirms a cleared wedge re-arms recovery. +func TestCheckStuckVolumeMountEpisode(t *testing.T) { + f := wedgeFakes(t) + t0 := time.Now() + pod := pendingPod("cdi-upload", t0, 2*stuckMountThreshold) + pod.Spec.Volumes = []corev1.Volume{{ + Name: "vol", + VolumeSource: corev1.VolumeSource{ + PersistentVolumeClaim: &corev1.PersistentVolumeClaimVolumeSource{ClaimName: "pvc-a"}, + }, + }} + clientset := fake.NewSimpleClientset(&pod) + z := &zedkube{nodeName: testNodeName} + + z.checkStuckVolumeMountWithClient(clientset, t0) + assert.Equal(t, 1, z.stuckMountRecoverCount) + assert.Equal(t, 1, f.signalCalls) + assert.Equal(t, t0.Add(stuckMountSuppressWindow), z.stuckMountSuppressUntil) + assert.FileExists(t, f.flagPath) + + // Inside the cooldown the detector must not touch k3s again. + z.checkStuckVolumeMountWithClient(clientset, t0.Add(stuckMountSuppressWindow/2)) + assert.Equal(t, 1, z.stuckMountRecoverCount) + assert.Equal(t, 1, f.signalCalls) + + // Cooldown expired and still wedged: attempt again, up to the cap. + at := t0 + for i := 2; i <= stuckMountMaxRecover; i++ { + at = at.Add(stuckMountSuppressWindow + time.Minute) + z.checkStuckVolumeMountWithClient(clientset, at) + assert.Equal(t, i, z.stuckMountRecoverCount) + assert.Equal(t, i, f.signalCalls) + } + + // At the cap the detector gives up rather than thrashing k3s. + at = at.Add(stuckMountSuppressWindow + time.Minute) + z.checkStuckVolumeMountWithClient(clientset, at) + assert.Equal(t, stuckMountMaxRecover, z.stuckMountRecoverCount) + assert.Equal(t, stuckMountMaxRecover, f.signalCalls) + + // The wedge clears, which ends the episode and resets the attempt count. + f.presentPVs = map[string]bool{} + at = at.Add(time.Minute) + z.checkStuckVolumeMountWithClient(clientset, at) + assert.Equal(t, 0, z.stuckMountRecoverCount) + assert.Equal(t, stuckMountMaxRecover, f.signalCalls) + + // A later episode must be able to recover again, or the cap would disarm + // the detector for the lifetime of the process. + f.presentPVs = map[string]bool{"pv-a": true} + at = at.Add(stuckMountSuppressWindow + time.Minute) + z.checkStuckVolumeMountWithClient(clientset, at) + assert.Equal(t, 1, z.stuckMountRecoverCount) + assert.Equal(t, stuckMountMaxRecover+1, f.signalCalls) +} + +func TestCheckStuckVolumeMountNoRecovery(t *testing.T) { + t0 := time.Now() + wedged := pendingPod("cdi-upload", t0, 2*stuckMountThreshold, "pvc-a") + + tests := []struct { + name string + pods []runtime.Object + nodeName string + }{ + {"no pods at all", nil, testNodeName}, + {"only a healthy pod", []runtime.Object{func() runtime.Object { + p := pendingPod("young", t0, time.Minute, "pvc-a") + return &p + }()}, testNodeName}, + // The fake clientset does not evaluate field selectors, so these also + // prove the client-side re-check in podMountWedge does the filtering. + {"wedged pod on another node", []runtime.Object{func() runtime.Object { + p := wedged.DeepCopy() + p.Spec.NodeName = "other-node" + return p + }()}, testNodeName}, + {"node name not yet known", []runtime.Object{wedged.DeepCopy()}, ""}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + f := wedgeFakes(t) + z := &zedkube{nodeName: tc.nodeName} + z.checkStuckVolumeMountWithClient(fake.NewSimpleClientset(tc.pods...), t0) + assert.Equal(t, 0, z.stuckMountRecoverCount) + assert.Equal(t, 0, f.signalCalls) + assert.NoFileExists(t, f.flagPath) + }) + } +} + +// TestCheckStuckVolumeMountTwoPodsOneRestart checks that a tick with several +// wedged pods restarts k3s once, not once per pod. +func TestCheckStuckVolumeMountTwoPodsOneRestart(t *testing.T) { + f := wedgeFakes(t) + f.claims["pvc-b"] = "pv-b" + f.attachedPVs["pv-b"] = true + f.presentPVs["pv-b"] = true + + t0 := time.Now() + podA := pendingPod("cdi-upload-a", t0, 2*stuckMountThreshold, "pvc-a") + podB := pendingPod("cdi-upload-b", t0, 2*stuckMountThreshold, "pvc-b") + + z := &zedkube{nodeName: testNodeName} + z.checkStuckVolumeMountWithClient(fake.NewSimpleClientset(&podA, &podB), t0) + assert.Equal(t, 1, z.stuckMountRecoverCount) + assert.Equal(t, 1, f.signalCalls) +} + +// TestCheckStuckVolumeMountListError checks that an API blip neither triggers +// recovery nor clears an episode already in progress. +func TestCheckStuckVolumeMountListError(t *testing.T) { + f := wedgeFakes(t) + clientset := fake.NewSimpleClientset() + clientset.PrependReactor("list", "pods", + func(k8stesting.Action) (bool, runtime.Object, error) { + return true, nil, errors.New("apiserver unreachable") + }) + + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 2} + z.checkStuckVolumeMountWithClient(clientset, time.Now()) + assert.Equal(t, 2, z.stuckMountRecoverCount) + assert.Equal(t, 0, f.signalCalls) +} + +func TestRecoverKubeletMountWedge(t *testing.T) { + wedge := []string{"pod=cdi-upload pv=pv-a attached+device-present but unmounted, Pending 7m0s"} + + t.Run("touches the start flag and signals k3s", func(t *testing.T) { + f := wedgeFakes(t) + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 1} + z.recoverKubeletMountWedge(wedge) + assert.Equal(t, 1, f.signalCalls) + assert.FileExists(t, f.flagPath) + }) + + t.Run("dry run takes no action", func(t *testing.T) { + f := wedgeFakes(t) + stuckMountDryRun = true + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 1} + z.recoverKubeletMountWedge(wedge) + assert.Equal(t, 0, f.signalCalls) + assert.NoFileExists(t, f.flagPath) + }) + + t.Run("unwritable start flag still restarts k3s", func(t *testing.T) { + f := wedgeFakes(t) + // A regular file where the flag's parent directory should be: MkdirAll + // fails regardless of privileges. + blocked := filepath.Join(t.TempDir(), "run") + assert.NoError(t, os.WriteFile(blocked, nil, 0644)) + stuckMountK3sStartFlag = filepath.Join(blocked, "k3s-start") + + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 1} + z.recoverKubeletMountWedge(wedge) + assert.Equal(t, 1, f.signalCalls) + }) + + t.Run("enumeration failure still touched the flag", func(t *testing.T) { + f := wedgeFakes(t) + f.signalErr = errors.New("cannot read /proc") + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 1} + z.recoverKubeletMountWedge(wedge) + assert.Equal(t, 1, f.signalCalls) + assert.FileExists(t, f.flagPath) + }) + + t.Run("no k3s process found", func(t *testing.T) { + f := wedgeFakes(t) + f.signalPids = nil + z := &zedkube{nodeName: testNodeName, stuckMountRecoverCount: 1} + z.recoverKubeletMountWedge(wedge) + assert.Equal(t, 1, f.signalCalls) + assert.FileExists(t, f.flagPath) + }) +} diff --git a/pkg/pillar/cmd/zedkube/zedkube.go b/pkg/pillar/cmd/zedkube/zedkube.go index 3ce3fff09e2..419a7e2d85e 100644 --- a/pkg/pillar/cmd/zedkube/zedkube.go +++ b/pkg/pillar/cmd/zedkube/zedkube.go @@ -151,6 +151,12 @@ type zedkube struct { // window is live, preventing a false-positive delete of a new VMI that is // legitimately Pending during failover start-up. vmiFailoverSuppressUntil map[string]time.Time + // Stuck-volume-mount detector state (node-scoped). stuckMountRecoverCount + // counts recovery attempts within the current wedge episode (reset when a + // tick observes no wedged pod); stuckMountSuppressUntil is the cooldown + // after an attempt so the detector cannot thrash a kubelet restart. + stuckMountRecoverCount int + stuckMountSuppressUntil time.Time // lbConfigError is set by resolveLBInterfaces when an LB CIDR from the // controller overlaps with a management port IP. When set, the offending // entry is omitted from EdgeNodeClusterStatus.LBInterfaces and the error @@ -734,6 +740,7 @@ func Run(ps *pubsub.PubSub, loggerArg *logrus.Logger, logArg *base.LogObject, ar case <-appStatusTimer.C: zedkubeCtx.checkAppsFailover(zedkubeWdUpdate) zedkubeCtx.checkStuckPendingVMI() + zedkubeCtx.checkStuckVolumeMount() zedkubeWdUpdate() zedkubeCtx.checkAppsStatus() zedkubeCtx.reconcileVMIRSAffinity(zedkubeWdUpdate)