Repository: kubernetes
Issue: eviction_manager does not attempt to cleanup unused images before evicting pods (with imagefs)
Labels: kind/bug,area/kubelet,sig/node,triage/needs-information,needs-triage

### What happened?

TL;DR: One of our nodes being out of ephemeral-storage (from imagefs being beyond the hard eviction threshold) led to a pod eviction, but the eviction_manager did not try to reclaim unused images before attempting eviction. This happens shortly after the pod is setup / started by the kubelet.

The metrics for that node (image below) point to imageFs filling up (and not nodefs). 
We also had  `Threshold quantity: 4668496467, available: 4527052Ki` in the eviction event, which match (roughly) `size of our imagefs * imagefs.available threshold` ) ,

What seems surprising is that the kubelet apparently does not attempt to reclaim unused images

If I'm following correctly the code flow here (all the code link are to release-2.29, since it's where I hit this) https://github.com/kubernetes/kubernetes/blob/86e25a07e279516eb13af436ca5706b1806ea604/pkg/kubelet/eviction/eviction_manager.go#L456-L459 and here https://github.com/kubernetes/kubernetes/blob/86e25a07e279516eb13af436ca5706b1806ea604/pkg/kubelet/eviction/helpers.go#L1201-L1210

we should always hit the following code  when hitting signalImageFSAvailable https://github.com/kubernetes/kubernetes/blob/86e25a07e279516eb13af436ca5706b1806ea604/pkg/kubelet/images/image_gc_manager.go#L390-L394 

However, this isn't always the case: see the logs below: in the first one, this does happen as it should, and no eviction occured. In the second one the image GC is not called and eviction happens:

Image GC, no eviction
```
janv. 04 06:11:53 qpk8s-node-033 kubelet[26615]: I0104 06:11:53.500246   26615 util.go:30] "No sandbox for pod can be found. Need to start a new one" pod="REDACTED-dev/cyclades-dev1-job-db-w74bj"
janv. 04 06:11:53 qpk8s-node-033 kubelet[26615]: I0104 06:11:53.867218   26615 kubelet.go:2465] "SyncLoop (PLEG): event for pod" pod="REDACTED-dev/REDACTED-dev1-job-db-w74bj" event={"ID":"9e7
7962a-9ef4-4003-a620-8fc9f99a65de","Type":"ContainerStarted","Data":"fed98b0d4a5008c9d4e3813afb0477c4bec6d81c9ec9ca1c5f359fd00bc08687"}
janv. 04 06:12:08 qpk8s-node-033 kubelet[26615]: I0104 06:12:08.959726   26615 eviction_manager.go:366] "Eviction manager: attempting to reclaim" resourceName="ephemeral-storage"
janv. 04 06:12:08 qpk8s-node-033 kubelet[26615]: I0104 06:12:08.960139   26615 container_gc.go:88] "Attempting to delete unused containers"
janv. 04 06:12:08 qpk8s-node-033 kubelet[26615]: I0104 06:12:08.960699   26615 scope.go:117] "RemoveContainer" containerID="74b79d8dd06301f2c806ba5227797fb93fe38b96dc33caad4803f74d6440f1b8"
janv. 04 06:12:08 qpk8s-node-033 kubelet[26615]: I0104 06:12:08.967179   26615 scope.go:117] "RemoveContainer" containerID="231f370f8d36173c94c9560baee42bf1fe108573ff322a1c4f542233671078db"
janv. 04 06:12:08 qpk8s-node-033 kubelet[26615]: I0104 06:12:08.971757   26615 scope.go:117] "RemoveContainer" containerID="893a23f56984eb2f53dcec21d138ad84a93969dcabf6e72b5a270f8e45351e52"
janv. 04 06:12:09 qpk8s-node-033 kubelet[26615]: I0104 06:12:09.636342   26615 image_gc_manager.go:391] "Attempting to delete unused images"
janv. 04 06:12:09 qpk8s-node-033 kubelet[26615]: I0104 06:12:09.638685   26615 image_gc_manager.go:447] "Removing image to free bytes" imageID="sha256:cc42097299cf96c7b08e31669dddb2af764381fd
d167cfaf25f94f3989a22e6e" size=853261112 runtimeHandler=""
janv. 04 06:12:09 qpk8s-node-033 kubelet[26615]: I0104 06:12:09.853135   26615 image_gc_manager.go:447] "Removing image to free bytes" imageID="sha256:78abc00a071160e2902c30cea3350f7dc1250b67
3410231f989103d22bd4e9cb" size=717064073 runtimeHandler=""
<multiples lines of the above>
janv. 04 06:12:15 qpk8s-node-033 kubelet[26615]: I0104 06:12:15.928391   26615 eviction_manager.go:373] "Eviction manager: able to reduce resource pressure without evicting pods." resourceName="ephemeral-storage"
```

