Repository: kubernetes
Issue: Kubelet unable to attach or mount volumes: timed out waiting for the condition
Labels: kind/bug,sig/storage,lifecycle/rotten,needs-triage

### What happened?

On our production bare metal cluster, on some nodes which are running batch jobs, we are observing that pods are taking around 5-6 minutes to start due to attachment/volume timeout even for a simple configmap. The pod manifest which we used for testing this timeout error:

```
apiVersion: v1
kind: Pod
metadata:
  name: pod-volume-mount
spec:
  containers:
  - name: pod-volume-mount
    image: some_image
    command:
      - sleep
      - "3600"
  nodeName: node1
```

This is from the events:

```
Events:
  Type     Reason       Age                    From     Message
  ----     ------       ----                   ----     -------
  Warning  FailedMount  3m43s (x3 over 8m13s)  kubelet  Unable to attach or mount volumes: unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition
  Normal   Pulled       2m51s                  kubelet  Container image "some_image" already present on machine
  Normal   Created      2m44s                  kubelet  Created container pod-volume-mount
  Normal   Started      2m36s                  kubelet  Started container pod-volume-mount
```


This is the volume in question:

```
Volumes:
  kube-api-access-xglfn:
    Type:                    Projected (a volume that contains injected data from multiple sources)
    TokenExpirationSeconds:  3607
    ConfigMapName:           kube-root-ca.crt
    ConfigMapOptional:       <nil>
    DownwardAPI:             true
```

Kubelet logs:

Nov 23 17:13:45 node1 kubelet[3860676]: I1123 17:13:45.649677 3860676 kubelet.go:2053] "SyncLoop ADD" source="api" pods=[default/pod-volume-mount]
Nov 23 17:15:49 node1 kubelet[3860676]: E1123 17:15:49.736874 3860676 kubelet.go:1720] "Unable to attach or mount volumes for pod; skipping pod" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount"
Nov 23 17:15:49 node1 kubelet[3860676]: E1123 17:15:49.736938 3860676 pod_workers.go:949] "Error syncing pod, skipping" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount" podUID=85ddb91b-3f9b-4d42-b592-0886354a110c
Nov 23 17:18:04 node1 kubelet[3860676]: E1123 17:18:04.933901 3860676 kubelet.go:1720] "Unable to attach or mount volumes for pod; skipping pod" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount"
Nov 23 17:18:04 node1 kubelet[3860676]: E1123 17:18:04.933958 3860676 pod_workers.go:949] "Error syncing pod, skipping" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount" podUID=85ddb91b-3f9b-4d42-b592-0886354a110c
Nov 23 17:20:17 node1 kubelet[3860676]: I1123 17:20:17.752931 3860676 reconciler.go:225] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-xglfn\" (UniqueName: \"kubernetes.io/projected/85ddb91b-3f9b-4d42-b592-0886354a110c-kube-api-access-xglfn\") pod \"pod-volume-mount\" (UID: \"85ddb91b-3f9b-4d42-b592-0886354a110c\") "
Nov 23 17:20:17 node1 kubelet[3860676]: I1123 17:20:17.863907 3860676 reconciler.go:266] "operationExecutor.MountVolume started for volume \"kube-api-access-xglfn\" (UniqueName: \"kubernetes.io/projected/85ddb91b-3f9b-4d42-b592-0886354a110c-kube-api-access-xglfn\") pod \"pod-volume-mount\" (UID: \"85ddb91b-3f9b-4d42-b592-0886354a110c\") "
Nov 23 17:20:19 node1 kubelet[3860676]: E1123 17:20:19.122489 3860676 kubelet.go:1720] "Unable to attach or mount volumes for pod; skipping pod" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount"
Nov 23 17:20:19 node1 kubelet[3860676]: E1123 17:20:19.122551 3860676 pod_workers.go:949] "Error syncing pod, skipping" err="unmounted volumes=[kube-api-access-xglfn], unattached volumes=[kube-api-access-xglfn]: timed out waiting for the condition" pod="default/pod-volume-mount" podUID=85ddb91b-3f9b-4d42-b592-0886354a110c
Nov 23 17:20:20 node1 kubelet[3860676]: I1123 17:20:20.567085 3860676 operation_generator.go:714] MountVolume.SetUp succeeded for volume "kube-api-access-xglfn" (UniqueName: "kubernetes.io/projected/85ddb91b-3f9b-4d42-b592-0886354a110c-kube-api-access-xglfn") pod "pod-volume-mount" (UID: "85ddb91b-3f9b-4d42-b592-0886354a110c")
Nov 23 17:20:33 node1 kubelet[3860676]: I1123 17:20:33.501179 3860676 kuberuntime_manager.go:484] "No sandbox for pod can be found. Need to start a new one" pod="default/pod-volume-mount"
Nov 23 17:21:26 node1 kubelet[3860676]: I1123 17:21:26.022399 3860676 kubelet.go:2091] "SyncLoop (PLEG): event for pod" pod="default/pod-volume-mount" event=&{ID:85ddb91b-3f9b-4d42-b592-0886354a110c Type:ContainerStarted Data:ac860d141bb6f4c4725511fa4d0f4d1e3e10bda7b1ac552a3ec67506eb9e6c68}
Nov 23 17:21:42 node1 kubelet[3860676]: I1123 17:21:42.423765 3860676 kubelet.go:2091] "SyncLoop (PLEG): event for pod" pod="default/pod-volume-mount" event=&{ID:85ddb91b-3f9b-4d42-b592-0886354a110c Type:ContainerStarted 
Data:2f3fd21efef32f0b8ddee02dc215707efffee5237ba27845236e917a863a7aae}

Kubelet stack dump:

[kubelet_go.txt](https://github.com/kubernetes/kubernetes/files/10107335/kubelet_go.txt)

PLEG Relist Rates:

<img width="452" alt="image" src="https://user-images.githubusercontent.com/38296600/204376970-62c252a4-8ea7-4bb6-9bb1-57ffbc132769.png">


CRI status: Containerd is working fine without any latency(it does not hang) when using crictl commands

Number of pods running on the node during the timeout: Around 150(with a capacity of 250 pods per node)

Our understanding: If many pods are created and terminated in a short interval of time, relist does not complete within 3 minutes and pod cache does get updated coupled with the fact that the kubelet volume manager has a timeout of 2 minutes and hence the volume timeout error. 

### What did you expect to happen?

We do not expect configmap volumes to time out while mounting.

### How can we reproduce it (as minimally and precisely as possible)?

(Most probably)Nodes with batch jobs where pods are created and terminated in a short interval of time.

### Anything else we need to know?

_No response_

### Kubernetes version

<details>

```console
$ kubectl version
v1.22.8
# paste output here
```

</details>


### Cloud provider

<details>
None. We are using bare metal cluster.
</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
NAME="Ubuntu"
VERSION="20.04.4 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 20.04.4 LTS"
VERSION_ID="20.04"
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"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal
# paste output here
$ uname -a
Linux node1 5.4.0-120-generic #136-Ubuntu SMP Fri Jun 10 13:40:48 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
# paste output here

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here
```

</details>


### Install tools

<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>
Containerd: v1.5.8
</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>
CNI(Calico): Version:  v3.20.3
</details>