Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Race condition / timeout issues when mounting PV (AWS EBS via CSI driver) #76568

Open
frittentheke opened this Issue Apr 14, 2019 · 1 comment

Comments

Projects
None yet
2 participants
@frittentheke
Copy link

frittentheke commented Apr 14, 2019

What happened:
Initially a node was drained of all running pods. One pod was causing trouble at was not starting due to a failed mount. First it was re-scheduled to another node in the same AZ - just as expected. Also the volume was detached from the "old" node and then attached at the one that was intended to run the replacement pod.

The mount of the volume, a 1.5 TB EBS disk with ext4 on it in this case, was reported to be failing though.

At first this error seemed solid, but I could not find a reason - The volume was attached, reported as NVME device and was also mounted at the OS level even while the failed mount was still reported and the pod was pending.

I attempted to re-schedule over and other again to other (new) nodes and even attempted a simple reboot of one instance.

This is the eventlog of the pod:

Normal   Scheduled               8m40s                  default-scheduler                                    Successfully assigned redacted/redacted-75d5c8696f-cj2dq to ip-10-2-10-5.eu-central-1.compute.internal

Normal   SuccessfulAttachVolume  8m38s                  attachdetach-controller                              AttachVolume.Attach succeeded for volume "redacted-data"

Warning  FailedMount             2m5s (x3 over 6m37s)   kubelet, ip-10-2-10-5.eu-central-1.compute.internal  Unable to mount volumes for pod "redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)": timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config redacted-data default-token-jpdmg]

Normal   Pulling                 84s                    kubelet, ip-10-2-10-5.eu-central-1.compute.internal  pulling image "redacted/redacted:1.2.3"

Normal   Pulled                  28s                    kubelet, ip-10-2-10-5.eu-central-1.compute.internal  Successfully pulled image "redacted/redacted:1.2.3"

Normal   Created                 13s                    kubelet, ip-10-2-10-5.eu-central-1.compute.internal  Created container

And also when looking at the Kubelet logs (after rebooting this node) it seems not to be happy:

Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.773555    1951 feature_gate.go:198] Setting GA feature gate CSIPersistentVolume=true. It will be removed in a future release.
Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.773592    1951 feature_gate.go:198] Setting GA feature gate MountPropagation=true. It will be removed in a future release.
Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.774925    1951 feature_gate.go:198] Setting GA feature gate MountPropagation=true. It will be removed in a future release.
Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.774935    1951 feature_gate.go:198] Setting GA feature gate CSIPersistentVolume=true. It will be removed in a future release.
Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.774969    1951 feature_gate.go:198] Setting GA feature gate CSIPersistentVolume=true. It will be removed in a future release.
Apr 11 17:09:51 ip-10-2-10-5 kubelet[1951]: W0411 17:09:51.774973    1951 feature_gate.go:198] Setting GA feature gate MountPropagation=true. It will be removed in a future release.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: W0411 17:09:52.170893    1951 feature_gate.go:198] Setting GA feature gate CSIPersistentVolume=true. It will be removed in a future release.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: W0411 17:09:52.170902    1951 feature_gate.go:198] Setting GA feature gate MountPropagation=true. It will be removed in a future release.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: W0411 17:09:52.170959    1951 feature_gate.go:198] Setting GA feature gate CSIPersistentVolume=true. It will be removed in a future release.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: W0411 17:09:52.170965    1951 feature_gate.go:198] Setting GA feature gate MountPropagation=true. It will be removed in a future release.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: I0411 17:09:52.284180    1951 docker_service.go:256] Docker Info: &{ID:Y3WL:ZII3:TIKD:BH6M:M3VI:XIGW:QB5Y:RHLG:AOD6:PLZP:XPVY:VGDV Containers:0 ContainersRunning:0 ContainersPaused:0 ContainersStopped:0 Images:0 Driver:overlay2 DriverStatus:[[Backing Filesystem extfs] [Supports d_type true] [Native Overlay Diff true]] SystemStatus:[] Plugins:{Volume:[local] Network:[bridge host macvlan null overlay] Authorization:[] Log:[awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog]} MemoryLimit:true SwapLimit:true KernelMemory:true CPUCfsPeriod:true CPUCfsQuota:true CPUShares:true CPUSet:true IPv4Forwarding:true BridgeNfIptables:true BridgeNfIP6tables:true Debug:false NFd:24 OomKillDisable:true NGoroutines:44 SystemTime:2019-04-11T17:09:52.277478146Z LoggingDriver:json-file CgroupDriver:cgroupfs NEventsListener:0 KernelVersion:4.19.25-coreos OperatingSystem:Container Linux by CoreOS 2023.5.0 (Rhyolite) OSType:linux Architecture:x86_64 IndexServerAddress:https://index.docker.io/v1/ RegistryConfig:0xc0000f7030 NCPU:8 MemTotal:33361072128 GenericResources:[] DockerRootDir:/var/lib/docker HTTPProxy: HTTPSProxy: NoProxy: Name:ip-10-2-10-5 Labels:[] ExperimentalBuild:false ServerVersion:18.06.1-ce ClusterStore: ClusterAdvertise: Runtimes:map[runc:{Path:docker-runc Args:[]}] DefaultRuntime:runc Swarm:{NodeID: NodeAddr: LocalNodeState:inactive ControlAvailable:false Error: RemoteManagers:[] Nodes:0 Managers:0 Cluster:<nil>} LiveRestoreEnabled:false Isolation: InitBinary:docker-init ContainerdCommit:{ID:468a545b9edcd5932818eb9de8e72413e616e86e Expected:468a545b9edcd5932818eb9de8e72413e616e86e} RuncCommit:{ID:69663f0bd4b60df09991c08812a60108003fa340 Expected:69663f0bd4b60df09991c08812a60108003fa340} InitCommit:{ID:v0.13.2 Expected:fec3683b971d9c3ef73f284f176672c44b448662} SecurityOptions:[name=seccomp,profile=default name=selinux]}
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: W0411 17:09:52.294232    1951 probe.go:271] Flexvolume plugin directory at /usr/libexec/kubernetes/kubelet-plugins/volume/exec/ does not exist. Recreating.
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: I0411 17:09:52.299246    1951 volume_manager.go:248] Starting Kubelet Volume Manager
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: I0411 17:09:52.385830    1951 kubelet_node_status.go:278] Setting node annotation to enable volume controller attach/detach
Apr 11 17:09:52 ip-10-2-10-5 kubelet[1951]: I0411 17:09:52.399428    1951 kubelet_node_status.go:278] Setting node annotation to enable volume controller attach/detach

