2016-12-02 07:09:06.349139957 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:09:06.349292938 +0000 UTC [INFO] Docker VMDK plugin started port=1019 mock_esx=false log_level=info config="/etc/docker-volume-vsphere.conf" version="VMDK Volume Driver v0.3" 
2016-12-02 07:09:06.349366717 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2016-12-02 07:09:06.360707517 +0000 UTC [INFO] Discovered 0 volumes in use.
2016-12-02 07:09:06.360738865 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vmdk.sock" 
2016-12-02 07:19:59.229357332 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:19:59.229401415 +0000 UTC [INFO] VMDK plugin tests started log_file="/var/log/docker-volume-vsphere.log" conf_file="/etc/docker-volume-vsphere.conf" using_conf_file_defaults=true driver=vmdk log_level=debug 
2016-12-02 07:20:00.384776787 +0000 UTC [INFO] Attaching volume and creating filesystem name=refCountTestVol fstype=ext4 
2016-12-02 07:20:03.029588158 +0000 UTC [INFO] Volume and filesystem created name=refCountTestVol fstype=ext4 
2016-12-02 07:20:05.395801635 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:08.966202091 +0000 UTC [INFO] Attach complete event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE name=refCountTestVol 
2016-12-02 07:20:10.709604134 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:10.709652346 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=2 
2016-12-02 07:20:10.971466326 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:10.971493748 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=3 
2016-12-02 07:20:11.149668846 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:11.14969609 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=4 
2016-12-02 07:20:11.332479343 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:11.332506087 +0000 UTC [INFO] Already mounted, skipping mount. refcount=5 name=refCountTestVol 
2016-12-02 07:20:12.550758257 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:20:12.550783947 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=6 
2016-12-02 07:20:12.677462758 +0000 UTC [INFO] Unmounting Volume name=refCountTestVol 
2016-12-02 07:20:12.677494154 +0000 UTC [INFO] Still in use, skipping unmount request. name=refCountTestVol refcount=5 
2016-12-02 07:20:13.043050206 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:20:13.043125934 +0000 UTC [INFO] Docker VMDK plugin started log_level=info config="/etc/docker-volume-vsphere.conf" version="VMDK Volume Driver v0.3" port=1019 mock_esx=false 
2016-12-02 07:20:13.043168132 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2016-12-02 07:22:39.816035959 +0000 UTC [INFO] Discovered 1 volumes in use.
2016-12-02 07:22:39.816485047 +0000 UTC [INFO] Volume name=refCountTestVol count=4 mounted=true device='/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0'
2016-12-02 07:22:39.816725089 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vmdk.sock" 
2016-12-02 07:22:41.775496892 +0000 UTC [INFO] Removing volume name=refCountTestVol 
2016-12-02 07:22:41.775531244 +0000 UTC [ERROR] Remove failure - volume is still mounted.  volume=refCountTestVol, refcount=4
2016-12-02 07:22:42.835677228 +0000 UTC [INFO] Attaching volume and creating filesystem name=vol.build584 fstype=ext4 
2016-12-02 07:22:44.477905596 +0000 UTC [INFO] Volume and filesystem created name=vol.build584 fstype=ext4 
2016-12-02 07:22:44.632076457 +0000 UTC [INFO] Mounting volume name=vol.build584 
2016-12-02 07:22:46.482531073 +0000 UTC [INFO] Attach complete event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE name=vol.build584 
2016-12-02 07:22:46.985688005 +0000 UTC [INFO] Unmounting Volume name=vol.build584 
2016-12-02 07:22:47.313200776 +0000 UTC [INFO] Mounting volume name=vol.build584 
2016-12-02 07:22:47.689594504 +0000 UTC [INFO] Attach complete event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE name=vol.build584 
2016-12-02 07:22:48.029763411 +0000 UTC [INFO] Unmounting Volume name=vol.build584 
2016-12-02 07:22:49.156145237 +0000 UTC [INFO] Removing volume name=vol.build584 
2016-12-02 07:22:51.812311784 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP00 fstype=ext4 
2016-12-02 07:22:56.166732719 +0000 UTC [INFO] Volume and filesystem created name=volTestP00 fstype=ext4 
2016-12-02 07:22:56.322746557 +0000 UTC [INFO] Removing volume name=volTestP00 
2016-12-02 07:22:58.744357777 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP01 fstype=ext4 
2016-12-02 07:23:03.497151377 +0000 UTC [INFO] Volume and filesystem created name=volTestP01 fstype=ext4 
2016-12-02 07:23:03.769467612 +0000 UTC [INFO] Removing volume name=volTestP01 
2016-12-02 07:23:05.93947158 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=volTestP02 
2016-12-02 07:23:09.84955874 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP02 
2016-12-02 07:23:09.887455515 +0000 UTC [INFO] Removing volume name=volTestP02 
2016-12-02 07:23:11.686727345 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=volTestP03 
2016-12-02 07:23:16.15206964 +0000 UTC [INFO] Volume and filesystem created name=volTestP03 fstype=ext4 
2016-12-02 07:23:16.298708496 +0000 UTC [INFO] Removing volume name=volTestP03 
2016-12-02 07:23:19.302728452 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP04 fstype=ext4 
2016-12-02 07:23:26.531423778 +0000 UTC [INFO] Volume and filesystem created name=volTestP04 fstype=ext4 
2016-12-02 07:23:26.567965373 +0000 UTC [INFO] Removing volume name=volTestP04 
2016-12-02 07:23:29.300979748 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=volTestP05 
2016-12-02 07:23:32.634569942 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP05 
2016-12-02 07:23:32.683809447 +0000 UTC [INFO] Removing volume name=volTestP05 
2016-12-02 07:23:35.686495437 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=volTestP06 
2016-12-02 07:23:39.214375734 +0000 UTC [INFO] Volume and filesystem created name=volTestP06 fstype=ext4 
2016-12-02 07:23:39.292637808 +0000 UTC [INFO] Removing volume name=volTestP06 
2016-12-02 07:23:41.941825877 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP07 fstype=ext4 
2016-12-02 07:23:45.149728546 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP07 
2016-12-02 07:23:45.197371338 +0000 UTC [INFO] Removing volume name=volTestP07 
2016-12-02 07:23:47.792789695 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP08 fstype=ext4 
2016-12-02 07:23:50.71311801 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP08 
2016-12-02 07:23:50.74947131 +0000 UTC [INFO] Removing volume name=volTestP08 
2016-12-02 07:24:05.504706719 +0000 UTC [WARNING] Received signal signal=terminated 
2016-12-02 07:40:06.336350279 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:40:06.336399522 +0000 UTC [INFO] Docker VMDK plugin started version="VMDK Volume Driver v0.3" port=1019 mock_esx=false log_level=info config="/etc/docker-volume-vsphere.conf" 
2016-12-02 07:40:06.336464432 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2016-12-02 07:40:06.349190337 +0000 UTC [INFO] Initiating recovery unmount. name=refCountTestVol refcnt=0 mounted=true dev="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0" 
2016-12-02 07:40:06.857894339 +0000 UTC [INFO] Discovered 1 volumes in use.
2016-12-02 07:40:06.857926503 +0000 UTC [INFO] Volume name=refCountTestVol count=0 mounted=true device='/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0'
2016-12-02 07:40:06.857949161 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vmdk.sock" 
2016-12-02 07:58:19.126911005 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:58:19.127068294 +0000 UTC [INFO] VMDK plugin tests started log_file="/var/log/docker-volume-vsphere.log" conf_file="/etc/docker-volume-vsphere.conf" using_conf_file_defaults=true driver=vmdk log_level=debug 
2016-12-02 07:58:19.628490996 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:20.322151665 +0000 UTC [INFO] Attach complete name=refCountTestVol event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0": 0x100 == IN_CREATE 
2016-12-02 07:58:20.925726863 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:20.925766083 +0000 UTC [INFO] Already mounted, skipping mount. refcount=2 name=refCountTestVol 
2016-12-02 07:58:21.104203592 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:21.10423128 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=3 
2016-12-02 07:58:21.321998661 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:21.322026951 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=4 
2016-12-02 07:58:21.53649949 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:21.536529932 +0000 UTC [INFO] Already mounted, skipping mount. name=refCountTestVol refcount=5 
2016-12-02 07:58:22.76076692 +0000 UTC [INFO] Mounting volume name=refCountTestVol 
2016-12-02 07:58:22.760796019 +0000 UTC [INFO] Already mounted, skipping mount. refcount=6 name=refCountTestVol 
2016-12-02 07:58:22.91229911 +0000 UTC [INFO] Unmounting Volume name=refCountTestVol 
2016-12-02 07:58:22.912354297 +0000 UTC [INFO] Still in use, skipping unmount request. refcount=5 name=refCountTestVol 
2016-12-02 07:58:23.371913424 +0000 UTC [INFO] No config file found. Using defaults.
2016-12-02 07:58:23.372044193 +0000 UTC [INFO] Docker VMDK plugin started log_level=info config="/etc/docker-volume-vsphere.conf" version="VMDK Volume Driver v0.3" port=1019 mock_esx=false 
2016-12-02 07:58:23.372134723 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock
2016-12-02 08:00:49.528331096 +0000 UTC [INFO] Discovered 1 volumes in use.
2016-12-02 08:00:49.528388432 +0000 UTC [INFO] Volume name=refCountTestVol count=4 mounted=true device='/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:0:0'
2016-12-02 08:00:49.52841024 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vmdk.sock" 
2016-12-02 08:00:51.356845599 +0000 UTC [INFO] Removing volume name=refCountTestVol 
2016-12-02 08:00:51.356875662 +0000 UTC [ERROR] Remove failure - volume is still mounted.  volume=refCountTestVol, refcount=4
2016-12-02 08:00:52.455954398 +0000 UTC [INFO] Attaching volume and creating filesystem name=DefaultTestVol fstype=ext4 
2016-12-02 08:00:54.422478811 +0000 UTC [INFO] Volume and filesystem created name=DefaultTestVol fstype=ext4 
2016-12-02 08:00:54.521831173 +0000 UTC [INFO] Mounting volume name=DefaultTestVol 
2016-12-02 08:00:56.33853685 +0000 UTC [INFO] Attach complete name=DefaultTestVol event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE 
2016-12-02 08:00:56.770285252 +0000 UTC [INFO] Unmounting Volume name=DefaultTestVol 
2016-12-02 08:00:57.182847429 +0000 UTC [INFO] Mounting volume name=DefaultTestVol 
2016-12-02 08:00:57.623197806 +0000 UTC [INFO] Attach complete name=DefaultTestVol event="/dev/disk/by-path/pci-0000:0b:00.0-scsi-0:0:1:0": 0x100 == IN_CREATE 
2016-12-02 08:00:57.886197265 +0000 UTC [INFO] Unmounting Volume name=DefaultTestVol 
2016-12-02 08:00:58.826866172 +0000 UTC [INFO] Removing volume name=DefaultTestVol 
2016-12-02 08:01:01.19699785 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP00 fstype=ext4 
2016-12-02 08:01:04.485416904 +0000 UTC [INFO] Volume and filesystem created name=volTestP00 fstype=ext4 
2016-12-02 08:01:04.596260713 +0000 UTC [INFO] Removing volume name=volTestP00 
2016-12-02 08:01:07.016310271 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP01 fstype=ext4 
2016-12-02 08:01:09.989296325 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP01 
2016-12-02 08:01:10.244877301 +0000 UTC [INFO] Removing volume name=volTestP01 
2016-12-02 08:01:11.811612527 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP02 fstype=ext4 
2016-12-02 08:01:15.532886165 +0000 UTC [INFO] Volume and filesystem created name=volTestP02 fstype=ext4 
2016-12-02 08:01:15.903890892 +0000 UTC [INFO] Removing volume name=volTestP02 
2016-12-02 08:01:18.134417132 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP03 fstype=ext4 
2016-12-02 08:01:21.661760243 +0000 UTC [INFO] Volume and filesystem created name=volTestP03 fstype=ext4 
2016-12-02 08:01:21.95858214 +0000 UTC [INFO] Removing volume name=volTestP03 
2016-12-02 08:01:23.349320457 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP04 fstype=ext4 
2016-12-02 08:01:26.754245563 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP04 
2016-12-02 08:01:27.05217913 +0000 UTC [INFO] Removing volume name=volTestP04 
2016-12-02 08:01:29.741594733 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP05 fstype=ext4 
2016-12-02 08:01:36.892810505 +0000 UTC [INFO] Volume and filesystem created fstype=ext4 name=volTestP05 
2016-12-02 08:01:36.978078439 +0000 UTC [INFO] Removing volume name=volTestP05 
2016-12-02 08:01:39.382947459 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP06 fstype=ext4 
2016-12-02 08:01:43.15594691 +0000 UTC [INFO] Volume and filesystem created name=volTestP06 fstype=ext4 
2016-12-02 08:01:43.276196092 +0000 UTC [INFO] Removing volume name=volTestP06 
2016-12-02 08:01:45.577061623 +0000 UTC [INFO] Attaching volume and creating filesystem name=volTestP07 fstype=ext4 
2016-12-02 08:01:49.208790882 +0000 UTC [INFO] Volume and filesystem created name=volTestP07 fstype=ext4 
2016-12-02 08:01:49.277114639 +0000 UTC [INFO] Removing volume name=volTestP07 
2016-12-02 08:01:51.727932951 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=volTestP08 
2016-12-02 08:01:55.211117564 +0000 UTC [INFO] Volume and filesystem created name=volTestP08 fstype=ext4 
2016-12-02 08:01:55.260455332 +0000 UTC [INFO] Removing volume name=volTestP08