Boot2docker issues

[smithd13]

Hi

Similar but different to issue #1744 - we deployed vmware docker volume driver to our vSphere Cluster today and can't get it to work with boot2docker (or rancherOS).

Upon provisioning a new host VM and installing the plugin, if we create a new volume it fails with the following error:

docker@gm-l-doc-05:~$ docker volume create --driver=vsphere --name=test Error response from daemon: create test: VolumeDriver.Create: Device not found

Looking at the /var/log/docker-volume-vsphere.log we get:

docker@gm-l-doc-05:/var/log$ cat docker-volume-vsphere.log 2017-12-05 18:24:04.033322944 +0000 UTC [INFO] No config file found. Using defaults. 2017-12-05 18:24:04.033360671 +0000 UTC [INFO] Starting plugin config="/etc/docker-volume-vsphere.conf" group=root driver=vsphere log_level=info 2017-12-05 18:24:04.033376743 +0000 UTC [INFO] Getting volume data from unix:///var/run/docker.sock 2017-12-05 18:24:04.039196327 +0000 UTC [INFO] Found 0 running or paused containers 2017-12-05 18:24:04.039395559 +0000 UTC [INFO] Discovered 0 volumes that may be in use. 2017-12-05 18:24:04.039403283 +0000 UTC [INFO] Refcounting successfully completed 2017-12-05 18:24:04.039409932 +0000 UTC [INFO] Docker VMDK plugin started version=latest port=1019 mock_esx=false 2017-12-05 18:24:04.039511936 +0000 UTC [INFO] Going into ServeUnix - Listening on Unix socket address="/run/docker/plugins/vsphere.sock" 2017-12-05 18:24:41.269889734 +0000 UTC [ERROR] Failed to get volume meta-data error="Volume test not found (file: /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk)" name=test 2017-12-05 18:24:41.927050486 +0000 UTC [INFO] Attaching volume and creating filesystem fstype=ext4 name=test 2017-12-05 18:24:42.732951946 +0000 UTC [WARNING] Get device path failed for unit %s @ PCI bridge device %s: 1Error="open /sys/bus/pci/devices/0000:00:/pci_bus: no such file or directory" 2017-12-05 18:24:42.732983923 +0000 UTC [ERROR] Failed to get device path volDev={1 160 } err="Device not found" 2017-12-05 18:24:42.732999399 +0000 UTC [ERROR] Could not find attached device, removing the volume name=test error="Device not found"

dmesg shows it adding the hard drive fine:

vmw_pvscsi: msg type: 0x0 - MSG RING: 1/0 (5) vmw_pvscsi: msg: device added at scsi0:1:0 scsi 0:0:1:0: Direct-Access VMware Virtual disk 2.0 PQ: 0 ANSI: 6 sd 0:0:1:0: Attached scsi generic sg2 type 0 sd 0:0:1:0: [sdb] 204800 512-byte logical blocks: (105 MB/100 MiB) sd 0:0:1:0: [sdb] Write Protect is off sd 0:0:1:0: [sdb] Mode Sense: 31 00 00 00 sd 0:0:1:0: [sdb] Cache data unavailable sd 0:0:1:0: [sdb] Assuming drive cache: write through sd 0:0:1:0: [sdb] Attached SCSI disk vmw_pvscsi: msg type: 0x1 - MSG RING: 2/1 (5) vmw_pvscsi: msg: device removed at scsi0:1:0 `

After trying to add a volume, /var/log/vmware-vmsvc.log constantly spams with:

` [Dec 05 18:24:11.760] [ warning] [guestinfo] GetDiskInfo: ERROR: Partition name buffer too small [Dec 05 18:24:11.760] [ warning] [guestinfo] Failed to get disk info. [Dec 05 18:24:41.761] [ warning] [guestinfo] GetDiskInfo: ERROR: Partition name buffer too small [Dec 05 18:24:41.761] [ warning] [guestinfo] Failed to get disk info. [Dec 05 18:25:11.761] [ warning] [guestinfo] GetDiskInfo: ERROR: Partition name buffer too small [Dec 05 18:25:11.761] [ warning] [guestinfo] Failed to get disk info.

until the container-vm is rebooted.

/var/log/docker.log shows:

time="2017-12-05T18:24:38.895344004Z" level=debug msg="Calling POST /v1.32/volumes/create" time="2017-12-05T18:24:38.895413245Z" level=debug msg="form data: {\"Driver\":\"vsphere\",\"DriverOpts\":{},\"Labels\":{},\"Name\":\"test\"}" time="2017-12-05T18:24:38.896226598Z" level=debug msg="Registering new volume reference: driver \"vsphere:latest\", name \"test\"" time="2017-12-05T18:24:44.031893120Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: VolumeDriver.Create: Device not found" error_type="plugins.statusError" module=api time="2017-12-05T18:24:44.031939788Z" level=error msg="Handler for POST /v1.32/volumes/create returned error: create test: VolumeDriver.Create: Device not found" time="2017-12-05T18:24:44.031971116Z" level=debug msg="FIXME: Got an API for which error does not match any expected type!!!: VolumeDriver.Create: Device not found" error_type="plugins.statusError" module=api

VM Details:

docker@gm-l-doc-05:/var/log$ uname -a Linux gm-l-doc-05 4.4.103-boot2docker #1 SMP Sun Dec 3 14:09:32 UTC 2017 x86_64 GNU/Linux

docker@gm-l-doc-05:/var/log$ docker -v Docker version 17.09.1-ce-rc1, build 2d63290 (also tried with their latest 17.11.0 build)

