vShared plugin: volume mount failed due to cannot start service before timeout

[lipingxue]

Steps:

1. create a volume with vShared plugin

root@sc-rdops-vm02-dhcp-52-237:~# docker volume create --driver=vshared --name=vol1
vol1
root@sc-rdops-vm02-dhcp-52-237:~# docker volume inspect vol1
[
    {
        "Driver": "vshared:latest",
        "Labels": {},
        "Mountpoint": "/mnt/vshared/vol1/",
        "Name": "vol1",
        "Options": {},
        "Scope": "global",
        "Status": {
            "Clients": null,
            "File server Port": 0,
            "Global Refcount": 0,
            "Service name": "",
            "Volume Status": "Ready"
        }
    }
]

2. run a container to attach this volume

root@sc-rdops-vm02-dhcp-52-237:~# docker run -it -v vol1:/vol busybox /bin/sh
Unable to find image 'busybox:latest' locally
latest: Pulling from library/busybox
9e87eff13613: Pull complete 
Digest: sha256:2605a2c4875ce5eb27a9f7403263190cd1af31e48a2044d400320548356251c4
Status: Downloaded newer image for busybox:latest
docker: Error response from daemon: error while mounting volume '/mnt/vshared/vol1/': VolumeDriver.Mount: Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete..

root@sc-rdops-vm02-dhcp-52-237:~# docker volume inspect vol1
[
    {
        "Driver": "vshared:latest",
        "Labels": {},
        "Mountpoint": "/mnt/vshared/vol1/",
        "Name": "vol1",
        "Options": {},
        "Scope": "global",
        "Status": {
            "Clients": null,
            "File server Port": 0,
            "Global Refcount": 0,
            "Service name": "",
            "Volume Status": "Error"
        }
    }
]

This is the vsphere_shared.log:

2017-08-16 15:37:34.151414591 -0700 PDT [INFO] VolumeDriver Get: vol1
2017-08-16 15:37:34.183235052 -0700 PDT [INFO] Volume not found: vol1
2017-08-16 15:37:34.184316907 -0700 PDT [ERROR] Failed to get volume meta-data error="No such volume" name=vol1 
2017-08-16 15:37:34.185197406 -0700 PDT [INFO] VolumeDriver Create: vol1
2017-08-16 15:37:34.185492167 -0700 PDT [INFO] Attempting to write initial metadata entry for vol1
2017-08-16 15:37:34.205793526 -0700 PDT [INFO] Watcher on global refcount returns event type=PUT 
2017-08-16 15:37:34.206888201 -0700 PDT [INFO] Attempting to create internal volume for vol1
2017-08-16 15:37:39.513496693 -0700 PDT [INFO] Attempting to update volume state to ready for volume: vol1
2017-08-16 15:37:39.594893479 -0700 PDT [INFO] Successfully created volume: vol1
2017-08-16 15:37:47.723957447 -0700 PDT [INFO] VolumeDriver Get: vol1
2017-08-16 15:38:01.259606622 -0700 PDT [INFO] VolumeDriver Get: vol1
2017-08-16 15:38:01.532861749 -0700 PDT [INFO] Mounting volume name=vol1 
2017-08-16 15:38:01.533706618 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vshared/vol1/" 
2017-08-16 15:38:01.533827245 -0700 PDT [INFO] Before AtomicIncr
2017-08-16 15:38:02.599618816 -0700 PDT [INFO] Watcher on global refcount returns event type=PUT 
2017-08-16 15:38:03.600109932 -0700 PDT [INFO] Attempting to change volume state to Mounting
2017-08-16 15:38:10.304162321 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:10.318087448 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:15.30415672 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:15.308395133 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:20.304441888 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:20.308937468 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:25.30413009 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:25.307482481 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:30.304159117 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:30.307000833 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:35.304201001 -0700 PDT [INFO] Checking status of file server container...
2017-08-16 15:38:35.30726231 -0700 PDT [INFO] File server not running for volume vol1
2017-08-16 15:38:35.307351514 -0700 PDT [WARNING] Timeout reached while waiting for file server container for volume vol1
2017-08-16 15:38:43.715999508 -0700 PDT [INFO] Watcher on global refcount returns event type=PUT 
2017-08-16 15:38:43.716619966 -0700 PDT [ERROR] name=vol1 error="Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete." 
2017-08-16 15:38:43.716865852 -0700 PDT [ERROR] Failed to mount name=vol1 error="Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete." 

docker service takes longer time than expected to start.

root@sc-rdops-vm02-dhcp-52-237:~# docker service ls
ID            NAME            MODE        REPLICAS  IMAGE
zlzxbqm0s728  vol1fileServer  replicated  0/1       dperson/samba:latest
root@sc-rdops-vm02-dhcp-52-237:~# docker service ps vol1fileServer 
ID            NAME                  IMAGE                 NODE                       DESIRED STATE  CURRENT STATE             ERROR                             PORTS
kbihay4nds7k  vol1fileServer.1      dperson/samba:latest  sc-rdops-vm02-dhcp-52-237  Running        Preparing 14 seconds ago                                    
kca4wdczcpp2   \_ vol1fileServer.1  dperson/samba:latest  sc-rdops-vm02-dhcp-52-237  Shutdown       Rejected 15 seconds ago   "No such image: dperson/samba@…"  
root@sc-rdops-vm02-dhcp-52-237:~# docker service ls
ID            NAME            MODE        REPLICAS  IMAGE
zlzxbqm0s728  vol1fileServer  replicated  1/1       dperson/samba:latest