[...]

Apr 11 17:10:45 ip-10-2-10-5 kubelet[1951]: I0411 17:10:45.915813    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-config" (UniqueName: "kubernetes.io/configmap/33a24d07-5c7c-11e9-a979-0290a00f82fe-redacted-config") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:45 ip-10-2-10-5 kubelet[1951]: I0411 17:10:45.915853    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-config-common" (UniqueName: "kubernetes.io/configmap/33a24d07-5c7c-11e9-a979-0290a00f82fe-redacted-config-common") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:46 ip-10-2-10-5 kubelet[1951]: I0411 17:10:46.919359    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:46 ip-10-2-10-5 kubelet[1951]: I0411 17:10:46.919416    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-jpdmg" (UniqueName: "kubernetes.io/secret/33a24d07-5c7c-11e9-a979-0290a00f82fe-default-token-jpdmg") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:46 ip-10-2-10-5 kubelet[1951]: E0411 17:10:46.919731    1951 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\"" failed. No retries permitted until 2019-04-11 17:10:47.419709377 +0000 UTC m=+55.690042714 (durationBeforeRetry 500ms). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"redacted-data\" (UniqueName: \"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\") pod \"redacted-75d5c8696f-cj2dq\" (UID: \"33a24d07-5c7c-11e9-a979-0290a00f82fe\") "
Apr 11 17:10:47 ip-10-2-10-5 kubelet[1951]: I0411 17:10:47.421022    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:47 ip-10-2-10-5 kubelet[1951]: E0411 17:10:47.421141    1951 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\"" failed. No retries permitted until 2019-04-11 17:10:48.421115928 +0000 UTC m=+56.691449284 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"redacted-data\" (UniqueName: \"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\") pod \"redacted-75d5c8696f-cj2dq\" (UID: \"33a24d07-5c7c-11e9-a979-0290a00f82fe\") "
Apr 11 17:10:48 ip-10-2-10-5 kubelet[1951]: I0411 17:10:48.423349    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:48 ip-10-2-10-5 kubelet[1951]: E0411 17:10:48.423438    1951 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\"" failed. No retries permitted until 2019-04-11 17:10:50.423415717 +0000 UTC m=+58.693749055 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"redacted-data\" (UniqueName: \"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\") pod \"redacted-75d5c8696f-cj2dq\" (UID: \"33a24d07-5c7c-11e9-a979-0290a00f82fe\") "
Apr 11 17:10:50 ip-10-2-10-5 kubelet[1951]: I0411 17:10:50.427725    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:50 ip-10-2-10-5 kubelet[1951]: E0411 17:10:50.427826    1951 nestedpendingoperations.go:267] Operation for "\"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\"" failed. No retries permitted until 2019-04-11 17:10:54.427802168 +0000 UTC m=+62.698135505 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"redacted-data\" (UniqueName: \"kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5\") pod \"redacted-75d5c8696f-cj2dq\" (UID: \"33a24d07-5c7c-11e9-a979-0290a00f82fe\") "
Apr 11 17:10:54 ip-10-2-10-5 kubelet[1951]: I0411 17:10:54.450602    1951 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe")
Apr 11 17:10:54 ip-10-2-10-5 kubelet[1951]: I0411 17:10:54.454746    1951 operation_generator.go:1196] Controller attach succeeded for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe") device path: "csi-4f1c78e66fb38daa4bb73fc4a178c0ab4cd46a6c4c8f9b829c26f42791708a5f"
Apr 11 17:10:54 ip-10-2-10-5 kubelet[1951]: I0411 17:10:54.551294    1951 operation_generator.go:501] MountVolume.WaitForAttach entering for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe") DevicePath "csi-4f1c78e66fb38daa4bb73fc4a178c0ab4cd46a6c4c8f9b829c26f42791708a5f"
Apr 11 17:10:54 ip-10-2-10-5 kubelet[1951]: I0411 17:10:54.554909    1951 operation_generator.go:510] MountVolume.WaitForAttach succeeded for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe") DevicePath "csi-4f1c78e66fb38daa4bb73fc4a178c0ab4cd46a6c4c8f9b829c26f42791708a5f"
Apr 11 17:10:54 ip-10-2-10-5 kubelet[1951]: I0411 17:10:54.614307    1951 operation_generator.go:531] MountVolume.MountDevice succeeded for volume "redacted-data" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-0047c818def8231e5") pod "redacted-75d5c8696f-cj2dq" (UID: "33a24d07-5c7c-11e9-a979-0290a00f82fe") device mount path "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/redacted-data/globalmount"
Apr 11 17:12:48 ip-10-2-10-5 kubelet[1951]: E0411 17:12:48.896965    1951 kubelet.go:1680] Unable to mount volumes for pod "redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)": timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]; skipping pod
Apr 11 17:12:48 ip-10-2-10-5 kubelet[1951]: E0411 17:12:48.897027    1951 pod_workers.go:190] Error syncing pod 33a24d07-5c7c-11e9-a979-0290a00f82fe ("redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)"), skipping: timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]
Apr 11 17:15:06 ip-10-2-10-5 kubelet[1951]: E0411 17:15:06.299819    1951 kubelet.go:1680] Unable to mount volumes for pod "redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)": timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]; skipping pod
Apr 11 17:15:06 ip-10-2-10-5 kubelet[1951]: E0411 17:15:06.299881    1951 pod_workers.go:190] Error syncing pod 33a24d07-5c7c-11e9-a979-0290a00f82fe ("redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)"), skipping: timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]
Apr 11 17:17:20 ip-10-2-10-5 kubelet[1951]: E0411 17:17:20.301428    1951 kubelet.go:1680] Unable to mount volumes for pod "redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)": timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]; skipping pod
Apr 11 17:17:20 ip-10-2-10-5 kubelet[1951]: E0411 17:17:20.301642    1951 pod_workers.go:190] Error syncing pod 33a24d07-5c7c-11e9-a979-0290a00f82fe ("redacted-75d5c8696f-cj2dq_redacted(33a24d07-5c7c-11e9-a979-0290a00f82fe)"), skipping: timeout expired waiting for volumes to attach or mount for pod "redacted"/"redacted-75d5c8696f-cj2dq". list of unmounted volumes=[redacted-data]. list of unattached volumes=[redacted-config-common redacted-config  redacted-data   default-token-jpdmg]

