Repository: kubernetes
Issue: Pod Stuck In Terminating State After Kublet Restart
Labels: kind/bug,sig/storage,lifecycle/rotten,needs-triage

### What happened?

A node in our GKE cluster was experiencing an extremely heavy load during load testing.

CNI pods (calico) and CSI pods crashed several times as well as the kubelet and caused the following.

```
INFO 2024-07-23T02:33:56.075736Z "Updating ready status of pod to false" pod="performance-citus/mirror-citus-shard0-0"
WARNING 2024-07-23T02:33:56Z Node is not ready
INFO 2024-07-23T02:39:01Z Marking for deletion Pod performance-citus/mirror-citus-shard0-0
DEFAULT 2024-07-23T02:33:56.178205Z audit_log, method: "io.k8s.discovery.v1.endpointslices.update", principal_email: "system:serviceaccount:kube-system:endpointslice-controller"
DEFAULT 2024-07-23T02:33:56.177543Z audit_log, method: "io.k8s.core.v1.endpoints.update", principal_email: "system:serviceaccount:kube-system:endpoint-controller"
INFO 2024-07-23T02:33:56.165537Z "Event occurred" object="performance-citus/mirror-citus-shard0-0" fieldPath="" kind="Pod" apiVersion="v1" type="Warning" reason="NodeNotReady" message="Node is not ready"
```

While the kublet was down, I believe a 3rd party operator(stackgres - which manages mirror-citus-shard0-0) attempted to delete the pod
```
INFO 2024-07-23T02:39:01.404541Z "HTTP" verb="DELETE" URI="/api/v1/namespaces/performance-citus/pods/mirror-citus-shard0-0" latency="23.911565ms" userAgent="kube-controller-manager/v1.29.6 (linux/amd64) kubernetes/7466e0b/system:serviceaccount:kube-system:node-controller" audit-ID="48eb34a8-c904-452c-9d24-e265c5b9b555" srcIP="172.16.0.4:44026" apf_pl="workload-high" apf_fs="kube-system-service-accounts" apf_iseats=1 apf_fseats=2 apf_additionalLatency="5ms" apf_execution_time="21.683835ms" resp=200
```

The kublet started back up
```
DEFAULT 2024-07-23T02:40:46.695093Z I0723 02:40:46.695068 1907 server.go:1256] "Started kubelet"
```

And then got the following events:
```
DEFAULT 2024-07-23T02:41:29.716685Z I0723 02:41:29.716630 1907 util.go:48] "No ready sandbox for pod can be found. Need to start a new one" pod="performance-citus/mirror-citus-shard0-0"
DEFAULT 2024-07-23T02:41:29.827338Z I0723 02:41:29.827304 1907 kubelet.go:2431] "SyncLoop DELETE" source="api" pods=["performance-citus/mirror-citus-shard0-0"]
INFO 2024-07-23T02:41:29.974546Z "Delete event for scheduled pod" pod="performance-citus/mirror-citus-shard0-0"
INFO 2024-07-23T02:41:29.973757Z "Delete event for scheduled pod" pod="performance-citus/mirror-citus-shard0-0"
INFO 2024-07-23T02:41:29.971246Z "Delete event for scheduled pod" pod="performance-citus/mirror-citus-shard0-0"
INFO 2024-07-23T02:41:33.490122527Z [background-id:f866480ddd35e7aa pod:performance-citus/mirror-citus-shard0-0] Pod not found
```

Also at this time, the csi driver (openebs zfs local pv) pod also restarted
```
DEFAULT 2024-07-23T02:40:59.843466Z I0723 02:40:59.843471 1907 kubelet.go:2447] "SyncLoop (PLEG): event for pod" pod="common/mirror-zfs-localpv-node-nlcwh" event={"ID":"565886d5-330a-4315-ab51-e4090e4faa81","Type":"ContainerDied","Data":"963386a20eb25eb4d10c9a35b20569b11c90d9da8902707a1b4dfaf4353964da"}
DEFAULT 2024-07-23T02:41:00.849481Z I0723 02:41:00.849355 1907 kubelet.go:2447] "SyncLoop (PLEG): event for pod" pod="common/mirror-zfs-localpv-node-nlcwh" event={"ID":"565886d5-330a-4315-ab51-e4090e4faa81","Type":"ContainerStarted","Data":"0bd24b519c769d49741aa3aa47946c26b3d75c5b536a9ec39a892aa16b0cba29"}
```

