search

vmware-archive / vsphere-storage-for-docker

vSphere Storage for Docker
https://vmware.github.io/vsphere-storage-for-docker
Apache License 2.0
251 stars 95 forks source link

Cannot mount a vfile volume created specifying the datastore #2086

Open nop00 opened 6 years ago

nop00 commented 6 years ago

Environment: ESX 6.0U3 Docker 17.09.1-ce Host OS: RancherOS 1.3.0

Steps to reproduce: 1./ Create the volume docker volume create --driver=vfile --name=test@datastore2 -o size=1gb 2./ Start a container, mounting the volume docker run --rm -it -v test@datastore2:/mnt/myvol --name busybox-on-node1 busybox

Expected result: Container starts with volume mounted.

Actual result: Get error docker: Error response from daemon: error while mounting volume '/var/lib/docker/plugins/a0e758baa4e3022def1cb2893b8e27876158803a5fd8c2dd68697f60cebf7fc8/rootfs/mnt/vfile/test@datastore2': VolumeDriver.Mount: Timeout reached; BlockingWait is not complete.

I have plenty of space on the server but I tried increasing the timeout anyway (as per https://vmware.github.io/vsphere-storage-for-docker/documentation/vfile-plugin.html#i-got--volumedrivermount-failed-to-blocking-wait-for-mounted-state-error-timeout-reached-blockingwait-is-not-complete-when-mounting-a-volume ), but the error remained.

Note that it does work if I do not specify the datastore.

Relevant logs (from /var/log/vfile/log):

2018-05-18 10:40:49.156175949 +0000 UTC [INFO] Mounting volume name="test@datastore2"
2018-05-18 10:40:49.156287077 +0000 UTC [DEBUG] volume name=test@datastore2 refcnt=1
2018-05-18 10:40:49.156611843 +0000 UTC [DEBUG] Mounts read successfully: data="/dev/sda1 / ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /mnt/vfile ext4 rw,relatime,data=ordered 0 0\nproc /proc proc rw,nosuid,nodev,noexec,relatime 0 0\ntmpfs /dev tmpfs rw,nosuid,size=65536k,mode=755 0 0\ndevpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=666 0 0\nsysfs /sys sysfs ro,nosuid,nodev,noexec,relatime 0 0\ntmpfs /sys/fs/cgroup tmpfs ro,nosuid,nodev,noexec,relatime,mode=755 0 0\nnone /sys/fs/cgroup/hugetlb cgroup ro,nosuid,nodev,noexec,relatime,hugetlb 0 0\nnone /sys/fs/cgroup/cpuset cgroup ro,nosuid,nodev,noexec,relatime,cpuset 0 0\nnone /sys/fs/cgroup/cpu,cpuacct cgroup ro,nosuid,nodev,noexec,relatime,cpu,cpuacct 0 0\nnone /sys/fs/cgroup/blkio cgroup ro,nosuid,nodev,noexec,relatime,blkio 0 0\nnone /sys/fs/cgroup/memory cgroup ro,nosuid,nodev,noexec,relatime,memory 0 0\nnone /sys/fs/cgroup/devices cgroup ro,nosuid,nodev,noexec,relatime,devices 0 0\nnone /sys/fs/cgroup/freezer cgroup ro,nosuid,nodev,noexec,relatime,freezer 0 0\nnone /sys/fs/cgroup/perf_event cgroup ro,nosuid,nodev,noexec,relatime,perf_event 0 0\nnone /sys/fs/cgroup/pids cgroup ro,nosuid,nodev,noexec,relatime,pids 0 0\nnone /sys/fs/cgroup/net_cls,net_prio cgroup ro,nosuid,nodev,noexec,relatime,net_cls,net_prio 0 0\nmqueue /dev/mqueue mqueue rw,nosuid,nodev,noexec,relatime 0 0\nshm /dev/shm tmpfs rw,nosuid,nodev,noexec,relatime 0 0\ndevtmpfs /dev devtmpfs rw,relatime,size=4057716k,nr_inodes=1014429,mode=755 0 0\nnone /dev/pts devpts rw,relatime,mode=600,ptmxmode=000 0 0\nshm /dev/shm tmpfs rw,nosuid,nodev,noexec,relatime,size=65536k 0 0\nmqueue /dev/mqueue mqueue rw,nosuid,nodev,noexec,relatime 0 0\nnone /var/run tmpfs rw,relatime 0 0\nnsfs /var/run/docker/netns/default nsfs rw 0 0\nnsfs /var/run/system-docker/netns/default nsfs rw 0 0\nnsfs /var/run/system-docker/netns/a4fed5352600 nsfs rw 0 0\nnsfs /var/run/docker/netns/ingress_sbox nsfs rw 0 0\nnsfs /var/run/docker/netns/1-tdolbv5io3 nsfs rw 0 0\noverlay /etc overlay rw,relatime,lowerdir=/var/lib/system-docker/overlay2/l/UTG3MDPESQWLIW26YZXTIEV2FA:/var/lib/system-docker/overlay2/l/4UGPMS3IM5BUQQLYQCQ7VRSZA6:/var/lib/system-docker/overlay2/l/4RS64MKJGKCXVSDACLJEGZTDSB:/var/lib/system-docker/overlay2/l/FKHTBKSWLS666Y3DVCP776WC36:/var/lib/system-docker/overlay2/l/QKRFVAFZHP2EMVKXRTSDF5MCMU:/var/lib/system-docker/overlay2/l/YUBF5EP7LPADPOCSVJ7LRSPNKE:/var/lib/system-docker/overlay2/l/A6TZN6VDPTQPA5VZ3OYYKXFZGP:/var/lib/system-docker/overlay2/l/JJC5LKO7FWHHZJPLACXI7KASYR:/var/lib/system-docker/overlay2/l/QN2ZC7D5EX5FUPM4W352BI3IXE:/var/lib/system-docker/overlay2/l/7OQLABPNP6RMY6C6A7GQ73DSH2:/var/lib/system-docker/overlay2/l/2OEVCQZB6HBVIPH4G7YON2UO7K:/var/lib/system-docker/overlay2/l/TNXXJQJDZTTEQ6EYDYSNWDQBQO:/var/lib/system-docker/overlay2/l/5CQSPBUR575F3RWGFAYHW4ADKP:/var/lib/system-docker/overlay2/l/HTGRM4WUTDZPXI6NACEKC73W57,upperdir=/var/lib/system-docker/overlay2/1dedc5080d4b20be903874cf363d9e38123a34b3e762855c3c02c55d9cd210e0/diff,workdir=/var/lib/system-docker/overlay2/1dedc5080d4b20be903874cf363d9e38123a34b3e762855c3c02c55d9cd210e0/work 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/docker ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/logrotate.d ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/selinux ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hostname ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/ssl/certs/ca-certificates.crt.rancher ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /var/log ext4 rw,relatime,data=ordered 0 0\nnone /run/docker/plugins tmpfs rw,relatime 0 0\n/dev/sda1 /etc/hosts ext4 ro,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/hosts ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 ro,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\n/dev/sda1 /etc/resolv.conf ext4 rw,relatime,data=ordered 0 0\nproc /proc/bus proc ro,relatime 0 0\nproc /proc/fs proc ro,relatime 0 0\nproc /proc/irq proc ro,relatime 0 0\nproc /proc/sys proc ro,relatime 0 0\nproc /proc/sysrq-trigger proc ro,relatime 0 0\ndevtmpfs /proc/kcore devtmpfs rw,relatime,size=4057716k,nr_inodes=1014429,mode=755 0 0\ndevtmpfs /proc/timer_list devtmpfs rw,relatime,size=4057716k,nr_inodes=1014429,mode=755 0 0\ndevtmpfs /proc/timer_stats devtmpfs rw,relatime,size=4057716k,nr_inodes=1014429,mode=755 0 0\ndevtmpfs /proc/sched_debug devtmpfs rw,relatime,size=4057716k,nr_inodes=1014429,mode=755 0 0\ntmpfs /proc/scsi tmpfs ro,relatime 0 0\ntmpfs /sys/firmware tmpfs ro,relatime 0 0\n"
2018-05-18 10:40:49.157283767 +0000 UTC [DEBUG] Successfully retrieved mounts: map=map[]
2018-05-18 10:40:49.157388126 +0000 UTC [INFO] Directory doesn't exist, creating it path="/mnt/vfile/test@datastore2/"
2018-05-18 10:40:49.157500534 +0000 UTC [DEBUG] MountVolume: before get lock for global refcount of test@datastore2
2018-05-18 10:40:49.181196871 +0000 UTC [DEBUG] BlockingLockWithLease: key=SVOLS_gref_test@datastore2-lock
2018-05-18 10:40:49.219142166 +0000 UTC [INFO] Service start timeoutvalue=90
2018-05-18 10:40:50.244028686 +0000 UTC [INFO] Locked SVOLS_gref_test@datastore2-lock successfully
2018-05-18 10:40:50.244090041 +0000 UTC [DEBUG] Before AtomicIncr for StartServerTrigger
2018-05-18 10:40:51.27183824 +0000 UTC [DEBUG] CompareAndPut: key=SVOLS_start_trigger_test@datastore2 oldVal=0 newVal=1
2018-05-18 10:40:51.314864361 +0000 UTC [INFO] Watcher on start trigger returns event type=PUT
2018-05-18 10:40:51.314924121 +0000 UTC [DEBUG] Watcher got a increase event on watcher, new value is 1
2018-05-18 10:40:51.314970354 +0000 UTC [DEBUG] CompareAndPutIfNotEqual: key=SVOLS_start_marker_test@datastore2, newVal=1
2018-05-18 10:40:51.314899454 +0000 UTC [DEBUG] BlockingWaitAndGet: key=SVOLS_stat_test@datastore2 value=Mounted newKey=SVOLS_info_test@datastore2
2018-05-18 10:40:51.376928315 +0000 UTC [INFO] Service start timeoutvalue=90
2018-05-18 10:42:31.378662017 +0000 UTC [ERROR] Failed to blocking wait for Mounted state name="test@datastore2" error="Timeout reached; BlockingWait is not complete"
2018-05-18 10:42:31.441966217 +0000 UTC [ERROR] Failed to mount name="test@datastore2" error="Timeout reached; BlockingWait is not complete"
2018-05-18 10:42:31.442025488 +0000 UTC [INFO] Detaching test@datastore2 - it is not used anymore
govint commented 6 years ago

Assigning to Nirdesh to triage and re-assign.