CSI volume reconstruction does not work for ephemeral volumes

[jsafrane]

When a pod is marked as deleted while kubelet is down / being restarted, newly started kubelet does not clean up CSI filesystem volumes of the pod.

Newly started kubelet tries to reconstruct the volume using CSI's ConstructVolumeSpec function. This part looks working, CSI volume plugin loads its json file.

But then VolumeManager checks if the volume is still mounted in /var/lib/kubelet/pods/9440e7e5-d454-4555-84b7-d72e43ec4b3a/volumes/kubernetes.io~csi/pvc-45640a32-4ba3-4a7d-ad4b-087281f1460d/mount directory.

There are two issues:

1. CSI does not require volumes to be presented as mounts. They can be just directories with files on them. This will be case of the most of in-line volumes.

2. Even if the CSI driver used mount, kubelet mounts it into /var/lib/kubelet/pods/9440e7e5-d454-4555-84b7-d72e43ec4b3a/volumes/kubernetes.io~csi/pvc-45640a32-4ba3-4a7d-ad4b-087281f1460d/mount. Checking of /var/lib/kubelet/pods/9440e7e5-d454-4555-84b7-d72e43ec4b3a/volumes/kubernetes.io~csi/pvc-45640a32-4ba3-4a7d-ad4b-087281f1460d does not make sense.
   Kubelet checks the right directory given by GetPath()

[jsafrane]

/sig storage

related to #79896

cc @jingxu97 @vladimirvivien @msau42

[jsafrane]

Maybe a stupid idea... Reconciler sync has found a directory in /var/lib/kubelet/pods/<pod UID>/volumes/<plugin name>/<volume name>. Reconciler has no way how to check that CSI volume (or any other volume) is really mounted / published there. Depending on DSW:

• The volume is in DSW -> from comment here it seems that the SetUp (=NodePublish) will be called on the volume:

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go