docker@gm-l-doc-05:/var/log$ vmware-toolbox-cmd -v 10.0.0.50046 (build-3000743)

Any help is appreciated.

Many Thanks

Darren Smith

[shuklanirdesh82]

@smithd13 can you please share the output of following command?

esxcli storage guestvol status

[smithd13]

Hi

[root@gm-l-thw-esx-02:/var/log/vmware] esxcli storage guestvol status === Service: Version: 0.18.087b0d7-0.0.1 Status: Running Pid: 68765 Port: 1019 LogConfigFile: /etc/vmware/vmdkops/log_config.json LogFile: /var/log/vmware/vmdk_ops.log LogLevel: INFO === Authorization Config DB: DB_LocalPath: N/A DB_Mode: NotConfigured (no local DB, no symlink to shared DB) DB_SharedLocation: N/A

The Hyps are running: VMware ESXi, 6.5.0, 5969303 - storage is Fibre Channel attached with a Pure Storage SAN. There is no VSAN. We also use NSX.

I haven't configured any of the auth yet, so its just using the standalone configuration, hence the auth-db messages in the vmdk_ops.log:

As you can see however, it is creating the vmdk fine and trying to attach it to the VM:

12/05/17 18:02:38 68765 [MainThread] [INFO ] Started new thread : 949662627584 with target <function execRequestThread at 0xdd1a8909d8> and args (11, 79407, b'{"cmd":"get","details":{"Name":"test"},"version":"2"}') 12/05/17 18:02:38 68765 [Thread-28] [INFO ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access 12/05/17 18:02:40 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] executeRequest 'get' completed with ret={'Error': 'Volume test not found (file: /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk)'} 12/05/17 18:02:40 68765 [MainThread] [INFO ] Started new thread : 949662627584 with target <function execRequestThread at 0xdd1a8909d8> and args (10, 79407, b'{"cmd":"create","details":{"Name":"test","Opts":{"fstype":"ext4"}},"version":"2"}') 12/05/17 18:02:40 68765 [Thread-29] [INFO ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] createVMDK: /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk opts={'fstype': 'ext4'} vm_name=gm-l-doc-02 vm_uuid=423a2ef2-2df8-0c97-87b9-38863f96d648 tenant_uuid=11111111-1111-1111-1111-111111111111 datastore_url=/vmfs/volumes/516fefa1-79ed04f1-d551-78acc0fa9a4e 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [WARNING] Volume size not specified 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] No access control, skipping volumes tracing in auth DB 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] executeRequest 'create' completed with ret=None 12/05/17 18:02:41 68765 [MainThread] [INFO ] Started new thread : 949662627584 with target <function execRequestThread at 0xdd1a8909d8> and args (11, 79407, b'{"cmd":"attach","details":{"Name":"test"},"version":"2"}') 12/05/17 18:02:41 68765 [Thread-30] [INFO ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] disk_attach: VMDK /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk to VM 'gm-l-doc-02' , bios uuid = 423a2ef2-2df8-0c97-87b9-38863f96d648, VC uuid=503ad4eb-6ff4-4cea-b735-c599aa979ff0) 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] Found vm name='gm-l-doc-02' 12/05/17 18:02:41 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] Attaching /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk as independent_persistent 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] Disk /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk successfully attached. controller pci_slot_number=160, disk_slot=1 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] executeRequest 'attach' completed with ret={'ControllerPciSlotNumber': '160', 'Unit': '1'} 12/05/17 18:02:42 68765 [MainThread] [INFO ] Started new thread : 949662627584 with target <function execRequestThread at 0xdd1a8909d8> and args (10, 79407, b'{"cmd":"detach","details":{"Name":"test"},"version":"2"}') 12/05/17 18:02:42 68765 [Thread-31] [INFO ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] disk_detach: VMDK /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk to VM 'gm-l-doc-02' , bios uuid = 423a2ef2-2df8-0c97-87b9-38863f96d648, VC uuid=503ad4eb-6ff4-4cea-b735-c599aa979ff0) 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] Found vm name='gm-l-doc-02' 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] Disk detached /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk 12/05/17 18:02:42 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] executeRequest 'detach' completed with ret=None 12/05/17 18:02:42 68765 [MainThread] [INFO ] Started new thread : 949662627584 with target <function execRequestThread at 0xdd1a8909d8> and args (11, 79407, b'{"cmd":"remove","details":{"Name":"test"},"version":"2"}') 12/05/17 18:02:42 68765 [Thread-32] [INFO ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access 12/05/17 18:02:43 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] removeVMDK: /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk 12/05/17 18:02:43 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] *** cleanVMDK: /vmfs/volumes/THW_PURE_LINUX-01/dockvols/_DEFAULT/test.vmdk 12/05/17 18:02:43 68765 [gm-l-doc-02-THW_PURE_LINUX-01._DEFAULT.test] [INFO ] executeRequest 'remove' completed with ret=None

Thanks

Darren

[shuklanirdesh82]

https://github.com/vmware/docker-volume-vsphere/issues/2023#issuecomment-349434535

Thanks Darren! This issue was fixed through #1978. Please try vDVS 0.19 release and confirm from your side.

The reported issue is similar to #1969.

[smithd13]

haha, it was released the day after my colleague fetched the VIB to deploy today :-)

I'll get it deployed tomorrow and will let you know. Thanks

[govint]

2025 to document the compat req. between the plugin and the ESX host service from vDVS 0.19 onwards.

[smithd13]

Works fine now! Thanks for your help.