Finally after man attempts to try and "fix" this by rescheduling we waited a few minuted and all of a sudden the volume was "accepted" as mounted and the pod starts up just fine.

The only line regarding any kernel activity during the time-frame of the other logs I could find was:

[Thu Apr 11 17:10:53 2019] EXT4-fs (nvme1n1): mounted filesystem with ordered data mode. Opts: (null)

What you expected to happen:

I expected to either get a clear error message about a failed mount command or a successfully mounted volume to start a pod.

How to reproduce it (as minimally and precisely as possible):

This seems to be a timing issue or even race condition of some sort. It boils down to a 1.5TB EBS volume, ext4 formatted that is mounted to a directory of a pod.

Anything else we need to know?:

Environment:

  • Kubernetes version (use kubectl version): 1.13.4
  • Cloud provider or hardware configuration: AWS (eu-central-1)
  • OS (e.g: cat /etc/os-release): CoreOS Container Linux 2023.5.0 (Rhyolite)
  • Kernel (e.g. uname -a): 4.19.25-coreos
  • Install tools: kubeadm 1.13.4
  • Others: External Cloud Controller and CSI setup including AWS EBS driver (version 0.3.0)
@frittentheke

This comment has been minimized.

Copy link
Author

frittentheke commented Apr 14, 2019

/sig storage

@k8s-ci-robot k8s-ci-robot added sig/storage and removed needs-sig labels Apr 14, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.