Lines 398 to 406 in a292437

	if volumeInDSW {
	// Some pod needs the volume. And it exists on disk. Some previous
	// kubelet must have created the directory, therefore it must have
	// reported the volume as in use. Mark the volume as in use also in
	// this new kubelet so reconcile() calls SetUp and re-mounts the
	// volume if it's necessary.
	volumeNeedReport = append(volumeNeedReport, reconstructedVolume.volumeName)
	klog.V(4).Infof("Volume exists in desired state (volume.SpecName %s, pod.UID %s), marking as InUse", volume.volumeSpecName, volume.podName)
	continue

• The volume is not in DSW and it will be added to ASW, so it's unmounted / unpublished in the next sync:

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go

Lines 412 to 415 in a292437

	klog.V(2).Infof(
	"Reconciler sync states: could not find pod information in desired state, update it in actual state: %+v",
	reconstructedVolume)
	volumesNeedUpdate[reconstructedVolume.volumeName] = reconstructedVolume

In both cases, we can expect that the volume plugin / CSI driver is idempotent and SetUp() won't do anything if the volume is already set up / TearDown() will not do anything if the volume has been torn down already.

Are our volume plugins really idempotent? IMO they are. We perhaps don't need to check for presence of mount point anywhere, just presence of directory /var/lib/kubelet/pods/<pod UID>/volumes/<plugin name>/<volume name> should be enough to reconstruct the volume and set it up / tear it down.

Adding @gnufied to the loop.

[jsafrane]

Filed #79980, PTAL

[msau42]

I'm curious how the reconstruction e2e tests passed

[msau42]

https://k8s-testgrid.appspot.com/sig-storage-kubernetes#gce-serial&include-filter-by-regex=CSI.*force

[jsafrane]

I'm curious how the reconstruction e2e tests passed

They start kubelet with a pod already deleted. If the pod still exists, volume reconstruction can see it in DSW and does nothing when reconstructVolume fails:

kubernetes/pkg/kubelet/volumemanager/reconciler/reconciler.go

Lines 385 to 391 in 978c38d

	reconstructedVolume, err := rc.reconstructVolume(volume)
	if err != nil {
	if volumeInDSW {
	// Some pod needs the volume, don't clean it up and hope that
	// reconcile() calls SetUp and reconstructs the volume in ASW.
	klog.V(4).Infof("Volume exists in desired state (volume.SpecName %s, pod.UID %s), skip cleaning up mounts", volume.volumeSpecName, volume.podName)
	continue

[Reconstruction fails because it checks for a mount in a wrong directory.]

In this case, kubelet waits for the volume to appear in VolumesInUse before calling SetUp(). The pod is deleted before that and kubelet then just deletes DSW entry and the volume is never cleaned up.

[jsafrane]

I'm curious how the reconstruction e2e tests passed

They pass because their container does not handle SIGTERM and it takes 30 seconds to kill them. Kubelet has enough time to SetUp the volume during reconciliation.

[jsafrane]

It turns out that I tested with broken version of #80743 and reconstruction is broken only for ephemeral volumes that don't mount.

[jingxu97]

So the conclusion is that we only need to fix for ephemeral volumes? Thanks!

…

On Tue, Jul 30, 2019 at 3:27 AM Jan Šafránek ***@***.***> wrote: It turns out that I tested with broken version of #80743 <#80743> and reconstruction is broken only for ephemeral volumes that don't mount. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#79980?email_source=notifications&email_token=AESI3ROIV2SK6SNZWU4EFFTQCAJSBA5CNFSM4H7OA642YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD3DQYAQ#issuecomment-516361218>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AESI3RIJYBLS5F3WOVSEBE3QCAJSBANCNFSM4H7OA64Q> .

-- - Jing

[jsafrane]

Yes, sorry again about the noise.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[msau42]

/remove-lifecycle stale
cc @pohly

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten

[pohly]

/remove-lifecycle rotten

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[pohly]

/remove-lifecycle rotten

[pohly]

/lifecycle frozen

[verult]

From #103651: this issue surfaced through e2e tests using the hostPath CSI driver. The cause is IsLikelyNotMountPoint() (which is used in CheckVolumeExistenceOperation() for reconstruction) - it doesn't play well with volumes that bind mount from a directory instead of a device.

[pohly]

To work around this bug here, volume life cycle checking was disabled for all tests, not just the subpath test:
f1e1f3a#r56140970

This check is useful and should be enabled again.

[dbgoytia]

Hey everyone! I arrived at this conversation by investigating on issue #105242 (seems to me like a duplicate of #103651). I'm wondering if there's something I can help with? I'm still a bit new to the codebase, though.

I was able to reproduce the problem by using the following ginkgo focus command in the e2e framework:

./hack/ginkgo-e2e.sh --provider=gce --ginkgo.focus="CSI.Volumes.*csi-hostpath*.*Dynamic.PV.*default.fs.*should.unmount.if.pod.is.force.deleted.while.kubelet.is.down" --storage.testdriver=/home/build/oss/refactor/test-linux.yaml

And do see that if we manually add the --check-volume-lifecycle=false to the statefulset/csi-hostpathplugin tests will pass correctly.

{"msg":"PASSED [sig-storage] CSI Volumes [Driver: csi-hostpath] [Testpattern: Dynamic PV (default fs)] subPath should unmount if pod is force deleted while kubelet is down [Disruptive][Slow][LinuxOnly]","total":1,"completed":1,"skipped":6322,"failed":0}

I also see that during the process, something in the cleanup function doesn't correctly delete the pv's after the tests are done, so they remain alive if we execute a kubectl get pv command.

[dbgoytia]

I think I found a bit of more info on the issue @jsafrane, probably could be of some help. I think that the volume is not being correclty marked as unmounted inside operation_generator.go in GenerateUnmountVolumeFunc. I'm not sure why but I'll continue to investigate on it.

journalctl -u kubelet| grep 'UnmountVolume.TearDown succeeded for volume "pvc-cfed9346-6b91-4a2a-9fdd-67f81' -A10
Oct 06 18:45:22 e2e-test-build-minion-group-j4tc kubelet[4635]: I1006 18:45:22.616963    4635 operation_generator.go:867] UnmountVolume.TearDown succeeded for volume "pvc-cfed9346-6b91-4a2a-9fdd-67f81
34ec3ea" (OuterVolumeSpecName: "") pod "e438ee68-674a-4ab9-9943-ae63a3fe5a3f" (UID: "e438ee68-674a-4ab9-9943-ae63a3fe5a3f"). InnerVolumeSpecName "pvc-cfed9346-6b91-4a2a-9fdd-67f8134ec3ea". PluginName 
"kubernetes.io/csi", VolumeGidValue ""
Oct 06 18:45:22 e2e-test-build-minion-group-j4tc kubelet[4635]: I1006 18:45:22.616993    4635 operation_generator.go:880] "DEBUG" PodName=e438ee68-674a-4ab9-9943-ae63a3fe5a3f VolumeName=pvc-cfed9346-6
b91-4a2a-9fdd-67f8134ec3ea
Oct 06 18:45:22 e2e-test-build-minion-group-j4tc kubelet[4635]: E1006 18:45:22.617017    4635 operation_generator.go:883] UnmountVolume.MarkVolumeAsUnmounted failed for volume "" (UniqueName: "pvc-cfe
d9346-6b91-4a2a-9fdd-67f8134ec3ea") pod "e438ee68-674a-4ab9-9943-ae63a3fe5a3f" (UID: "e438ee68-674a-4ab9-9943-ae63a3fe5a3f") : no volume with the name "pvc-cfed9346-6b91-4a2a-9fdd-67f8134ec3ea" exists
 in the list of attached volumes

I think this error is coming from DeletePodFromVolume in actual_state_of_the_world.go

[dbgoytia]

I added a couple of extra debug lines to that lines in the actual_state_of_the_world.go file, and can see that when DeletePodFromVolume tries to see if the volume exists, it doesn't find it in the asw.attachedVolumes struct, like so:

func (asw *actualStateOfWorld) DeletePodFromVolume(
	podName volumetypes.UniquePodName, volumeName v1.UniqueVolumeName) error {
	asw.Lock()
	defer asw.Unlock()

	volumeObj, volumeExists := asw.attachedVolumes[volumeName]
	klog.InfoS("DEBUG:", "volumeName", volumeName)
	klog.InfoS("DEBUG:", "volumeObj", volumeObj, "volumeExists", volumeExists, "asw.attachedVolumes", asw.attachedVolumes)
	klog.Info("DEBUG:", "volumeExists",volumeExists)
	if !volumeExists {
		return fmt.Errorf(
			"no volume with the name %q exists in the list of attached volumes",
			volumeName)
	}

	_, podExists := volumeObj.mountedPods[podName]
	if podExists {
		delete(asw.attachedVolumes[volumeName].mountedPods, podName)
	}

	return nil
}

Oct 07 00:04:30 e2e-test-build-minion-group-klvd kubelet[4740]: I1007 00:04:30.677329    4740 actual_state_of_world.go:662] "DEBUG:" volumeName=pvc-295aa817-8cdd-4dac-818a-6c81b79778f5
Oct 07 00:04:30 e2e-test-build-minion-group-klvd kubelet[4740]: I1007 00:04:30.679563    4740 actual_state_of_world.go:663] "DEBUG:" volumeObj={volumeName: mountedPods:map[] spec:<nil> pluginName: pluginIsAttachable:false deviceMountState: devicePath: deviceMountPath: volumeInUseErrorForExpansion:false} volumeExists=false

