Kubernetes 1.7.0 local storage teardown failed

[CallMeFoxie]

/kind bug

Tearing down (for example simple updating pods in stateful set) of local-storage PVC seems to be broken:

I0630 10:46:44.480172 24010 reconciler.go:186] operationExecutor.UnmountVolume started for volume "test" (UniqueName: "kubernetes.io/local-volume/97513921-5d70-11e7-a549-180373f4ecc0-test-affinity-test-1") pod "97513921-5d70-11e7-a549-180373f4ecc0" (UID: "97513921-5d70-11e7-a549-180373f4ecc0")
I0630 10:46:44.480243 24010 local.go:271] Unmounting volume "test-affinity-test-1" at path "/www/adm/kubernetes/root/pods/97513921-5d70-11e7-a549-> 180373f4ecc0/volumes/kubernetes.iolocal-volume/test-affinity-test-1"
W0630 10:46:44.480277 24010 util.go:87] Warning: "/www/adm/kubernetes/root/pods/97513921-5d70-11e7-a549-180373f4ecc0/volumes/kubernetes.iolocal-volume/test-affinity-test-1" is not a mountpoint, deleting
E0630 10:46:44.480328 24010 nestedpendingoperations.go:262] Operation for ""kubernetes.io/local-volume/97513921-5d70-11e7-a549-180373f4ecc0-test-affinity-test-1" ("97513921-5d70-11e7-a549-180373f4ecc0")" failed. No retries permitted until 2017-06-30 10:46:48.48030593 +0200 CEST (durationBeforeRetry 4s). Error: UnmountVolume.TearDown failed for volume "test" (UniqueName: "kubernetes.io/local-volume/97513921-5d70-11e7-a549-180373f4ecc0-test-affinity-test-1") pod "97513921-5d70-11e7-a549-180373f4ecc0" (UID: "97513921-5d70-11e7-a549-180373f4ecc0") : remove /www/adm/kubernetes/root/pods/97513921-5d70-11e7-a549-180373f4ecc0/volumes/kubernetes.io~local-volume/test-affinity-test-1: device or resource busy

I've managed to track it down to
pkg/volume/local/local.go calling through some pkg/volume/util/util.go mounter.IsLikelyNotMountPoint(dir)

which literally has written in its comments:

// IsLikelyNotMountPoint determines if a directory is not a mountpoint.
// It is fast but not necessarily ALWAYS correct. If the path is in fact
// a bind mount from one part of a mount to another it will not be detected.
// mkdir /tmp/a /tmp/b; mount --bin /tmp/a /tmp/b; IsLikelyNotMountPoint("/tmp/b")
// will return true. When in fact /tmp/b is a mount point. If this situation
// if of interest to you, don't use this function...

which makes it detect it as a normal directory rather than a mount dir (as it is a normal directory... just bind mounted)

Environment:

• Kubernetes version (use kubectl version): v1.7.0
• Cloud provider or hardware configuration**: self hosted

Testing out a (dirty?) patch as we're speaking

[k8s-github-robot]

@CallMeFoxie There are no sig labels on this issue. Please add a sig label by:
(1) mentioning a sig: @kubernetes/sig-<team-name>-misc
e.g., @kubernetes/sig-api-machinery-* for API Machinery
(2) specifying the label manually: /sig <label>
e.g., /sig scalability for sig/scalability

Note: method (1) will trigger a notification to the team. You can find the team list here and label list here

[CallMeFoxie]

/sig storage

[CallMeFoxie]

Whoops the dirty fix to force umount does not work as it may fail "as it was already unmounted".

Trying out a patch which reads /proc/mounts instead, it seems to be workign much better, can remove/add pods to those PV(C)s without any issue:

diff --git a/pkg/util/mount/mount_linux.go b/pkg/util/mount/mount_linux.go
index 1685ecb..4c007ba 100644
--- a/pkg/util/mount/mount_linux.go
+++ b/pkg/util/mount/mount_linux.go
@@ -180,6 +180,22 @@ func IsNotMountPoint(file string) (bool, error) {
 	if err != nil {
 		return true, err
 	}
+	mountsfd, err := os.Open("/proc/mounts")
+	if err != nil {
+		return true, err
+	}
+
+	scanner := bufio.NewScanner(mountsfd)
+	for scanner.Scan() {
+		line := scanner.Text()
+		parts := strings.Split(line, " ")
+		if len(parts) >= 2 {
+			if strings.Compare(parts[1], file) == 0 {
+				return false, nil
+			}
+		}
+	}
+
 	// If the directory has a different device as parent, then it is a mountpoint.
 	if stat.Sys().(*syscall.Stat_t).Dev != rootStat.Sys().(*syscall.Stat_t).Dev {
 		return false, nil

[ianchakeres]

I experienced this issue while writing some e2e tests - #47999

These tests can be used to reproduce the issue on GCE.

The run-one-command pod tests succeed (e.g. "when one pod requests one prebound PVC), while the pods that are created and deleted independently end up encountering this bug.

For example,
Context("when two pods request one prebound PVC one after other"
Context("when two pods request one prebound PVC at the same time"

@msau42 @jeffvance

[CallMeFoxie]

I am unsure if this fix fixes the GCE issues as well as I've never used GCE (or AWS for that matter) but it seems to fix it for self hosted kubernetes.

Can make it into PR if it's a reasonable fix? Only unsure about the err at opening /proc/mounts - not sure how it behaves on GCE/AWS/within docker.

[ianchakeres]

@CallMeFoxie - Let's reuse listProcMounts(procMountsPath) to get all the info from /proc/mounts.

Yes. Let's get a PR, and I'll test it on GCE.

You want to submit the PR or should I?

[ianchakeres]

Here's the code I'm testing.

	mountPoints, mountPointsErr := listProcMounts(procMountsPath)
        if mountPointsErr == nil {
                for _, mp := range mountPoints {
                        if mp.Path == file {
                                return false, nil
                        }
                }
        }

[msau42]

If I understand correctly, the issue is if the underlying directory is a just a dir and not a mount point, and you bind mount that, then IsLikelyNotMountPoint() will detect it as a directory instead of a mount.

If that's the case, I'm curious why Ian's tests are only running into this problem in the case of two pods accessing the same volume.

[msau42]

For the fix, I would prefer that a new method is used instead of IsLikelyNotMountPoint(). It is being used by other plugins and having to iterate through all the mounts on a node could impact performance. Also it is only the local storage plugin where the underyling directory may not be a mount point.

[ianchakeres]

@msau42 The tests are failing even if I run one pod after the other. I'll create a test that just uses one pod with create and destroy (instead of one-command pod) to see if I can repro the error.

[msau42]

Ok, sounds like this is just a generic issue then with non-mount point local volumes then, which fits in with the root cause.

[msau42]

Btw, I noticed in the common Unmount method, that if it thinks it is not a mount point, then it's going to go and delete all the contents of the directory. This is definitely not the behavior we want because the directory cleanup should only happen when the PV gets released and not during unmount.

So we should definitely get a fix into the next 1.7 patch.

cc @saad-ali

[msau42]

Actually nevermind, the unmount calls os.Remove, not os.RemoveAll, so it's not as bad. Sorry for the scare.

[ianchakeres]

/assign @ianchakeres

[arunmk]

Is there a way to know the release for which this fix is scheduled?

Thanks