Storage: devicePath is empty while WaitForAttach in StatefulSets

[fntlnz]

Is this a BUG REPORT or FEATURE REQUEST?:

/kind bug

What happened:

I created a StatefulSet with 4 replicas and it worked correctly.
After some time I needed to restart one of the pods and when it came back again it was stuck on this error:

Events:
  Type     Reason       Age               From                                   Message
  ----     ------       ----              ----                                   -------
  Warning  FailedMount  9m (x40 over 1h)  kubelet, ip-180-12-10-58.ec2.internal  Unable to mount volumes for pod "storage-0_twodotoh(51577cea-9ccd-11e8-b024-1232e142048e)": timeout expired waiting for volumes to attach or mount for pod "myorg"/"mypod-0". list of unmounted volumes=[data]. list of unattached volumes=[data mypod-config default-token-cjfqp]
  Warning  FailedMount  3m (x55 over 1h)  kubelet, ip-180-12-10-58.ec2.internal  MountVolume.WaitForAttach failed for volume "pvc-a12b7de1-30ed-11ee-a324-2232d546216c" : WaitForAttach failed for AWS Volume "aws://us-east-1b/vol-045d3gx6hg53gz341": devicePath is empty.

When that happens I can get it working by deleting the pod again, it can happen that the error happens again after that but usually not three times in a row.

The main issue is that if you don't act manually on it it will continue to be reconciled by reconciler.go and will never come back again.

The issue seems to be on actual_state_of_world.go while doing the MarkVolumeAsAttached part, at some point the devicePath string is not written in the object.

actual_state_of_world.go:616 ->
  reconciler.go:238 ->
    operation_executor.go:712 ->
       operation_generator.go:437 -> error on line 496

What you expected to happen:

The pod comes back with no error.

How to reproduce it (as minimally and precisely as possible):
The problem seems to be difficult to reproduce, I can trigger it after the
Upgrading to 1.11 does not solve the problem.
It does not happen on Deployments, I haven't been able to reproduce there.

• Start a Kubernetes cluster on AWS that is configured to use EBS volumes
• Create a statefulset with a dynamic provisioned volume (see yaml file below)
• Delete one of the pods of your choice

At this point one of two things can happen:

• It just works
  OR
• The pod is not able to come back again and give the error I reported above.

I haven't found a reliable way to make one or the other happen when I wanted, it seems to be very random but I'm sure that it only happens when the pod is recreated on the same node.

Statefulset to reproduce

apiVersion: v1
kind: Namespace
metadata:
  name: repro-devicepath
---
apiVersion: apps/v1
kind: StatefulSet
metadata:
  name: myrepro
  namespace: repro-devicepath
  labels:
    component: myrepro
spec:
  serviceName: myrepro
  selector:
    matchLabels:
      component: myrepro
  replicas: 4
  template:
    metadata:
      name: myrepro
      labels:
        component: myrepro
    spec:
      containers:
        - name: myrepro
          image: docker.io/fntlnz/caturday:latest
          volumeMounts:
            - name: data
              mountPath: /data
  volumeClaimTemplates:
  - metadata:
      namespace: repro-devicepath
      name: data
    spec:
      storageClassName: ebs-1
      accessModes:
        - "ReadWriteOnce"
      resources:
        requests:
          storage: 1Gi

Anything else we need to know?:

When this happens, if one looks at devicePath in the node's status it will be reported empty, one can verify that with:

 kubectl get node -o json | jq ".items[].status.volumesAttached" 