After the driver started, it attempted  to publish the node volume.
```
INFO 2024-07-23T02:41:20.552995067Z GRPC call: /csi.v1.Node/NodePublishVolume requests {"target_path":"/var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/mount","volume_capability":{"AccessType":{"Mount":{"fs_type":"zfs"}},"access_mode":{"mode":1}},"volume_context":{"openebs.io/cas-type":"localpv-zfs","openebs.io/poolname":"zfspv-pool","storage.kubernetes.io/csiProvisionerIdentity":"1711133401917-1665-zfs.csi.openebs.io"},"volume_id":"pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c"}
ERROR 2024-07-23T02:41:20.565802524Z GRPC error: rpc error: code = Internal desc = zfs get mountpoint failed, cannot open 'zfspv-pool/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c': dataset does not exist
ERROR 2024-07-23T02:41:20.565768826Z zfs: could not get mountpoint on dataset zfspv-pool/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c cmd [get -pH -o value mountpoint zfspv-pool/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c] error: cannot open 'zfspv-pool/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c': dataset does not exist
```

This publish failed but the kubelet logged a successful mount:
```
DEFAULT 2024-07-23T02:41:20.549581Z I0723 02:41:20.549480 1907 operation_generator.go:664] "MountVolume.MountDevice succeeded for volume \"pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\" (UniqueName: \"kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\") pod \"mirror-citus-shard0-0\" (UID: \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\") device mount path \"/var/lib/kubelet/plugins/kubernetes.io/csi/zfs.csi.openebs.io/ba33a2244c475d064d33ba6b1934dd720ee89fd2e931120ee8ee6af1e612d16d/globalmount\"" pod="performance-citus/mirror-citus-shard0-0"
```

A few milliseconds later I see this from the kubet logs
```
DEFAULT 2024-07-23T02:41:20.566467Z E0723 02:41:20.566432 1907 nestedpendingoperations.go:348] Operation for "{volumeName:kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c podName: nodeName:}" failed. No retries permitted until 2024-07-23 02:41:52.566409131 +0000 UTC m=+65.995713484 (durationBeforeRetry 32s). Error: MountVolume.SetUp failed for volume "pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c" (UniqueName: "kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c") pod "mirror-citus-shard0-0" (UID: "f3e6dda8-df2a-464a-9b77-f72225bcbd52") : rpc error: code = Internal desc = zfs get mountpoint failed, cannot open 'zfspv-pool/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c': dataset does not exist
```

The zfs csi driver had not yet synced the dataset but did so here
```
INFO 2024-07-23T02:42:22.346842379Z Successfully synced 'common/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c'
```

However, the mount request has already happened and also the pod was attempted to be deleted above and stuck because the volume couldn't unmount. This log has been flooding logs ever since
```
E0723 02:41:30.012618    1907 reconciler_common.go:169] "operationExecutor.UnmountVolume failed (controllerAttachDetachEnabled true) for volume \"pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\" (UniqueName: \"kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\") pod \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\" (UID: \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\") : UnmountVolume.NewUnmounter failed for volume \"pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\" (UniqueName: \"kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\") pod \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\" (UID: \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\") : kubernetes.io/csi: unmounter failed to load volume data file [/var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/mount]: kubernetes.io/csi: failed to open volume data file [/var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/vol_data.json]: open /var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/vol_data.json: no such file or directory" err="UnmountVolume.NewUnmounter failed for volume \"pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\" (UniqueName: \"kubernetes.io/csi/zfs.csi.openebs.io^pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c\") pod \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\" (UID: \"f3e6dda8-df2a-464a-9b77-f72225bcbd52\") : kubernetes.io/csi: unmounter failed to load volume data file [/var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/mount]: kubernetes.io/csi: failed to open volume data file [/var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/vol_data.json]: open /var/lib/kubelet/pods/f3e6dda8-df2a-464a-9b77-f72225bcbd52/volumes/kubernetes.io~csi/pvc-09c95a39-cf08-4035-9f2e-2bef87ec738c/vol_data.json: no such file or directory"
```


### What did you expect to happen?

The volume to be unmounted or if not present/already unmounted, the failed unmount that will never succeed (due to the missing file) should not block the pod from terminating

### How can we reproduce it (as minimally and precisely as possible)?

Don't really have steps to reproduce

### Anything else we need to know?

_No response_

### Kubernetes version

<details>

```console
Client Version: v1.29.2
Kustomize Version: v5.0.4-0.20230601165947-6ce0bf390ce3
Server Version: v1.29.6-gke.1038001
```

</details>


### Cloud provider

<details>
GKE
</details>


### OS version

<details>

```console
PRETTY_NAME="Ubuntu 22.04.4 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04.4 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy
```

</details>


### Install tools

<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>
containerd github.com/containerd/containerd 1.7.13-0ubuntu0~22.04.1~gke1
</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>
calico, openebs zfs local-pv
</details>