No image GC, eviction 
```
janv. 06 12:43:37 qpk8s-node-033 kubelet[26615]: I0106 12:43:37.138045   26615 util.go:30] "No sandbox for pod can be found. Need to start a new one" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2"
janv. 06 12:43:37 qpk8s-node-033 kubelet[26615]: I0106 12:43:37.682549   26615 kubelet.go:2465] "SyncLoop (PLEG): event for pod" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2" event={"ID":"bad3f101-5920-4a11-9c8a-c0dd40326df2","Type":"ContainerStarted","Data":"934b77ca1f12f514ff7d764f31c77607081e06d50a0bbe2d2937b19b5f523c99"}
janv. 06 12:44:17 qpk8s-node-033 kubelet[26615]: I0106 12:44:17.658612   26615 eviction_manager.go:366] "Eviction manager: attempting to reclaim" resourceName="ephemeral-storage"
janv. 06 12:44:17 qpk8s-node-033 kubelet[26615]: I0106 12:44:17.658831   26615 eviction_manager.go:377] "Eviction manager: must evict pod(s) to reclaim" resourceName="ephemeral-storage"
janv. 06 12:44:17 qpk8s-node-033 kubelet[26615]: I0106 12:44:17.658913   26615 eviction_manager.go:395] "Eviction manager: pods ranked for eviction" pods=["REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2","kube-system/nginx-proxy-qpk8s-node-033","logging/filebeat-filebeat-xvfqd","kube-system/calico-node-rwk5j","prometheus/node-exporter-xfvp8","kured/kured-l2b8t","REDACTED-dev/REDACTED-dev12-grp0-pcorr-56f674d4f-hb6jh","REDACTED-dev/REDACTED-dev4-grp0-pgest-595d778d79-sbkww","kube-system/kube-proxy-kp7gw","kube-system/nodelocaldns-q6mg4"]
janv. 06 12:44:22 qpk8s-node-033 kubelet[26615]: I0106 12:44:22.456507   26615 kubelet_node_status.go:679] "Recording event message for node" node="qpk8s-node-033" event="NodeHasDiskPressure"
janv. 06 12:44:23 qpk8s-node-033 kubelet[26615]: I0106 12:44:23.769177   26615 kubelet.go:2465] "SyncLoop (PLEG): event for pod" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2" event={"ID":"bad3f101-5920-4a11-9c8a-c0dd40326df2","Type":"ContainerStarted","Data":"504dd0177d3f38094dbfbce7bc48e8673e4cc9f97f2b6b6ce2eeda0a20609f54"}
janv. 06 12:44:23 qpk8s-node-033 kubelet[26615]: I0106 12:44:23.769271   26615 kuberuntime_container.go:770] "Killing container with a grace period" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2" podUID="bad3f101-5920-4a11-9c8a-c0dd40326df2" containerName="REDACTED-dev9-pgest" containerID="containerd://504dd0177d3f38094dbfbce7bc48e8673e4cc9f97f2b6b6ce2eeda0a20609f54" gracePeriod=30
janv. 06 12:44:23 qpk8s-node-033 kubelet[26615]: I0106 12:44:23.782222   26615 pod_startup_latency_tracker.go:102] "Observed pod startup duration" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2" podStartSLOduration=1.639754381 podStartE2EDuration="47.782147845s" podCreationTimestamp="2025-01-06 12:43:36 +0100 CET" firstStartedPulling="2025-01-06 12:43:37.409859673 +0100 CET m=+3870058.832937451" lastFinishedPulling="2025-01-06 12:44:23.552253138 +0100 CET m=+3870104.975330915" observedRunningTime="2025-01-06 12:44:23.78166704 +0100 CET m=+3870105.204744839" watchObservedRunningTime="2025-01-06 12:44:23.782147845 +0100 CET m=+3870105.205225634"
janv. 06 12:44:24 qpk8s-node-033 kubelet[26615]: I0106 12:44:24.044767   26615 logs.go:325] "Finished parsing log file" path="/var/log/pods/REDACTED-dev_REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2_bad3f101-5920-4a11-9c8a-c0dd40326df2/REDACTED-dev9-pgest/0.log"
janv. 06 12:44:27 qpk8s-node-033 kubelet[26615]: E0106 12:44:27.659220   26615 eviction_manager.go:614] "Eviction manager: pod failed to evict" err="timeout waiting to kill pod" pod="REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2"
janv. 06 12:44:27 qpk8s-node-033 kubelet[26615]: I0106 12:44:27.659261   26615 eviction_manager.go:205] "Eviction manager: pods evicted, waiting for pod to be cleaned up" pods=["REDACTED-dev/REDACTED-dev9-grp1-pgest-84d9d6ff47-wflf2"]
```

