Intermittent MountVolume.MountDevice errors on Pod creation

[zarbis]

I've set up Rancher 2.0 cluster on DO to test CSI-DO. At first attempt i followed README.md and succeeded with example app. However after trying to do my own stuff I've started consistently getting Pod creation errors. To rule out the unknowns I've wiped all my stuff and returned back to example app and confirmed that i'm consistently getting this result:

Events:
  Type     Reason                  Age                From                     Message
  ----     ------                  ----               ----                     -------
  Warning  FailedScheduling        21s (x4 over 22s)  default-scheduler        pod has unbound PersistentVolumeClaims
  Normal   Scheduled               19s                default-scheduler        Successfully assigned my-csi-app to node-1
  Normal   SuccessfulMountVolume   19s                kubelet, node-1          MountVolume.SetUp succeeded for volume "default-token-jw8hg"
  Normal   SuccessfulAttachVolume  15s                attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-4b1897fb-5f66-11e8-8f45-c2743f7bbff2"
  Warning  FailedMount             5s (x4 over 10s)   kubelet, node-1          MountVolume.MountDevice failed for volume "pvc-4b1897fb-5f66-11e8-8f45-c2743f7bbff2" : rpc error: code = Internal desc = formatting disk failed: exit status 1 cmd: 'mkfs.ext4 -F /dev/disk/by-id/scsi-0DO_Volume_pvc-4b1897fb-5f66-11e8-8f45-c2743f7bbff2' output: "mke2fs 1.43.7 (16-Oct-2017)\nThe file /dev/disk/by-id/scsi-0DO_Volume_pvc-4b1897fb-5f66-11e8-8f45-c2743f7bbff2 does not exist and no size was specified.\n"

However just after waiting for couple hours problem is gone. I wonder if it was Block Storage degradation I've just happened to witness or this is something related to CSI-DO. Unfortunatelly I've wiped out that cluster and after setting up new one example app deploys just fine. I will provide additional info you might need if I witness this problem again.

[zarbis]

I've experienced this problem again and here are my observations:

1. It never happens on fresh cluster with fresh nodes but starts happening after a while. Re-creating cluster with fresh nodes solves problem for a while.
2. /dev/disk/by-id/scsi-0DO_Volume_pvc-* is present on a droplet when this error occurs. I've tried to run mkfs command manually and result was either the same as in error message or something along those lines:ext4 fs is already present and drive is currently used by a system, but effectively Pod was in Failed state.

So there is some sort of deterioration over time somewhere in a system.
If you can provide me with debug steps to perform when I reproduce problem again - I will share the results I can gather.

[zarbis]

One more observation: some sort of ID mismatch happens when this issue arises.
This problem happened to me again, Pod has such event:
Warning FailedMount 7s (x5 over 17s) kubelet, node-1 MountVolume.MountDevice failed for volume "pvc-910ee89c-60fc-11e8-ac9b-a22ee19381a6" ...<same mkfs error here>

First I take a look at what k8s has to say about that PVC:

$ kubectl get pv
NAME                                       CAPACITY   ACCESS MODES   RECLAIM POLICY   STATUS    CLAIM                            STORAGECLASS       REASON    AGE
pvc-910ee89c-60fc-11e8-ac9b-a22ee19381a6   2Gi        RWO            Delete           Bound     jenkins/jenkins-home-jenkins-0   do-block-storage             3m

Looks good, then I confirm that block storage is attached to node-1:

Then I ssh into the node and look around:

root@node-1:~# ls /dev/disk/by-id/scsi-0DO_Volume_pvc-910ee89c-60fc-11e8-ac9b-a22ee19381a6
ls: cannot access '/dev/disk/by-id/scsi-0DO_Volume_pvc-910ee89c-60fc-11e8-ac9b-a22ee19381a6': No such file or directory

Block device is absent indeed, or is it?

root@node-1:~# ls /dev/disk/by-id/
scsi-0DO_Volume_pvc-1996973e-60c8-11e8-ac9b-a22ee19381a6

So what's happening here?
PV ID referred everywhere:
pvc-910ee89c-60fc-11e8-ac9b-a22ee19381a6
Block device actually mounted into the node:
pvc-1996973e-60c8-11e8-ac9b-a22ee19381a6

