Testing with docker 17.06

[pshahzeb]

A quick run against docker 17.06 have some of the e2e tests failing.
See error below

FAIL: restart_test.go:169: RestartTestData.TestPluginKill

restart_test.go:190:
    c.Assert(err, IsNil, Commentf(out))
... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc42030e000), Stderr:[]uint8(nil)} ("exit status 1")
... Error response from daemon: error while mounting volume '/mnt/vmdk/restart_test_volume_164614/': Post http://%!F(MISSING)run%!F(MISSING)docker%!F(MISSING)plugins%!F(MISSING)bba007e1293f361a4c1732a374e21596b3bfc029e5484a6f1bbff22a2f853476%!F(MISSING)vsphere.sock/VolumeDriver.Mount: dial unix /run/docker/plugins/bba007e1293f361a4c1732a374e21596b3bfc029e5484a6f1bbff22a2f853476/vsphere.sock: connect: no such file or directory
Error: failed to start containers: restart_test_container_1088637

FAIL: restart_test.go:82: RestartTestData.TearDownSuite

restart_test.go:89:
    c.Assert(err, IsNil, Commentf(out))
... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc420361620), Stderr:[]uint8(nil)} ("exit status 1")
... Error response from daemon: get restart_test_volume_164614: error while checking if volume "restart_test_volume_164614" exists in driver "vsphere:latest": Error looking up volume plugin vsphere:latest: plugin "vsphere:latest" not found


FAIL: vmlistener_test.go:190: VMListenerTestParams.TestFailoverAcrossVmOnVmfs

vmlistener_test.go:215:
    c.Assert(err, IsNil, Commentf(out))
... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc420391b80), Stderr:[]uint8(nil)} ("exit status 125")
... docker: Error response from daemon: create vmlistener_test_volume_343404: Error looking up volume plugin vsphere: plugin "vsphere" not found.
See 'docker run --help'.

Archive.zip

Attaching logs as well.

[govint]

This could be that the plugin is not yet ready (must be in a refcount recovery)) and hasn't as yet created the socket file. This error was observed in a different scenario on installation of the plugin ( #1769).

[pshahzeb]

I see. I am able to reproduce this consistently. Just ran the RestartTest
The plugin kill leaves the plugin disabled.
I logged in into the VM to verify this. Could be a test issue about how we are restarting the plugin.

[ashahi1]

This issue looks to be similar to Issue #1779
@pshahzeb Can you please confirm?

Log file has been attached at the end.

Steps:

1. Ran a container with ```--restart=always``` option.
2. Killed the vDVS plugin
3. Docker plugin ls shows plugin as disabled
4. Tried to manually enable the plugin but failed due to error: Error response from daemon: dial unix /run/docker/plugins/b40828886cb83dd46ba5daf27740d631f47e95b16926ec4343f889594c2b7c49/vsphere.sock: connect: no such file or directory

Plugin logs:

2017-08-22 01:05:52.282923295 -0700 PDT [INFO] No config file found. Using defaults.
2017-08-22 01:05:52.283281041 -0700 PDT [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info
2017-08-22 01:05:52.283472474 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock
2017-08-22 01:05:52.294149485 -0700 PDT [INFO] Found 1 running or paused containers
2017-08-22 01:05:52.695400219 -0700 PDT [WARNING] Initiating recovery mount. name="restart_test_volume_475003@sharedVmfs-1" refcnt=1 mounted=false dev=
2017-08-22 01:06:03.099735833 -0700 PDT [WARNING] Exceeded timeout while waiting for device attach to completetimeout=10s device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0"
2017-08-22 01:06:03.104039541 -0700 PDT [INFO] Discovered 1 volumes that may be in use.
2017-08-22 01:06:03.10426894 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=false device=''
2017-08-22 01:06:03.104397311 -0700 PDT [INFO] Refcounting successfully completed
2017-08-22 01:06:03.104542001 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false
2017-08-22 01:06:03.104773412 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock"
2017-08-22 01:06:04.782638129 -0700 PDT [WARNING] Received signal signal=terminated
2017-08-22 01:06:28.306907881 -0700 PDT [INFO] No config file found. Using defaults.
2017-08-22 01:06:28.307186729 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere
2017-08-22 01:06:28.307426467 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock
2017-08-22 01:06:28.318397047 -0700 PDT [INFO] Found 1 running or paused containers
2017-08-22 01:06:28.790583888 -0700 PDT [WARNING] Initiating recovery mount. name="restart_test_volume_475003@sharedVmfs-1" refcnt=1 mounted=false dev=
2017-08-22 01:06:39.234774627 -0700 PDT [WARNING] Exceeded timeout while waiting for device attach to completetimeout=10s device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0"
2017-08-22 01:06:39.239566585 -0700 PDT [INFO] Discovered 1 volumes that may be in use.
2017-08-22 01:06:39.239790259 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=false device=''
2017-08-22 01:06:39.239921713 -0700 PDT [INFO] Refcounting successfully completed
2017-08-22 01:06:39.240055056 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false
2017-08-22 01:06:39.240233235 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock"
2017-08-22 01:06:40.80906085 -0700 PDT [WARNING] Received signal signal=terminated

---

Detailed steps and their output are as follows:

1. Ran a container with --restart=always option.

root@promc-2n-dhcp105-23:/run/docker/plugins# docker run  --restart=always --volume-driver vsphere -d -v restart_test_volume_475003:/vol --name restart_test_container_898141 busybox  tail -f /dev/null
b7b35908ce15f22081ba41491a33bd5ae473aa0147238833a93741271118be2b

2. Killed the vDVS plugin

root@promc-2n-dhcp105-23:/run/docker/plugins# docker plugin list --no-trunc | grep vsphere
b40828886cb83dd46ba5daf27740d631f47e95b16926ec4343f889594c2b7c49   vsphere:latest      VMWare vSphere Docker Volume plugin   true
root@promc-2n-dhcp105-23:/run/docker/plugins#
root@promc-2n-dhcp105-23:/run/docker/plugins# docker-runc kill b40828886cb83dd46ba5daf27740d631f47e95b16926ec4343f889594c2b7c49
root@promc-2n-dhcp105-23:/run/docker/plugins#

3. Docker plugin ls shows plugin as disabled

root@promc-2n-dhcp105-23:/run/docker/plugins# docker plugin ls
ID                  NAME                DESCRIPTION                           ENABLED
b40828886cb8        vsphere:latest      VMWare vSphere Docker Volume plugin   false
root@promc-2n-dhcp105-23:/run/docker/plugins#

4. Tried to manually enable the plugin but failed.

root@promc-2n-dhcp105-23:/run/docker/plugins# docker plugin enable b40828886cb8
Error response from daemon: dial unix /run/docker/plugins/b40828886cb83dd46ba5daf27740d631f47e95b16926ec4343f889594c2b7c49/vsphere.sock: connect: no such file or directory
root@promc-2n-dhcp105-23:/run/docker/plugins#
root@promc-2n-dhcp105-23:/run/docker/plugins# docker plugin ls
ID                  NAME                DESCRIPTION                           ENABLED
b40828886cb8        vsphere:latest      VMWare vSphere Docker Volume plugin   false
root@promc-2n-dhcp105-23:/run/docker/plugins#

Logs:
docker-volume-vsphere.txt

[pshahzeb]

Yes it is the same issue.

2017-08-22 01:06:28.790583888 -0700 PDT [WARNING] Initiating recovery mount. name="restart_test_volume_475003@sharedVmfs-1" refcnt=1 mounted=false dev=
2017-08-22 01:06:39.234774627 -0700 PDT [WARNING] Exceeded timeout while waiting for device attach to completetimeout=10s device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0"

Precisely the time window where docker hits us on the socket and we haven't started listening on the socket yet.

[shuklanirdesh82]

closing this as per #1787 (comment)