I found some other users on slack that have this problem, @wirewc sent me this (note the empty devicePath happening in his system.

 volumesAttached:
 - devicePath: ""
   name: kubernetes.io/iscsi/10.48.147.131:iqn.2016-12.org.gluster-block:b5a96cbd-926b-421f-922b-4df13ca150e0:0
 volumesInUse:
 - kubernetes.io/iscsi/10.48.147.131:iqn.2016-12.org.gluster-block:b5a96cbd-926b-421f-922b-4df13ca150e0:0
 - kubernetes.io/iscsi/pvc-bb8b444f-9a68-11e8-b661-0050569c4ace:pvc-bb8b444f-9a68-11e8-b661-0050569c4ace:0

Also @ntfrnzn detailed a similar issue here: equinixmetal-archive/csi-packet#8

Environment:

• Kubernetes version (use kubectl version):

Client Version: version.Info{Major:"1", Minor:"10", GitVersion:"v1.10.3", GitCommit:"2bba0127d85d5a46ab4b778548be28623b32d0b0", GitTreeState:"clean", BuildDate:"2018-05-21T09:17:39Z", GoVersion:"go1.9.3", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"10", GitVersion:"v1.10.3", GitCommit:"2bba0127d85d5a46ab4b778548be28623b32d0b0", GitTreeState:"clean", BuildDate:"2018-05-21T09:05:37Z", GoVersion:"go1.9.3", Compiler:"gc", Platform:"linux/amd64"}

I'm hitting this on a production cluster on 1.10.3 but I get the same error on a testing cluster that has 1.11

• Cloud provider or hardware configuration: AWS, deployed using kubeadm
• OS (e.g. from /etc/os-release):

NAME="Container Linux by CoreOS"
ID=coreos
VERSION=1800.6.0
VERSION_ID=1800.6.0
BUILD_ID=2018-08-04-0323
PRETTY_NAME="Container Linux by CoreOS 1800.6.0 (Rhyolite)"
ANSI_COLOR="38;5;75"
HOME_URL="https://coreos.com/"
BUG_REPORT_URL="https://issues.coreos.com"
COREOS_BOARD="amd64-usr"

• Kernel (e.g. uname -a): Linux ip-180-12-0-57 4.14.59-coreos-r2 #1 SMP Sat Aug 4 02:49:25 UTC 2018 x86_64 Intel(R) Xeon(R) Platinum 8175M CPU @ 2.50GHz GenuineIntel GNU/Linux
• Install tools:
• Others:

[fntlnz]

/sig storage

[gnufied]

@fntlnz When this happens, what is the status of EBS volume? Is that still attached to the node where you deleted and recreated the pod?

[fntlnz]

@gnufied as far as I can remember the volume is released, I remember this because I was looking at the volumes on the aws console and they were blue (not attached).

[gnufied]

FWIW - devicePath being empty for iSCSI is expected. iSCSI does not perform "real" attach/detach, so naturally there is no devicePath - https://github.com/kubernetes/kubernetes/blob/master/pkg/volume/iscsi/attacher.go#L58

We need to see corresponding entry for EBS when that happens. iSCSI could be a red herring.

[fntlnz]

Oh you’re right @gnufied I’m trying to find a way to reproduce this reliably, will keep this issue posted.

[fntlnz]

@gnufied just happened and noted that when this error occurs the volume is marked as attached on aws as xvdp and it is available with lsblk but empty.

NAME    MAJ:MIN   RM  SIZE RO TYPE  MOUNTPOINT
xvda    202:0      0   50G  0 disk  
|-xvda1 202:1      0  128M  0 part  /boot
|-xvda2 202:2      0    2M  0 part  
|-xvda3 202:3      0    1G  0 part  
|-xvda4 202:4      0    1G  0 part  
| `-usr 254:0      0 1016M  1 crypt /usr
|-xvda6 202:6      0  128M  0 part  /usr/share/oem
|-xvda7 202:7      0   64M  0 part  
`-xvda9 202:9      0 47.7G  0 part  /
xvdbi   202:15360  0 1000G  0 disk  /var/lib/kubelet/pods/xxxxxxxx-91eb-11e8-a727-1232e142048e/volumes/kubernetes.io~aws-ebs/pvc-xxxxxxx-9142-11e8-a727-xxxxxxxxxx
xvdbp   202:17152  0 1000G  0 disk  
xvdca   202:19968  0    5G  0 disk  /var/lib/kubelet/pods/xxxxxxx-6348-11e8-b117-xxxxxxxxxxxe/volumes/kubernetes.io~aws-ebs/pvc-xxxxxxxx-1e08-11e8-b226-xxxxxxxxxxx
xvdcm   202:23040  0   50G  0 disk  /var/lib/kubelet/pods/xxxxxxxx-6348-11e8-b117-xxxxx/volumes/kubernetes.io~aws-ebs/pvc-xxxxxxxx-05e7-11e8-9188-xxxxxxxxx

It is also not listed in any process mountinfo or mounts

The only relevant log I see in the kubelet is:

Aug 15 17:01:30 ip-180-12-20-217 kubelet[856]: I0815 17:01:30.084342     856 reconciler.go:237] Starting operationExecutor.MountVolume for volume "pvc-xxxxxxxxxxx-11e8-a727-xxxxxxxx" (UniqueName: "kubernetes.io/aws-ebs/aws://us-east-1a/vol-xxxxxxxxxxxxx") pod "mypod-2" (UID: "xxxxxx-a0a4-11e8-b024-xxxxxxxx")
Aug 15 17:01:30 ip-xxxxxxxxxx kubelet[856]: I0815 17:01:30.084387     856 volume_host.go:219] using default mounter/exec for kubernetes.io/aws-ebs
Aug 15 17:01:30 ip-xxxxxxxxxx kubelet[856]: I0815 17:01:30.084403     856 volume_host.go:219] using default mounter/exec for kubernetes.io/aws-ebs
Aug 15 17:01:30 ip-xxxxxxxxxx kubelet[856]: I0815 17:01:30.084410     856 volume_host.go:219] using default mounter/exec for kubernetes.io/aws-ebs
A

