Unable to mount first shared volume

[pdhamdhere]

Errors mounting very first volume and now log spews bunch of error though volume is deleted.

root@u-1:~# docker volume inspect doesitwork1
[
    {
        "Driver": "vfile:latest",
        "Labels": {},
        "Mountpoint": "/mnt/vfile/doesitwork1/",
        "Name": "doesitwork1",
        "Options": {},
        "Scope": "global",
        "Status": {
            "Clients": null,
            "File server Port": 0,
            "Global Refcount": 0,
            "Service name": "",
            "Volume Status": "Ready"
        }
    }
]
root@u-1:~# docker run --rm -it -v doesitwork1:/x busybox
docker: Error response from daemon: error while mounting volume '/mnt/vfile/doesitwork1/': VolumeDriver.Mount: Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete.
ERRO[0042] error waiting for container: context canceled 
root@u-1:~# 

From vFile.log

2017-08-25 06:36:19.76009732 +0000 UTC [INFO] Attempting to change volume state to Mounting
2017-08-25 06:36:24.798841058 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:24.806640127 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:29.798760213 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:29.804070783 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:34.798926048 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:34.809954321 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:39.798648045 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:39.80520654 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:44.798918106 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:44.806325808 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:49.798784148 +0000 UTC [INFO] Checking status of file server container...
2017-08-25 06:36:49.80634023 +0000 UTC [INFO] File server not running for volume doesitwork1
2017-08-25 06:36:49.807108924 +0000 UTC [WARNING] Timeout reached while waiting for file server container for volume doesitwork1
2017-08-25 06:36:59.827002073 +0000 UTC [INFO] Watcher on global refcount returns event type=PUT 
2017-08-25 06:36:59.828133378 +0000 UTC [ERROR] name=doesitwork1 error="Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete." 
2017-08-25 06:36:59.828665677 +0000 UTC [ERROR] Failed to mount name=doesitwork1 error="Failed to blocking wait for Mounted state. Error: Timeout reached; BlockingWait is not complete." 
2017-08-25 06:36:59.829108093 +0000 UTC [INFO] Detaching doesitwork1 - it is not used anymore
2017-08-25 06:37:00.827970333 +0000 UTC [INFO] Attempting to change volume state to Unmounting
2017-08-25 06:37:00.855648518 +0000 UTC [INFO] Volume not in proper state for the operation: Error

I noticed smb container was running on different node after above errors.

Deleting volume using docker volume rm failed with "volume in use" error.

Removed smb container and then successfully remvoed volume.

However, log continues to spew errors;\

2017-08-25 07:19:49.299714501 +0000 UTC [INFO] VolumeDriver Get: InternalVoldoesitwork1
2017-08-25 07:19:49.361141773 +0000 UTC [INFO] Volume not found: InternalVoldoesitwork1
2017-08-25 07:19:49.361253167 +0000 UTC [ERROR] Failed to get volume meta-data error="No such volume" name=InternalVoldoesitwork1 
2017-08-25 07:19:49.388447773 +0000 UTC [INFO] VolumeDriver Get: InternalVoldoesitwork1
2017-08-25 07:19:49.45516289 +0000 UTC [INFO] Volume not found: InternalVoldoesitwork1
2017-08-25 07:19:49.45538344 +0000 UTC [ERROR] Failed to get volume meta-data name=InternalVoldoesitwork1 error="No such volume" 
2017-08-25 07:19:49.457042605 +0000 UTC [WARNING] Failed to remove internal volume for volume doesitwork1. Reason: Error response from daemon: {"message":"get InternalVoldoesitwork1: no such volume"}. Failed to inspect internal volume. Error: Error: No such volume: InternalVoldoesitwork1.

Restarted docker but no luck.

cc/ @luomiao @shivanshu21

[luomiao]

We have a garbage collector to kill and remove left-over services.
Even you see the volume still in use error, it's from the base plugin,
we will still continue delete the vFile volume.
And the garbage collector will eventually delete the service along with the internal volume.

Do you mean the errors will continue and won't stop?

[luomiao]

Currently the garbage collector interval is 30 seconds.
That's why you noticed the service still there and manually killed it.
I am thinking of reduce this interval to 5 seconds.
So the left-over services and interval volumes will be removed within a short time before the users can notice.

[luomiao]

The upcoming PRs #1819 and #1799 should be able to alleviate the symptom here.