At some moment PV ID and block device ID are getting mismatched. Not sure what exact condition causes it, but this is a point of no return: i was not able to create any more PVs even if I remove faulty PVs/PVCs, only full cluster teardown and reassembly helps.

Will provide more details as I encounter it more in my testing.

Update: After removing PV mislabeled block device stays on node until reboot, however DO dashboard show no Volumes. Rebooting nodes "fixes" them so cluster reassembly is no longer needed.

[zarbis]

Small update to my observations:

1. at some point block device with wrong ID appears on node in /dev/disk/by-id/
2. Pod creation fails with mkfs "The file <...> does not exist" error
3. After this point node becomes "corrupted":

• if you remove PV, DO Volume gets detached but this faulty block device stays on node
• if you create new PV that lands on this node new DO Volume gets attached but it doesn't show up in /dev/disk/by-id/ until reboot
• after reboot new block device shows up, but Pod creation fails with:

MountVolume.MountDevice failed for volume "<PVC_ID>" : 
rpc error: code = Internal desc = mounting failed: exit status 255 cmd: 
'mount -t ext4 /dev/disk/by-id/scsi-0DO_Volume_<PVC_ID> /var/lib/kubelet/plugins/kubernetes.io/csi/pv/<PVC_ID>/globalmount' 
output: "mount: mounting /dev/disk/by-id/scsi-0DO_Volume_<PVC_ID> on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/<PVC_ID>/globalmount failed: No error information\n"

4. after removing PV node is functional again

Pinging @fatih i guess?

[fatih]

@zarbis thanks for all the report. I know how frustrating this can be, so thanks for providing all this information. It seems like the plugin might fail to attach the volumes to the droplets. There was an issue which was fixed here: #34

This is released on May 29: https://github.com/digitalocean/csi-digitalocean/blob/master/CHANGELOG.md#v011-alpha---may-29th-2018 So I definitely recommend to upgrade to v0.1.1. I think it might be due this issue.

I'm on this and try to fix things when I can reproduce it myself as well. As always please keep posting whatever you find.

[lohazo]

Still got same error in 0.1.3

[fatih]

@lohazo this is a completely different error. Can you please open a new issue with your Kubernetes version and the steps you did seeing this. Thanks

[fatih]

@lohazo also please provide these information:

kubectl logs -l app=csi-provisioner-doplugin -c digitalocean-csi-plugin -n kube-system
kubectl logs -l app=csi-attacher-doplugin -c digitalocean-csi-plugin -n kube-system
kubectl logs -l app=csi-doplugin -c csi-doplugin -n kube-system
kubectl get pods -n kube-system

[lohazo]

I created new issue #54 can you take a look @fatih

[davidhiendl]

I can confirm the original issue, funny enough I can reliably reproduce it by mounting multiple DO volumes in a single pod simultaneously. Mounting other volumes like CephFS/RBD/HostPath alongside does not seem to cause the issue. I first noticed this while migrating/restoring data from an other cluster.

Event Log:

Events:
  Type     Reason                  Age              From                      Message
  ----     ------                  ----             ----                      -------
  Normal   Scheduled               14s              default-scheduler         Successfully assigned transfer-pod to k8s-xi-worker-1
  Normal   SuccessfulMountVolume   14s              kubelet, k8s-xi-worker-1  MountVolume.SetUp succeeded for volume "hostfs"
  Normal   SuccessfulMountVolume   14s              kubelet, k8s-xi-worker-1  MountVolume.SetUp succeeded for volume "default-token-jcjzs"
  Normal   SuccessfulAttachVolume  13s              attachdetach-controller   AttachVolume.Attach succeeded for volume "pvc-aa090bfa-a4d7-11e8-9fb0-829d8140666b"
  Normal   SuccessfulAttachVolume  10s              attachdetach-controller   AttachVolume.Attach succeeded for volume "pvc-b7303a8d-a4d7-11e8-9fb0-829d8140666b"
  Normal   SuccessfulMountVolume   2s               kubelet, k8s-xi-worker-1  MountVolume.SetUp succeeded for volume "pvc-b7303a8d-a4d7-11e8-9fb0-829d8140666b"
  Warning  FailedMount             1s (x2 over 3s)  kubelet, k8s-xi-worker-1  MountVolume.MountDevice failed for volume "pvc-aa090bfa-a4d7-11e8-9fb0-829d8140666b" : rpc error: code = Internal desc = formatting disk failed: exit status 1 cmd: 'mkfs.ext4 -F /dev/disk/by-id/scsi-0DO_Volume_pvc-aa090bfa-a4d7-11e8-9fb0-829d8140666b' output: "mke2fs 1.43.7 (16-Oct-2017)\nThe file /dev/disk/by-id/scsi-0DO_Volume_pvc-aa090bfa-a4d7-11e8-9fb0-829d8140666b does not exist and no size was specified.\n"