I'm starting thinking that the problem here is happening because of a dirty unmount rather then a bad mount.

[gnufied]

Can you confirm if unmount is left from previous pod or if unmounted volume is because of new pod (that triggered attach but did not mount) ? One way of confirming that would be - if device name (/dev/xvdbp) changes.

[akshaymankar]

Hi, we're also facing the same issue. We can confirm that the unmount is left from previous pod. The difference in our scenario is that we were trying to upgrade from 1.11.1 to 1.11.2. We initally thought it had something to do with the versions. But here is what our hypothesis is:

When pod gets deleted first time, it leaves the mount behind.
When we restart the kubelet, it sees an extra mount and unmounts it. After the unmount MarkDeviceAsUnmounted gets called. It marks devicePath as empty.

When the scheduler puts back the container on the kubelet, kubelet tries to mount again. But the attachedVolumes map in actualStateOfWorld has the attachedVolume object with empty devicePath. Which causes WaitForAttach to fail.

It makes me wonder why does MarkDeviceAsUnmounted have to set devicePath as empty.

/cc @BenChapman

[fntlnz]

@gnufied the device name remains the same in my case /dev/xvdbp

[ddebroy]

Looks like the kube e2e is also running into this as part of pull-kubernetes-e2e-kops-aws.[sig-storage] Dynamic Provisioning DynamicProvisioner should provision storage with different parameters tests that target EBS provisioning.

https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/pr-logs/pull/67530/pull-kubernetes-e2e-kops-aws/103140/

Aug 24 22:25:51.337: INFO: At 2018-08-24 22:10:49 +0000 UTC - event for pvc-volume-tester-stzb2: {kubelet ip-172-20-55-168.us-west-2.compute.internal} Created: Created container
Aug 24 22:25:51.337: INFO: At 2018-08-24 22:10:50 +0000 UTC - event for pvc-volume-tester-27r57: {default-scheduler } Scheduled: Successfully assigned e2e-tests-volume-provisioning-2qbc4/pvc-volume-tester-27r57 to ip-172-20-55-168.us-west-2.compute.internal
Aug 24 22:25:51.337: INFO: At 2018-08-24 22:10:50 +0000 UTC - event for pvc-volume-tester-27r57: {kubelet ip-172-20-55-168.us-west-2.compute.internal} FailedMount: MountVolume.WaitForAttach failed for volume "pvc-7c7f5f34-a7ea-11e8-99eb-02c590dc6280" : WaitForAttach failed for AWS Volume "aws://us-west-2b/vol-0194c1ef086c2bb42": devicePath is empty.
Aug 24 22:25:51.337: INFO: At 2018-08-24 22:10:51 +0000 UTC - event for pvc-volume-tester-stzb2: {kubelet ip-172-20-55-168.us-west-2.compute.internal} SandboxChanged: Pod sandbox changed, it will be killed and re-created.
Aug 24 22:25:51.337: INFO: At 2018-08-24 22:12:53 +0000 UTC - event for pvc-volume-tester-27r57: {kubelet ip-172-20-55-168.us-west-2.compute.internal} FailedMount: Unable to mount volumes for pod "pvc-volume-tester-27r57_e2e-tests-volume-provisioning-2qbc4(8f49de8c-a7ea-11e8-99eb-02c590dc6280)": timeout expired waiting for volumes to attach or mount for pod "e2e-tests-volume-provisioning-2qbc4"/"pvc-volume-tester-27r57". list of unmounted volumes=[my-volume]. list of unattached volumes=[my-volume default-token-zxnz8]