NodeStage might not always be idempotent for nitro instances

[wongma7]

/kind bug

What happened?

E0929 03:30:04.925766       1 mount_linux.go:179] Mount failed: exit status 32
Mounting command: mount
Mounting arguments: -t ext4 -o defaults /dev/xvdba /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-asdf/globalmount
Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-asdf/globalmount: /dev/nvme3n1 already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-asdf/globalmount.

E0929 03:30:04.925829       1 driver.go:119] GRPC error: rpc error: code = Internal desc = could not format "/dev/xvdba" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-asdf/globalmount": mount failed: exit status 32

The logs aren't mine and I am ASSUMING that /dev/xvdba is a symlink to /dev/nvme3n1. But from reading the code I think there is potential for a bug so I will try to reproduce and get my own logs.

The check here

aws-ebs-csi-driver/pkg/driver/node.go

Lines 199 to 202 in c428c04

	// This operation (NodeStageVolume) MUST be idempotent.
	// If the volume corresponding to the volume_id is already staged to the staging_target_path,
	// and is identical to the specified volume_capability the Plugin MUST reply 0 OK.
	if device == source {

seems faulty because on a nitro instance with nvme volumes source returned by findDevicePath might be of the form "/dev/xvdcf" where "/dev/xvdcf" is a symlink to "/dev/nvme1n1". Because findDevicePath naively assumes that if /dev/xvdcf exists then the volume is not nvme:

aws-ebs-csi-driver/pkg/driver/node_linux.go

Line 42 in edb4fbe

// If the path exists, assume it is not nvme device

. But devicePath returned by GetDeviceNameFromMount will be the "canonical" path "/dev/nvme1n1". So since "/dev/xvdcf" != "/dev/nvme1n1" the check will fail.

1. The check should canonicalize (follow symlinks) the devicePaths before comparing them. For reference, in the in-tree driver there is no comparison at all it simply assumes that if something is mounted at the target path then there is nothing to do. https://github.com/kubernetes/kubernetes/blob/c1e69551be1a72f0f8db6778f20658199d3a686d/pkg/volume/awsebs/attacher.go#L212. NodePublish doesn't bother to do comparison either , it has the same assumption as in-tree driver.

   aws-ebs-csi-driver/pkg/driver/node.go

   Line 664 in edb4fbe

   //Checking if the target directory is already mounted with a device.

2. findDevicePath should not naively assume that if /dev/xvdcf exists then the volume is not nvme, it should still try to find the canonical path, then the comparison will be valid. For reference, the in-tree driver returns all devicePaths associated with a given volume ID https://github.com/kubernetes/kubernetes/blob/eebeff9f7e0fccf1d220ce809eaea7f7f9248ce0/pkg/volume/awsebs/aws_util.go#L220 and it doesn't matter which one is the canonical one because as mentioned above, in-tree doesn't use the paths for any comparisons, ultimately it just picks one to call mount with and the canonical path shows up in the mount table.

What you expected to happen? Nodestage should be idempotent

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

WIP... I don't have clear repro steps yet. If I restart kubelet I would expect it to reconstruct actual state of world and not bother to call NodeStage again so I'm not sure how to force it to call NodeStage twice and trigger this bug at the moment.

Anything else we need to know?:

Environment

• Kubernetes version (use kubectl version): 1.20
• Driver version: 1.x

[nirmalaagash]

Similar to issue #1027

[wongma7]

The way to reproduce is to have a pod with an ebs csi volume mounted and restart kubelet. The instance must be nitro and kubelet must be >= 1.20. In 1.19 and below, kubelet checked if the dir is mounted for us before calling NodeStage. In 1.20 it called without checking, assuming our implementation is idempotent. Our implementation is really not due to this nitro-specific bug, so I'll submit a fix to make it more consistent with the newly idempotent NodePublish.

Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.611077   14145 event.go:291] "Event occurred" object="default/nginx-deployment-b8fdc6d6b-c4z7p" kind="Pod" apiVersion="v1" type="Warning" reason="FailedMount" message="MountVolume.MountDevice failed for volume \"pvc-b622b11e-64ad-419f-a229-7372be5314d5\" : rpc error: code = Internal desc = could not format \"/dev/xvdba\" and mount it at \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount\": mount failed: exit status 32\nMounting command: mount\nMounting arguments: -t ext4 -o defaults /dev/xvdba /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount\nOutput: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount: /dev/nvme1n1 already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount.\n"
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: E1007 00:01:05.610768   14145 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/ebs.csi.aws.com^vol-0f71a55a194a009b2 podName: nodeName:}" failed. No retries permitted until 2021-10-07 00:02:09.610734219 +000
lumeName:kubernetes.io/csi/ebs.csi.aws.com^vol-0f71a55a194a009b2 podName: nodeName:}" failed. No retries permitted until 2021-10-07 00:02:09.610734219 +0000 UTC m=+132.586677323 (durationBeforeRetry 1m4s). Error: "MountVolume.MountDevice failed for volume \"pvc-b622b11e-64ad-419f-a229-7372be5314d5\" (UniqueName: \"kubernetes.io/csi/ebs.csi.aws.com^vol-0f71a55a194a009b2\") pod \"nginx-deployment-b8fdc6d6b-c4z7p\" (UID: \"aa9febfe-f8b3-4ccb-84d8-bbef4865c98f\") : rpc error: code = Internal desc = could not format \"/dev/xvdba\" and mount it at \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount\": mount failed: exit status 32\nMounting command: mount\nMounting arguments: -t ext4 -o defaults /dev/xvdba /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount\nOutput: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount: /dev/nvme1n1 already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount.\n"
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.610680   14145 csi_mounter.go:459] kubernetes.io/csi: removing mount path [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: Output: mount: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount: /dev/nvme1n1 already mounted on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount.
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: Mounting arguments: -t ext4 -o defaults /dev/xvdba /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: Mounting command: mount
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: E1007 00:01:05.610661   14145 csi_attacher.go:306] kubernetes.io/csi: attacher.MountDevice failed: rpc error: code = Internal desc = could not format "/dev/xvdba" and mount it at "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount": mount failed: exit status 32
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.607522   14145 shared_informer.go:270] caches populated
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.602987   14145 csi_client.go:513] kubernetes.io/csi: creating new gRPC connection for [unix:///var/lib/kubelet/plugins/ebs.csi.aws.com/csi.sock]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.602977   14145 csi_client.go:359] kubernetes.io/csi: calling NodeStageVolume rpc [volid=vol-0f71a55a194a009b2,staging_target_path=/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.602931   14145 csi_util.go:70] kubernetes.io/csi: volume data file saved successfully [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/vol_data.json]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.602860   14145 csi_util.go:61] kubernetes.io/csi: saving volume data file [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/vol_data.json]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.602840   14145 csi_attacher.go:293] kubernetes.io/csi: created target path successfully [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.597257   14145 shared_informer.go:270] caches populated
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.594236   14145 csi_client.go:513] kubernetes.io/csi: creating new gRPC connection for [unix:///var/lib/kubelet/plugins/ebs.csi.aws.com/csi.sock]
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.594228   14145 csi_client.go:467] kubernetes.io/csi: calling NodeGetCapabilities rpc to determine if NodeSupportsStageUnstage
Oct 07 00:01:05 ip-192-168-29-9.us-west-2.compute.internal kubelet[14145]: I1007 00:01:05.594215   14145 csi_attacher.go:236] kubernetes.io/csi: attacher.MountDevice(csi-f58a686087468b435bcaf58ccfda076ca2150638f72394dcb423dbc41e1e2017, /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-b622b11e-64ad-419f-a229-7372be5314d5/globalmount)

[wongma7]

I reproduced also the stuck terminating part in #1027 (after kubelet has restarted and is printing those already mounted errors, just try deleting the pod)