[thomas]

Experiencing the same issue: https://github.com/confluentinc/cp-helm-charts (just as an example) does not appear to work with the csi plugin largely because it mounts two volumes for the zookeeper instance. The plugin will fail to attach the volume to the node, and manually attaching does not correct the issue.

Update: In the above-mentioned chart I used the old driver (https://github.com/kubernetes-incubator/external-storage/tree/master/digitalocean) in conjunction with this current CSI driver (one volume on csi, the other on the old driver) on the same pod to get around this issue. The pod started, at least, and appears to be working.

[fatih]

Thanks for the reports. I'm not sure if you're all seeing the same issue. As my understanding, the issue happens when two volumes are mounted to the same pod. I'm now going to try to reproduce this. I'll add more information. Meanwhile, please try to share always the example manifest (pvc's, deployments, etc..) so I can use them on my test cluster to reproduce. I'll add a CONTRIBUTING.md file so people are aware of it.

[fatih]

I tried the following setup, where a pod is referring to two volumes. They will be mounted to two different mount paths:

pod.yaml:

kind: Pod
apiVersion: v1
metadata:
  name: my-csi-app
spec:
  containers:
    - name: my-frontend
      image: busybox
      volumeMounts:
      - mountPath: "/data1"
        name: my-do-volume-1
      - mountPath: "/data2"
        name: my-do-volume-2
      command: [ "sleep", "1000000" ]
  volumes:
    - name: my-do-volume-1
      persistentVolumeClaim:
        claimName: csi-pvc-1
    - name: my-do-volume-2
      persistentVolumeClaim:
        claimName: csi-pvc-2

pvc-multiple.yaml:

---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: csi-pvc-1
spec:
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 5Gi
  storageClassName: do-block-storage
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: csi-pvc-2
spec:
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 5Gi
  storageClassName: do-block-storage

This is the events I see when do a kubectl describe pods my-csi-app:

Events:
  Type    Reason                  Age   From                     Message
  ----    ------                  ----  ----                     -------
  Normal  Scheduled               20s   default-scheduler        Successfully assigned my-csi-app to worker-6273
  Normal  SuccessfulMountVolume   19s   kubelet, worker-6273     MountVolume.SetUp succeeded for volume "default-token-pmkbp"
  Normal  SuccessfulAttachVolume  17s   attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-b90e9365-a5ee-11e8-b271-aa750cfd6233"
  Normal  SuccessfulAttachVolume  15s   attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-b924a471-a5ee-11e8-b271-aa750cfd6233"
  Normal  SuccessfulMountVolume   15s   kubelet, worker-6273     MountVolume.SetUp succeeded for volume "pvc-b90e9365-a5ee-11e8-b271-aa750cfd6233"
  Normal  SuccessfulMountVolume   11s   kubelet, worker-6273     MountVolume.SetUp succeeded for volume "pvc-b924a471-a5ee-11e8-b271-aa750cfd6233"
  Normal  Pulling                 10s   kubelet, worker-6273     pulling image "busybox"
  Normal  Pulled                  9s    kubelet, worker-6273     Successfully pulled image "busybox"
  Normal  Created                 9s    kubelet, worker-6273     Created container
  Normal  Started                 9s    kubelet, worker-6273     Started container

Everything works fine in this scenario. Gonna try out other kind of setups. Please let me know if the one you're using is similar to this. Also I would appreciate if you could test the setup above and then maybe provide a case that is created from the manifests above so I can also reproduce.

[fatih]

Alright, found a way to make it fail with the following setup:

pod.yaml:

kind: Pod
apiVersion: v1
metadata:
  name: my-csi-app
spec:
  containers:
    - name: my-frontend
      image: busybox
      volumeMounts:
      - mountPath: "/data/foo"
        name: foo
      - mountPath: "/data/bar"
        name: bar
      command: [ "sleep", "1000000" ]
  volumes:
    - name: foo
      persistentVolumeClaim:
        claimName: csi-foo
    - name: bar
      persistentVolumeClaim:
        claimName: csi-bar

pvc.yaml:

---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: csi-foo
spec:
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 5Gi
  storageClassName: do-block-storage
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: csi-bar
spec:
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 5Gi
  storageClassName: do-block-storage

This are the events I see:

Events:
  Type     Reason                  Age               From                     Message
  ----     ------                  ----              ----                     -------
  Warning  FailedScheduling        3m (x6 over 3m)   default-scheduler        persistentvolumeclaim "csi-foo" not found
  Normal   Scheduled               3m                default-scheduler        Successfully assigned my-csi-app to worker-6273
  Normal   SuccessfulMountVolume   3m                kubelet, worker-6273     MountVolume.SetUp succeeded for volume "default-token-pmkbp"
  Normal   SuccessfulAttachVolume  3m                attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-eda4d1a9-a5f0-11e8-b271-aa750cfd6233"
  Normal   SuccessfulAttachVolume  3m                attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-ed8e8d32-a5f0-11e8-b271-aa750cfd6233"
  Normal   SuccessfulMountVolume   3m                kubelet, worker-6273     MountVolume.SetUp succeeded for volume "pvc-ed8e8d32-a5f0-11e8-b271-aa750cfd6233"
  Warning  FailedMount             1m                kubelet, worker-6273     Unable to mount volumes for pod "my-csi-app_default(dcade27c-a5f0-11e8-b271-aa750cfd6233)": timeout expired waiting for volumes to attach or mount for pod "default"/"my-csi-app". list of unmounted volumes=[bar]. list of unattached volumes=[foo bar default-token-pmkbp]
  Warning  FailedMount             52s (x9 over 3m)  kubelet, worker-6273     MountVolume.MountDevice failed for volume "pvc-eda4d1a9-a5f0-11e8-b271-aa750cfd6233" : rpc error: code = Internal desc = formatting disk failed: exit status 1 cmd: 'mkfs.ext4 -F /dev/disk/by-id/scsi-0DO_Volume_pvc-eda4d1a9-a5f0-11e8-b271-aa750cfd6233' output: "mke2fs 1.43.7 (16-Oct-2017)\nThe file /dev/disk/by-id/scsi-0DO_Volume_pvc-eda4d1a9-a5f0-11e8-b271-aa750cfd6233 does not exist and no size was specified.\n"

Seems like, it happens if it's mounted under a sub directory under the same root. Such as /data/foo and /data/bar. It doesn't fail if it's /foo and /bar.

[davidhiendl]

Thanks for following up on this. My setup was with volumes mounted under a common ancestor.
I will test later if mounting without common ancestors (except "/" of course) fixes the issue.
Here is my pod manifest that experiences this issue (pvc and mount names replaced):

apiVersion: v1
kind: Pod
metadata:
  name: transfer-pod
spec:
  nodeSelector:
    kubernetes.io/hostname: k8s-xi-worker-1
  containers:
  - name: transfer-pod
    image: debian
    command: ["sleep", "360000"]
    volumeMounts:
    - name: hostfs
      mountPath: /hostfs
    - name: pv1
      mountPath: /pv/pv1
    - name: pv2
      mountPath: /pv/pv2
    - name: pv3
      mountPath: /pv/pv3
  volumes:
  - name: hostfs
    hostPath:
      path: /
  - name: pv1
    persistentVolumeClaim:
      claimName: pvc1
  - name: pv2
    persistentVolumeClaim:
      claimName: pvc2
  - name: pv3
    persistentVolumeClaim:
      claimName: pvc3

PVCs look similar to this (I have a different name for the the storage class than you because we are using a custom helm chart instead of manually deploying as described in this repo).

apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: pv1
  labels:
    ...
spec:
  storageClassName: digitalocean-blockstorage
  accessModes:
  - ReadWriteOnce
  resources:
    requests:
      storage: 30Gi