Here is the disk metrics matching those logs (/var/lib/containerd -> imagefs, /var -> nodefs (includes /var/lib/kubelet) ): 

![Image](https://github.com/user-attachments/assets/66cde14a-dd56-4691-9502-0f8c4a22b612)

### What did you expect to happen?

I expected the the image gc to be called in both cases by the eviction manager.

### How can we reproduce it (as minimally and precisely as possible)?

I don't have a reproducer yet. I'll try to find the time to craft one, but can't give guarantee currently.

Possible [ImageGCNoEviction](https://github.com/kubernetes/kubernetes/blob/86e25a07e279516eb13af436ca5706b1806ea604/test/e2e_node/eviction_test.go#L111) might help ? I'm not completely sure how to use this though 🤔 

### Anything else we need to know?

While looking for this in the issues and code, I found the following PR, which might have fixed the problem starting from 1.32:
- #127874 (merged in 1.32)

This led me to formulate the theory that maybe the difference between the two case was a different trigger:
- 1 -> adding container images exceeded the threshold, triggering signalImageFsAvailable which led to correctly gc the unused image
- 2 -> container writing to the containerfs (== not a volume mount) triggered signalContainerFsAvailable which is not handled before the above PR.

I haven't delved enough into that code to know if that theory is plausible, though.

Possibly relevant as well : https://github.com/kubernetes/kubernetes/commit/26923b91e8cbd2d409e5d177ddd509429b76cb35 (split disk kep implementation)

Slack thread : https://kubernetes.slack.com/archives/C0BP8PW9G/p1736523264787059

/sig node
/area kubelet
/cc @AnishShah @kannon92 


### Kubernetes version

<details>

```console
$ kubectl versionClient Version: v1.32.0
Kustomize Version: v5.5.0
Server Version: v1.29.10
```

</details>


### Cloud provider

<details>
On-premise, on a vsphere infra (no cloud controller)
</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
NAME="Red Hat Enterprise Linux"
VERSION="8.10 (Ootpa)"
ID="rhel"
ID_LIKE="fedora"
VERSION_ID="8.10"
PLATFORM_ID="platform:el8"
PRETTY_NAME="Red Hat Enterprise Linux 8.10 (Ootpa)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:8::baseos"
HOME_URL="https://www.redhat.com/"
DOCUMENTATION_URL="https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/8"
BUG_REPORT_URL="https://issues.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 8"
REDHAT_BUGZILLA_PRODUCT_VERSION=8.10
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="8.10"
$ uname -a
Linux <REDACTED> 4.18.0-553.27.1.el8_10.x86_64 #1 SMP Fri Oct 18 06:18:15 EDT 2024 x86_64 x86_64 x86_64 GNU/Linux
```

</details>


### Install tools

<details>
kubespray
</details>


### Container runtime (CRI) and version (if applicable)

<details>
containerd 1.7.22
</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>

</details>