2017-08-22 00:19:43.930397534 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:19:43.930603898 -0700 PDT [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info 2017-08-22 00:19:43.930658145 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:19:43.940946057 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 00:19:43.941300432 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 00:19:43.941310671 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:19:43.941323307 -0700 PDT [INFO] Docker VMDK plugin started mock_esx=false version="vSphere Volume Driver v0.5" port=1019 2017-08-22 00:19:43.941482576 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:32:00.379980201 -0700 PDT [ERROR] Failed to get volume meta-data name="restart_test_volume_742096" error="Volume restart_test_volume_742096 not found (file: /vmfs/volumes/sharedVmfs-1/dockvols/_DEFAULT/restart_test_volume_742096.vmdk)" 2017-08-22 00:32:00.802493598 -0700 PDT [INFO] Attaching volume and creating filesystem name="restart_test_volume_742096" fstype=ext4 2017-08-22 00:32:02.023446573 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:32:02.548352105 -0700 PDT [INFO] Volume and filesystem created name="restart_test_volume_742096" fstype=ext4 2017-08-22 00:32:06.42519549 -0700 PDT [ERROR] Failed to get volume meta-data name="restart_test_volume_742096@sharedVmfs-0" error="Volume restart_test_volume_742096 not found (file: /vmfs/volumes/sharedVmfs-0/dockvols/_DEFAULT/restart_test_volume_742096.vmdk)" 2017-08-22 00:32:06.854562111 -0700 PDT [INFO] Attaching volume and creating filesystem name="restart_test_volume_742096@sharedVmfs-0" fstype=ext4 2017-08-22 00:32:07.256228539 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:32:08.179466813 -0700 PDT [INFO] Volume and filesystem created name="restart_test_volume_742096@sharedVmfs-0" fstype=ext4 2017-08-22 00:32:11.095856735 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:32:11.179226867 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_742096@sharedVmfs-1/" 2017-08-22 00:32:11.602433425 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:32:13.010415198 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096@sharedVmfs-0" 2017-08-22 00:32:13.096048025 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_742096@sharedVmfs-0/" 2017-08-22 00:32:13.508060996 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE 2017-08-22 00:32:25.655930954 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096" 2017-08-22 00:32:25.714147752 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096@sharedVmfs-0" 2017-08-22 00:32:26.398587265 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:32:28.517604866 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:32:28.517673624 -0700 PDT [INFO] Starting plugin driver=vsphere log_level=info config="/etc/docker-volume-vsphere.conf" 2017-08-22 00:32:28.517694287 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:32:30.517993992 -0700 PDT [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery 2017-08-22 00:32:30.518092991 -0700 PDT [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded). 2017-08-22 00:32:30.51814353 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:32:30.518607462 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:32:30.518876387 -0700 PDT [INFO] Scheduling again after 2 seconds 2017-08-22 00:32:32.519056631 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:32:32.645145692 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:32:32.735530768 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096@sharedVmfs-0" 2017-08-22 00:32:33.242237353 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" 2017-08-22 00:32:34.103004029 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0" 2017-08-22 00:32:34.336561176 -0700 PDT [INFO] Found 2 running or paused containers 2017-08-22 00:32:34.480550305 -0700 PDT [INFO] Discovered 2 volumes that may be in use. 2017-08-22 00:32:34.480618702 -0700 PDT [INFO] Volume name=restart_test_volume_742096@sharedVmfs-0 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0' 2017-08-22 00:32:34.480628503 -0700 PDT [INFO] Volume name=restart_test_volume_742096@sharedVmfs-1 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0' 2017-08-22 00:32:34.480633551 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:32:56.162795604 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096@sharedVmfs-1" 2017-08-22 00:32:56.162853265 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_742096@sharedVmfs-1" refcount=2 2017-08-22 00:32:57.29172908 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096@sharedVmfs-1" 2017-08-22 00:32:57.291805974 -0700 PDT [INFO] Still in use, skipping unmount request. name="restart_test_volume_742096@sharedVmfs-1" refcount=1 2017-08-22 00:32:57.345967441 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096" 2017-08-22 00:32:57.404532085 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096@sharedVmfs-0" 2017-08-22 00:32:58.915281824 -0700 PDT [INFO] Removing volume name="restart_test_volume_742096@sharedVmfs-0" 2017-08-22 00:33:07.035182205 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:33:07.539632779 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:33:18.66935467 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096" 2017-08-22 00:33:19.186809337 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:33:20.370279041 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:33:20.370346 -0700 PDT [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info 2017-08-22 00:33:20.370367775 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:33:22.370573102 -0700 PDT [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery 2017-08-22 00:33:22.370677832 -0700 PDT [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded). 2017-08-22 00:33:22.370699703 -0700 PDT [INFO] Docker VMDK plugin started mock_esx=false version="vSphere Volume Driver v0.5" port=1019 2017-08-22 00:33:22.370872246 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:33:22.37113738 -0700 PDT [INFO] Scheduling again after 2 seconds 2017-08-22 00:33:24.304332715 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:33:24.371381251 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:33:24.765081783 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:33:24.998631386 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 00:33:25.491454995 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 00:33:25.4915235 -0700 PDT [INFO] Volume name=restart_test_volume_742096@sharedVmfs-1 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0' 2017-08-22 00:33:25.491539126 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:33:47.045673806 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:33:47.147479938 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_742096@sharedVmfs-1" refcount=2 2017-08-22 00:33:49.113828418 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096@sharedVmfs-1" 2017-08-22 00:33:49.113903763 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_742096@sharedVmfs-1" refcount=3 2017-08-22 00:33:50.133905861 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096@sharedVmfs-1" 2017-08-22 00:33:50.133986882 -0700 PDT [INFO] Still in use, skipping unmount request. refcount=2 name="restart_test_volume_742096@sharedVmfs-1" 2017-08-22 00:33:50.18680044 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096" 2017-08-22 00:33:50.186833286 -0700 PDT [INFO] Still in use, skipping unmount request. name="restart_test_volume_742096@sharedVmfs-1" refcount=1 2017-08-22 00:33:50.242116519 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_742096" 2017-08-22 00:33:54.728757895 -0700 PDT [INFO] Mounting volume name="restart_test_volume_742096" 2017-08-22 00:33:55.198983003 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" 2017-08-22 00:34:02.834033059 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:34:02.9250942 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:34:02.925125209 -0700 PDT [INFO] Starting plugin driver=vsphere log_level=info config="/etc/docker-volume-vsphere.conf" 2017-08-22 00:34:02.925196627 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:34:02.964522955 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 00:34:03.324303207 -0700 PDT [WARNING] Initiating recovery mount. name="restart_test_volume_742096@sharedVmfs-1" refcnt=1 mounted=false dev= 2017-08-22 00:34:13.698080654 -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 00:34:13.702299516 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 00:34:13.70233844 -0700 PDT [INFO] Volume name=restart_test_volume_742096@sharedVmfs-1 count=1 mounted=false device='' 2017-08-22 00:34:13.702347719 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:34:13.702368367 -0700 PDT [INFO] Docker VMDK plugin started port=1019 mock_esx=false version="vSphere Volume Driver v0.5" 2017-08-22 00:34:13.702530483 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:34:15.425778406 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:39:47.059855667 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:39:47.059933052 -0700 PDT [INFO] Starting plugin driver=vsphere log_level=info config="/etc/docker-volume-vsphere.conf" 2017-08-22 00:39:47.060005543 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:39:47.081734236 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 00:39:47.590668246 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 00:39:47.590724695 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:39:47.590765408 -0700 PDT [INFO] Docker VMDK plugin started mock_esx=false version="vSphere Volume Driver v0.5" port=1019 2017-08-22 00:39:47.591279673 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:42:35.886984628 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:42:35.973948657 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:42:35.97401788 -0700 PDT [INFO] Starting plugin driver=vsphere log_level=info config="/etc/docker-volume-vsphere.conf" 2017-08-22 00:42:35.974075032 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:42:35.984750246 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 00:42:35.985282128 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 00:42:35.98529542 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:42:35.985309259 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:42:35.985481448 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:44:04.279238425 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:44:04.396078336 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:44:04.396110105 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere 2017-08-22 00:44:04.396191339 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:44:04.405130872 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 00:44:04.405466933 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 00:44:04.405477824 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:44:04.405485441 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:44:04.405641686 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:47:41.569648899 -0700 PDT [ERROR] Failed to get volume meta-data error="Volume restart_test_volume_475003 not found (file: /vmfs/volumes/sharedVmfs-1/dockvols/_DEFAULT/restart_test_volume_475003.vmdk)" name="restart_test_volume_475003" 2017-08-22 00:47:41.940221552 -0700 PDT [INFO] Attaching volume and creating filesystem name="restart_test_volume_475003" fstype=ext4 2017-08-22 00:47:42.356244794 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" 2017-08-22 00:47:42.905256246 -0700 PDT [INFO] Volume and filesystem created name="restart_test_volume_475003" fstype=ext4 2017-08-22 00:47:46.519746968 -0700 PDT [ERROR] Failed to get volume meta-data name="restart_test_volume_475003@sharedVmfs-0" error="Volume restart_test_volume_475003 not found (file: /vmfs/volumes/sharedVmfs-0/dockvols/_DEFAULT/restart_test_volume_475003.vmdk)" 2017-08-22 00:47:46.944836143 -0700 PDT [INFO] Attaching volume and creating filesystem name="restart_test_volume_475003@sharedVmfs-0" fstype=ext4 2017-08-22 00:47:47.329623993 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" 2017-08-22 00:47:48.628447848 -0700 PDT [INFO] Volume and filesystem created name="restart_test_volume_475003@sharedVmfs-0" fstype=ext4 2017-08-22 00:47:49.676419327 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:47:49.76391773 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_475003@sharedVmfs-1/" 2017-08-22 00:47:50.164487442 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:47:51.562538953 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003@sharedVmfs-0" 2017-08-22 00:47:51.655583548 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_475003@sharedVmfs-0/" 2017-08-22 00:47:52.059459494 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE 2017-08-22 00:48:04.025805499 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003@sharedVmfs-0" 2017-08-22 00:48:04.082075427 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003" 2017-08-22 00:48:04.886400329 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:48:06.034201647 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:48:06.034278274 -0700 PDT [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info 2017-08-22 00:48:06.034299123 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:48:08.034700887 -0700 PDT [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery 2017-08-22 00:48:08.034808375 -0700 PDT [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded). 2017-08-22 00:48:08.034857675 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:48:08.035324798 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:48:08.035690508 -0700 PDT [INFO] Scheduling again after 2 seconds 2017-08-22 00:48:09.644390146 -0700 PDT [ERROR] Failed to get volume meta-data name= error="Volume not found (file: /vmfs/volumes/sharedVmfs-1/dockvols/_DEFAULT/.vmdk)" 2017-08-22 00:48:10.036229499 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:48:10.284096477 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003@sharedVmfs-0" 2017-08-22 00:48:10.3681248 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:48:10.895391383 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:48:11.712104699 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE 2017-08-22 00:48:11.950334747 -0700 PDT [INFO] Found 2 running or paused containers 2017-08-22 00:48:12.088553664 -0700 PDT [INFO] Discovered 2 volumes that may be in use. 2017-08-22 00:48:12.08862305 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-0 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0' 2017-08-22 00:48:12.088631954 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:1:0' 2017-08-22 00:48:12.088636925 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:48:33.808216946 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 00:48:33.808308372 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_475003@sharedVmfs-1" refcount=2 2017-08-22 00:48:34.927496969 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 00:48:34.927568818 -0700 PDT [INFO] Still in use, skipping unmount request. name="restart_test_volume_475003@sharedVmfs-1" refcount=1 2017-08-22 00:48:34.982856065 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003" 2017-08-22 00:48:35.03415774 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003@sharedVmfs-0" 2017-08-22 00:48:36.431873675 -0700 PDT [INFO] Removing volume name="restart_test_volume_475003@sharedVmfs-0" 2017-08-22 00:48:40.835948629 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:48:41.330150673 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:48:52.337131739 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003" 2017-08-22 00:48:52.821833945 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:48:54.941376408 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:48:54.941550976 -0700 PDT [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" driver=vsphere log_level=info 2017-08-22 00:48:54.9415786 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:48:56.941998997 -0700 PDT [INFO] Can't connect to unix:///var/run/docker.sock due to (An error occurred trying to connect: context deadline exceeded), skipping discovery 2017-08-22 00:48:56.942110333 -0700 PDT [INFO] Refcounting failed: (An error occurred trying to connect: context deadline exceeded). 2017-08-22 00:48:56.942138684 -0700 PDT [INFO] Docker VMDK plugin started port=1019 mock_esx=false version="vSphere Volume Driver v0.5" 2017-08-22 00:48:56.942674887 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:48:56.943099074 -0700 PDT [INFO] Scheduling again after 2 seconds 2017-08-22 00:48:58.636512833 -0700 PDT [ERROR] Failed to get volume meta-data name= error="Volume not found (file: /vmfs/volumes/sharedVmfs-1/dockvols/_DEFAULT/.vmdk)" 2017-08-22 00:48:58.943337794 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:48:59.11588627 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:48:59.601416655 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:48:59.824923789 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 00:49:00.219678873 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 00:49:00.219757738 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=true device='/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0' 2017-08-22 00:49:00.219773799 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:49:21.677885871 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:49:21.775074713 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_475003@sharedVmfs-1" refcount=2 2017-08-22 00:49:23.778865634 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 00:49:23.778965778 -0700 PDT [INFO] Already mounted, skipping mount. name="restart_test_volume_475003@sharedVmfs-1" refcount=3 2017-08-22 00:49:24.75366401 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 00:49:24.753772523 -0700 PDT [INFO] Still in use, skipping unmount request. name="restart_test_volume_475003@sharedVmfs-1" refcount=2 2017-08-22 00:49:24.816541561 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003" 2017-08-22 00:49:24.817948376 -0700 PDT [INFO] Still in use, skipping unmount request. refcount=1 name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 00:49:24.875802711 -0700 PDT [INFO] Unmounting Volume name="restart_test_volume_475003" 2017-08-22 00:49:29.303701833 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:49:29.826174389 -0700 PDT [INFO] Scan complete event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" 2017-08-22 00:49:37.1843536 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:49:37.260747487 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:49:37.260847721 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere 2017-08-22 00:49:37.260926171 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:49:37.270629019 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 00:49:37.610395603 -0700 PDT [WARNING] Initiating recovery mount. name="restart_test_volume_475003@sharedVmfs-1" refcnt=1 mounted=false dev= 2017-08-22 00:49:47.970905906 -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 00:49:47.971071874 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 00:49:47.971085862 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=false device='' 2017-08-22 00:49:47.971091364 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:49:47.971116075 -0700 PDT [INFO] Docker VMDK plugin started port=1019 mock_esx=false version="vSphere Volume Driver v0.5" 2017-08-22 00:49:47.971195823 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:49:49.75927238 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:52:36.427692341 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:52:36.42777616 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere 2017-08-22 00:52:36.427867185 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:52:36.442290675 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 00:52:36.949184999 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 00:52:36.949225165 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:52:36.949308896 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:52:36.949572878 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:53:34.706122446 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 00:53:34.794497317 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_475003@sharedVmfs-1/" 2017-08-22 00:53:35.204383712 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 00:55:02.805356368 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 00:55:02.890709919 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 00:55:02.890785364 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere 2017-08-22 00:55:02.890810505 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 00:55:02.900197076 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 00:55:03.216792777 -0700 PDT [WARNING] Initiating recovery mount. mounted=false dev= name="restart_test_volume_475003@sharedVmfs-1" refcnt=1 2017-08-22 00:55:13.58064329 -0700 PDT [WARNING] Exceeded timeout while waiting for device attach to completedevice="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" timeout=10s 2017-08-22 00:55:13.58631041 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 00:55:13.586362609 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=false device='' 2017-08-22 00:55:13.586373246 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 00:55:13.586454686 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 00:55:13.586570213 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 00:55:15.391640878 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 01:00:24.855283957 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 01:00:24.855645771 -0700 PDT [INFO] Starting plugin driver=vsphere log_level=info config="/etc/docker-volume-vsphere.conf" 2017-08-22 01:00:24.855804908 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 01:00:24.869331095 -0700 PDT [INFO] Found 0 running or paused containers 2017-08-22 01:00:25.438960548 -0700 PDT [INFO] Discovered 0 volumes that may be in use. 2017-08-22 01:00:25.439225629 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 01:00:25.439405406 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 01:00:25.439783028 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 01:02:20.4017054 -0700 PDT [INFO] Mounting volume name="restart_test_volume_475003" 2017-08-22 01:02:20.514977638 -0700 PDT [INFO] Directory doesn't exist, creating it path="/mnt/vmdk/restart_test_volume_475003@sharedVmfs-1/" 2017-08-22 01:02:20.915898969 -0700 PDT [INFO] Scan complete device="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" event="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 2017-08-22 01:03:31.453682613 -0700 PDT [WARNING] Received signal signal=terminated 2017-08-22 01:03:31.53637756 -0700 PDT [INFO] No config file found. Using defaults. 2017-08-22 01:03:31.536705068 -0700 PDT [INFO] Starting plugin log_level=info config="/etc/docker-volume-vsphere.conf" driver=vsphere 2017-08-22 01:03:31.536849984 -0700 PDT [INFO] Getting volume data from unix:///var/run/docker.sock 2017-08-22 01:03:31.552204206 -0700 PDT [INFO] Found 1 running or paused containers 2017-08-22 01:03:31.929574272 -0700 PDT [WARNING] Initiating recovery mount. refcnt=1 mounted=false dev= name="restart_test_volume_475003@sharedVmfs-1" 2017-08-22 01:03:42.317458389 -0700 PDT [WARNING] Exceeded timeout while waiting for device attach to completedevice="/dev/disk/by-path/pci-0000:13:00.0-scsi-0:0:0:0" timeout=10s 2017-08-22 01:03:42.322139263 -0700 PDT [INFO] Discovered 1 volumes that may be in use. 2017-08-22 01:03:42.322341695 -0700 PDT [INFO] Volume name=restart_test_volume_475003@sharedVmfs-1 count=1 mounted=false device='' 2017-08-22 01:03:42.322470434 -0700 PDT [INFO] Refcounting successfully completed 2017-08-22 01:03:42.322632494 -0700 PDT [INFO] Docker VMDK plugin started version="vSphere Volume Driver v0.5" port=1019 mock_esx=false 2017-08-22 01:03:42.322821787 -0700 PDT [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-08-22 01:03:44.037296601 -0700 PDT [WARNING] Received signal signal=terminated 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