Unable to remove volume even though volume is not attached

[ashahi1]

Test failed to remove volume even though volume is not attached.
Hit this issue on CI: https://ci.vmware.run/vmware/docker-volume-vsphere/259

Test logs:

2017/05/25 19:45:43 START: Test vmdkops service restart + kill vm process
2017/05/25 19:45:43 Creating volume [vmlistener_test_volume_1495741543] on VM [192.168.31.83]
2017/05/25 19:46:01 Attaching volume [vmlistener_test_volume_1495741543] on VM [192.168.31.83]
2017/05/25 19:46:07 Confirming attached status for volume [vmlistener_test_volume_1495741543]
2017/05/25 19:46:11 Restarting vmdkops service on ESX host [192.168.31.62]
2017/05/25 19:46:14 Confirming attached status for volume [vmlistener_test_volume_1495741543]
2017/05/25 19:46:19 Retrieving VM power state for [Ubuntu.14.04]
2017/05/25 19:46:19 VM[Ubuntu.14.04]'s current power state is [poweredOn]
2017/05/25 19:46:19 Retrieving World ID for VM [Ubuntu.14.04] from ESX [192.168.31.62]
2017/05/25 19:46:19 VM's process ID is: 130824
2017/05/25 19:46:19 Killing VM from ESX [192.168.31.62]
2017/05/25 19:46:20 Sleep for 10 seconds
2017/05/25 19:46:30 Retrieving VM power state for [Ubuntu.14.04]
2017/05/25 19:46:30 VM[Ubuntu.14.04]'s current power state is [poweredOff]
2017/05/25 19:46:33 Powering on VM [Ubuntu.14.04]
2017/05/25 19:46:37 Sleep for 35 seconds
2017/05/25 19:47:12 Retrieving VM power state for [Ubuntu.14.04]
2017/05/25 19:47:12 VM[Ubuntu.14.04]'s current power state is [poweredOn]
2017/05/25 19:47:12 Confirming detached status for volume [vmlistener_test_volume_1495741543]
2017/05/25 19:47:19 END: Test vmdkops service restart + kill vm process
2017/05/25 19:47:19 Destroying volume [vmlistener_test_volume_1495741543]

----------------------------------------------------------------------
FAIL: vmlistener_test.go:61: VMListenerTestParams.TearDownTest

vmlistener_test.go:65:
    c.Assert(err, IsNil, Commentf(out))
... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc420164b60), Stderr:[]uint8(nil)} ("exit status 1")
... Error response from daemon: unable to remove volume: remove vmlistener_test_volume_1495741543: volume is in use - [974c2954d9dda822c15c048edf4e320ae6493c2623552b42c9e91729d52f0104]


----------------------------------------------------------------------
PANIC: vmlistener_test.go:78: VMListenerTestParams.TestKillVM

... Panic: Fixture has panicked (see related PANIC)
--- FAIL: Test (350.49s)

Test steps:

1. Create a volume
2. Attach it to a container
3. Restart the vmdkops service
4. Verify vmdkops_admin volume ls > verify volume stays as attached
5. Kill the vm
6. Verification: volume status should be detached
7. Power-on the vm
8. Remove the volume  <<<<<<<<<<<<<<<<<<<<<<<<< Failed here.

[shuklanirdesh82]

It is a race condition having it said it is an intermittent issue. Refcounting was in flight and docker thinks the volume is in use infact it was not; tagging this as test issue and supplying a slight more wait time.

Test is passed while looking at the detached state see below:

vmdkops.log

05/25/17 19:47:17 132045 [Ubuntu.14.04-vsanDatastore._DEFAULT.vmlistener_test_volume_1495741543] [INFO   ] executeRequest 'get' completed with ret={'attach-as': 'independent_persistent', 'access': 'read-write', 'clone-from': 'None', 'datastore': 'vsanDatastore', 'diskformat': 'thin', 'capacity': {'size': '100MB', 'allocated': '40MB'}, 'fstype': 'ext4', 'created by VM': 'Ubuntu.14.04', 'created': 'Thu May 25 19:45:48 2017', 'status': 'detached'}

test log

2017/05/25 19:46:33 Powering on VM [Ubuntu.14.04]
2017/05/25 19:46:37 Sleep for 35 seconds
2017/05/25 19:47:12 Retrieving VM power state for [Ubuntu.14.04]
2017/05/25 19:47:12 VM[Ubuntu.14.04]'s current power state is [poweredOn]
2017/05/25 19:47:12 Confirming detached status for volume [vmlistener_test_volume_1495741543]
2017/05/25 19:47:19 END: Test vmdkops service restart + kill vm process
2017/05/25 19:47:19 Destroying volume [vmlistener_test_volume_1495741543]

----------------------------------------------------------------------
FAIL: vmlistener_test.go:61: VMListenerTestParams.TearDownTest

vmlistener_test.go:65:
    c.Assert(err, IsNil, Commentf(out))
... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc420164b60), Stderr:[]uint8(nil)} ("exit status 1")
... Error response from daemon: unable to remove volume: remove vmlistener_test_volume_1495741543: volume is in use - [974c2954d9dda822c15c048edf4e320ae6493c2623552b42c9e91729d52f0104]

docker host syslog

May 25 19:47:20 sc-rdops-vm18-dhcp-57-89 dockerd[1234]: time="2017-05-25T19:47:20.468289503Z" level=error msg="Handler for DELETE /v1.28/volumes/vmlistener_test_volume_1495741543 returned error: unable to remove volume: remove vmlistener_test_volume_1495741543: volume is in use - [974c2954d9dda822c15c048edf4e320ae6493c2623552b42c9e91729d52f0104]"

docker-volume-vsphere log

2017-05-25 19:46:14.74137571 +0000 UTC [WARNING] Run 'get' failed: connection reset by peer (errno=104) -  Retrying...
2017-05-25 19:47:09.741137679 +0000 UTC [INFO] No config file found. Using defaults.
2017-05-25 19:47:09.779309985 +0000 UTC [WARNING] Failed to load config file /etc/docker-volume-vsphere.conf: open /etc/docker-volume-vsphere.conf: no such file or directory
2017-05-25 19:47:09.77937432 +0000 UTC [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info 
2017-05-25 19:47:09.779388986 +0000 UTC [INFO] Plugin options - port=1019 
2017-05-25 19:47:09.779401992 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2017-05-25 19:47:11.779877266 +0000 UTC [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery
2017-05-25 19:47:11.779970276 +0000 UTC [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded).
2017-05-25 19:47:11.779999312 +0000 UTC [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.4" port=1019 mock_esx=false 
2017-05-25 19:47:11.780153602 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 
2017-05-25 19:47:11.780389793 +0000 UTC [INFO] Scheduling again after 2 seconds
2017-05-25 19:47:13.781061134 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2017-05-25 19:47:15.781368275 +0000 UTC [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery
2017-05-25 19:47:15.781462975 +0000 UTC [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded). Attempts left: 20 
2017-05-25 19:47:15.781477888 +0000 UTC [INFO] Scheduling again after 4 seconds
2017-05-25 19:47:19.78192135 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2017-05-25 19:47:19.789383583 +0000 UTC [INFO] Found 0 running or paused containers
2017-05-25 19:47:19.789684094 +0000 UTC [INFO] Discovered 0 volumes in use.
2017-05-25 19:47:19.789719805 +0000 UTC [INFO] Refcounting successfully completed