Probably we should search for the name of the attached volume differently for ephemeral volumes?

[dobsonj]

/assign

[dobsonj]

There are two problems:

1. The IsLikelyNotMountPoint() call that verult already called out, which is known not to work for bind mounts. The mountpoint never gets found, so volume reconstruction fails with "... is not mounted", the PVC never never gets added to the list of attached volumes, and that's why we end up hitting this error:

E0324 22:56:00.476853 2430927 operation_generator.go:856] UnmountVolume.MarkVolumeMountAsUncertain failed for volume "" (UniqueName: "pvc-1787a6c7-ccd3-44a1-b6ad-474da06c5e2b") pod "bf5d71e6-da6a-448a-bab2-f35b2a938d45" (UID: "bf5d71e6-da6a-448a-bab2-f35b2a938d45") : no volume with the name "pvc-1787a6c7-ccd3-44a1-b6ad-474da06c5e2b" exists in the list of attached volumes

2. CSI inline volumes hit a different error (in addition to the first problem).

I0323 22:28:34.117352   76056 reconciler.go:388] "Could not construct volume information, cleaning up mounts" podName=55703bf4-9ee4-4fd5-8f4c-1e20f82391e4 volumeSpecName="my-csi-volume" err="failed to GetVolumeName from volumePlugin for volumeSpec \"my-csi-volume\" err=kubernetes.io/csi: plugin.GetVolumeName failed to extract volume source from spec: unexpected api.CSIVolumeSource found in volume.Spec"

The call path looks like this (starting in reconcile.go):

reconstructVolume > GetUniqueVolumeNameFromSpec > GetVolumeName > getPVSourceFromSpec

Inline volumes do not have a PV spec, so it fails here. We should be calling GetUniqueVolumeNameFromSpecWithPod() instead.

[mkimuram]

1. The IsLikelyNotMountPoint() call that verult already called out, which is known not to work for bind mounts. The mountpoint never gets found, so volume reconstruction fails with "... is not mounted", the PVC never never gets added to the list of attached volumes, and that's why we end up hitting this error:

There is an ongoing work that changes IsNotMountPoint to utilize openat2(2) syscall to detect mount point by using MountedFast. By using openat2(2), bind mount will be properly detected fast, but it requires kernel version is v5.6 or later. So, we would be able to also utilize openat2(2) in IsLikelyNotMountPoint. Then, the issue of bind mount can be resolved at least for kernel v5.6+, and we will be able to focus on how we solve this issue for old kernels.