Skip to content
This repository has been archived by the owner on Nov 9, 2020. It is now read-only.

New install unable to create and mount volumes #2048

Closed
rsjorslev opened this issue Jan 2, 2018 · 9 comments
Closed

New install unable to create and mount volumes #2048

rsjorslev opened this issue Jan 2, 2018 · 9 comments
Assignees
@govint
Labels
customer P0
Milestone
Wonder woman

Comments

@rsjorslev
Copy link

ESXi:
VMware ESXi, 6.5.0, 5969303 (SuperMicro Xeon-D system)
Datastore:
VMFS6, local SSD datastore (single host attached)
VM:
Ubuntu 16.04.03 (HW version 13 - also tried version 9 - same results) 2GB ram, 30GB VMDK for OS (LSI controller)
Docker version:
Server:
Engine:
Version: 17.12.0-ce
API version: 1.35 (minimum version 1.12)
Go version: go1.9.2
Git commit: c97c6d6
Built: Wed Dec 27 20:09:53 2017
OS/Arch: linux/amd64
Experimental: false
VDVS Version:
[root@esx01:~] esxcli storage guestvol status
=== Service:
Version: 0.20.15f5e1d-0.0.1
Status: Running
Pid: 71845
Port: 1019
LogConfigFile: /etc/vmware/vmdkops/log_config.json
LogFile: /var/log/vmware/vmdk_ops.log
LogLevel: DEBUG
=== Authorization Config DB:
DB_SharedLocation: N/A
DB_LocalPath: N/A
DB_Mode: NotConfigured (no local DB, no symlink to shared DB)

Steps to Reproduce:

  1. After installing VIB and plugin as described in the documentation create a volume as such:

docker volume create --driver=vsphere --name=volume002

Fails with:

Error response from daemon: create volume001: VolumeDriver.Create: Server returned an error: TypeError("'NoneType' object is not subscriptable",)

An actual VMDK file is created in dockvols under _DEFAULT

  1. Trying to remove the volume:

docker volume rm volume002@esx01-ssd02

Fails with:

Error response from daemon: unable to remove volume: remove volume002@esx01-ssd02: VolumeDriver.Remove: Failed to remove volume: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume002.vmdk

Triage:
vmdk_ops.log with DEBUG mode enabled:

01/02/18 15:58:36 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 10, buffer 'b'{"cmd":"get","details":{"Name":"volume001"},"version":"2"}''
01/02/18 15:58:36 71845 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 15:58:36 71845 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 15:58:36 71845 [MainThread] [INFO   ] Started new thread : 356221134592 with target <function execRequestThread at 0x52eec6cb70> and args (10, 72882, b'{"cmd":"get","details":{"Name":"volume001"},"version":"2"}')
01/02/18 15:58:36 71845 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 356105181984)>, <Thread(VMChangeListener, started daemon 356191966976)>, <Thread(Thread-77, started 356221134592)>]
01/02/18 15:58:36 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] execRequestThread: req={'cmd': 'get', 'version': '2', 'details': {'Name': 'volume001'}}
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 15:58:36 71845 [Thread-77] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] returning default info
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 15:58:36 71845 [Thread-77] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] Authorize: cmd=get opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 15:58:37 71845 [Thread-77] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] getVMDK: vmdk_path=/vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk vol_name=volume001, datastore=esx01-ssd02
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] getVMDK: file_exist=0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] executeRequest 'get' completed with ret={'Error': 'Volume volume001 not found (file: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk)'}
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] After decr: counter.value=0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Setting counter event
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 9, buffer 'b'{"cmd":"create","details":{"Name":"volume001","Opts":{"fstype":"ext4","size":"20gb"}},"version":"2"}''
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 15:58:37 71845 [MainThread] [INFO   ] Started new thread : 356221134592 with target <function execRequestThread at 0x52eec6cb70> and args (9, 72882, b'{"cmd":"create","details":{"Name":"volume001","Opts":{"fstype":"ext4","size":"20gb"}},"version":"2"}')
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 356105181984)>, <Thread(VMChangeListener, started daemon 356191966976)>, <Thread(Thread-78, started 356221134592)>]
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] execRequestThread: req={'cmd': 'create', 'version': '2', 'details': {'Opts': {'fstype': 'ext4', 'size': '20gb'}, 'Name': 'volume001'}}
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 15:58:37 71845 [Thread-78] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] returning default info
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Authorize: cmd=create opts=`{'fstype': 'ext4', 'size': '20gb'}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 15:58:37 71845 [Thread-78] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] *** createVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk opts={'fstype': 'ext4', 'size': '20gb'} vm_name=docker01 vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb tenant_uuid=11111111-1111-1111-1111-111111111111 datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] volume_datastore_path=[esx01-ssd02] dockvols/_DEFAULT/volume001.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Successfully created /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk volume
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] add to volumes table(11111111-1111-1111-1111-111111111111 /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76 volume001 20480)
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Skipping Add volume to DB 11111111-1111-1111-1111-111111111111 (allow_all_access)
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] No access control, skipping volumes tracing in auth DB
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] executeRequest 'create' completed with ret=None
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] After decr: counter.value=0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Setting counter event
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 10, buffer 'b'{"cmd":"attach","details":{"Name":"volume001"},"version":"2"}''
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 15:58:37 71845 [MainThread] [INFO   ] Started new thread : 356221134592 with target <function execRequestThread at 0x52eec6cb70> and args (10, 72882, b'{"cmd":"attach","details":{"Name":"volume001"},"version":"2"}')
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 356105181984)>, <Thread(VMChangeListener, started daemon 356191966976)>, <Thread(Thread-79, started 356221134592)>]
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] execRequestThread: req={'cmd': 'attach', 'version': '2', 'details': {'Name': 'volume001'}}
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 15:58:37 71845 [Thread-79] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] returning default info
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Authorize: cmd=attach opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 15:58:37 71845 [Thread-79] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] *** disk_attach: VMDK /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk to VM 'docker01' , bios uuid = 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1)
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Found vm name='docker01'
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Attaching /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk as independent_persistent
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] findDeviceByPath: Looking for device /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] d.backing.fileName [esx01-ssd02] docker01/docker01.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] findDeviceByPath: datastore=esx01-ssd02, backing_disk=docker01/docker01.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] dvol_dir=/vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT datastore_prefix=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/ real_vol_dir=dockvols/11111111-1111-1111-1111-111111111111
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] backing_disk=docker01/docker01.vmdk virtual_disk=dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] d.backing.fileName [esx01-ssd02] dockvols/11111111-1111-1111-1111-111111111111/woohoo.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] findDeviceByPath: datastore=esx01-ssd02, backing_disk=dockvols/11111111-1111-1111-1111-111111111111/woohoo.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] dvol_dir=/vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT datastore_prefix=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/ real_vol_dir=dockvols/11111111-1111-1111-1111-111111111111
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] backing_disk=dockvols/11111111-1111-1111-1111-111111111111/woohoo.vmdk virtual_disk=dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] idx=0 controller_key=1001 avail_slots=14
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Find an available slot: controller_key = 1001 slot = 1
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Find an available disk slot, controller_key=1001, slot_id=1
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [ERROR  ] Unhandled Exception:
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1838, in execRequestThread
    opts=opts)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1160, in executeRequest
    bios_uuid=vm_uuid, vc_uuid=vc_uuid)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 751, in attachVMDK
    return apply_action_VMDK(disk_attach, vmdk_path, vm_name, bios_uuid, vc_uuid)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 775, in apply_action_VMDK
    return action(vmdk_path, vm)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1597, in disk_attach
    vm_dev_info = dev_info(disk_slot, pci_slot_number)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1302, in dev_info
    'ControllerPciSlotNumber': pci_bus_slot_number[0],
TypeError: 'NoneType' object is not subscriptable
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] After decr: counter.value=0
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Setting counter event
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 9, buffer 'b'{"cmd":"remove","details":{"Name":"volume001"},"version":"2"}''
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 15:58:37 71845 [MainThread] [INFO   ] Started new thread : 356221134592 with target <function execRequestThread at 0x52eec6cb70> and args (9, 72882, b'{"cmd":"remove","details":{"Name":"volume001"},"version":"2"}')
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 356105181984)>, <Thread(VMChangeListener, started daemon 356191966976)>, <Thread(Thread-80, started 356221134592)>]
01/02/18 15:58:37 71845 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] execRequestThread: req={'cmd': 'remove', 'version': '2', 'details': {'Name': 'volume001'}}
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 15:58:37 71845 [Thread-80] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] returning default info
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Authorize: cmd=remove opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 15:58:37 71845 [Thread-80] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] *** removeVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk
01/02/18 15:58:37 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] *** cleanVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk
01/02/18 15:58:38 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] Open /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk failed - 4008
01/02/18 15:58:39 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] *** removeVMDK: Retrying removal on error: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:39 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Running cmd /bin/vmkvsitools lsof
01/02/18 15:58:39 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Volume open descriptor: cartel=72882, name=vmx, type=FILE, fd=115, desc=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001-flat.vmdk
01/02/18 15:58:40 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] *** removeVMDK: Retrying removal on error: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:40 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Running cmd /bin/vmkvsitools lsof
01/02/18 15:58:40 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Volume open descriptor: cartel=72882, name=vmx, type=FILE, fd=115, desc=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001-flat.vmdk
01/02/18 15:58:41 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] *** removeVMDK: Retrying removal on error: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:41 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Running cmd /bin/vmkvsitools lsof
01/02/18 15:58:41 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Volume open descriptor: cartel=72882, name=vmx, type=FILE, fd=115, desc=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001-flat.vmdk
01/02/18 15:58:42 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] *** removeVMDK: Retrying removal on error: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:42 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Running cmd /bin/vmkvsitools lsof
01/02/18 15:58:42 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Volume open descriptor: cartel=72882, name=vmx, type=FILE, fd=115, desc=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001-flat.vmdk
01/02/18 15:58:43 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] *** removeVMDK: Retrying removal on error: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk
01/02/18 15:58:43 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Running cmd /bin/vmkvsitools lsof
01/02/18 15:58:43 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] Volume open descriptor: cartel=72882, name=vmx, type=FILE, fd=115, desc=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001-flat.vmdk
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] Open /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk failed - 4008
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [WARNING] Failed to clean /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/volume001.vmdk file: {'Error': 'Failed to remove volume: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk'}
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.volume001
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [INFO   ] executeRequest 'remove' completed with ret={'Error': 'Failed to remove volume: Error caused by file /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume001.vmdk'}
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] After decr: counter.value=0
01/02/18 15:58:46 71845 [docker01-esx01-ssd02._DEFAULT.volume001] [DEBUG  ] Setting counter event
@govint
Copy link
Contributor

govint commented Jan 2, 2018

@rsjorslev, can you post the SCSI controller configuration of the VM you are using to run the containers? Is there a pvscsi controller configured? If so can you post its configuration.

@rsjorslev
Copy link
Author

Hi @govint, here is the full vmx from that VM:

.encoding = "UTF-8"
config.version = "8"
virtualHW.version = "13"
svga.present = "TRUE"
vmci0.present = "TRUE"
hpet0.present = "TRUE"
floppy0.present = "FALSE"
numvcpus = "2"
memSize = "4096"
sched.cpu.units = "mhz"
sched.cpu.latencySensitivity = "normal"
powerType.suspend = "soft"
tools.upgrade.policy = "upgradeAtPowerCycle"
scsi0.virtualDev = "lsilogic"
scsi0.present = "TRUE"
ide1:0.autodetect = "TRUE"
ide1:0.deviceType = "cdrom-raw"
ide1:0.clientDevice = "TRUE"
ide1:0.present = "TRUE"
scsi0:0.deviceType = "scsi-hardDisk"
scsi0:0.fileName = "docker01.vmdk"
sched.scsi0:0.shares = "normal"
sched.scsi0:0.throughputCap = "off"
scsi0:0.present = "TRUE"
ethernet0.virtualDev = "e1000"
ethernet0.networkName = "L111-Infrastructure01"
ethernet0.addressType = "vpx"
ethernet0.generatedAddress = "00:50:56:b2:0d:7a"
ethernet0.wakeOnPcktRcv = "FALSE"
ethernet0.present = "TRUE"
displayName = "docker01"
guestOS = "ubuntu-64"
bios.bootOrder = "cdrom"
toolScripts.afterPowerOn = "TRUE"
toolScripts.afterResume = "TRUE"
toolScripts.beforeSuspend = "TRUE"
toolScripts.beforePowerOff = "TRUE"
tools.syncTime = "TRUE"
tools.guest.desktop.autolock = "FALSE"
uuid.bios = "42 32 88 23 bc f7 ac ed-6d 5a e2 a5 dd c3 c5 fb"
vc.uuid = "50 32 e1 bb 0e 93 d9 5e-7b 96 7b 3d de 75 4a f1"
ehci.pcislotnumber = "-1"
ethernet0.bsdname = "en0"
ethernet0.connectiontype = "nat"
ethernet0.displayname = "Ethernet"
ethernet0.linkstatepropagation.enable = "FALSE"
ethernet0.pcislotnumber = "33"
gui.fullscreenatpoweron = "FALSE"
gui.viewmodeatpoweron = "windowed"
hgfs.linkrootshare = "TRUE"
hgfs.maprootshare = "TRUE"
isolation.tools.hgfs.disable = "FALSE"
msg.autoanswer = "true"
nvram = "docker01.nvram"
pcibridge0.pcislotnumber = "17"
pcibridge0.present = "TRUE"
pcibridge4.functions = "8"
pcibridge4.pcislotnumber = "21"
pcibridge4.present = "TRUE"
pcibridge4.virtualdev = "pcieRootPort"
pcibridge5.functions = "8"
pcibridge5.pcislotnumber = "22"
pcibridge5.present = "TRUE"
pcibridge5.virtualdev = "pcieRootPort"
pcibridge6.functions = "8"
pcibridge6.pcislotnumber = "23"
pcibridge6.present = "TRUE"
pcibridge6.virtualdev = "pcieRootPort"
pcibridge7.functions = "8"
pcibridge7.pcislotnumber = "24"
pcibridge7.present = "TRUE"
pcibridge7.virtualdev = "pcieRootPort"
proxyapps.publishtohost = "FALSE"
remotedisplay.vnc.enabled = "FALSE"
remotedisplay.vnc.port = "5900"
replay.supported = "FALSE"
scsi0.pcislotnumber = "16"
usb.pcislotnumber = "-1"
uuid.action = "create"
virtualhw.productcompatibility = "hosted"
vmci0.pcislotnumber = "35"
vmotion.checkpointfbsize = "4194304"
migrate.hostLog = "docker01-14d7918b.hlog"
sched.cpu.min = "0"
sched.cpu.shares = "normal"
sched.mem.min = "0"
sched.mem.minSize = "0"
sched.mem.shares = "normal"
migrate.encryptionMode = "opportunistic"
vcpu.hotadd = "TRUE"
mem.hotadd = "TRUE"
sched.swap.derivedName = "/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01-a2efdab7.vswp"
uuid.location = "56 4d 31 9a da f4 f4 fb-14 4c 1e 8a 3c db ac 7c"
scsi0:0.redo = ""
vmci0.id = "-574372357"
monitor.phys_bits_used = "43"
cleanShutdown = "FALSE"
softPowerOff = "FALSE"
scsi1.pciSlotNumber = "160"
scsi1.virtualDev = "pvscsi"
scsi1.present = "TRUE"
config.readOnly = "FALSE"
scsi1.sasWWID = "50 05 05 63 bc f7 ad e0"
acpi.smbiosVersion2.7 = "FALSE"
vmotion.checkpointSVGAPrimarySize = "4194304"
svga.guestBackedPrimaryAware = "TRUE"
scsi1:0.deviceType = "scsi-hardDisk"
scsi1:0.fileName = "/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/woohoo.vmdk"
scsi1:0.mode = "independent-persistent"
scsi1:0.present = "TRUE"
scsi1:0.redo = ""
scsi1:2.deviceType = "scsi-hardDisk"
scsi1:2.fileName = "/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/dockvols/11111111-1111-1111-1111-111111111111/volume002.vmdk"
scsi1:2.mode = "independent-persistent"
scsi1:2.present = "TRUE"
scsi1:2.redo = ""

@rsjorslev
Copy link
Author

scsi0 is the lsi controller added to the VM when it was created and scsi1 is the controller added by the driver.

@govint
Copy link
Contributor

govint commented Jan 2, 2018

@rsjorslev, thanks for posting the VMX config, the logs don;t show a PVSCSI controller being added. Most likely the VIB was used earlier and volumes were created and used? The code seems to be unable to find the PVSCSI controller in the VMX extra-config (in the code) and hence None being used later. Suggest removing the disk and the PVSCSI controller manually from the VMX config and they retry the volume attach via docker.

@rsjorslev
Copy link
Author

Just tried deleting the disk and pvscsi controller from the VM/VMX and then tried to create a new volume but got this:

01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 10, buffer 'b'{"cmd":"get","details":{"Name":"vol01"},"version":"2"}''
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 19:08:00 76262 [MainThread] [INFO   ] Started new thread : 593753995008 with target <function execRequestThread at 0x8a3cd67b70> and args (10, 77528, b'{"cmd":"get","details":{"Name":"vol01"},"version":"2"}')
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 593637518112)>, <Thread(VMChangeListener, started daemon 593724827392)>, <Thread(Thread-29, started 593753995008)>]
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] execRequestThread: req={'version': '2', 'cmd': 'get', 'details': {'Name': 'vol01'}}
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 19:08:00 76262 [Thread-29] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] returning default info
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Authorize: cmd=get opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 19:08:00 76262 [Thread-29] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] getVMDK: vmdk_path=/vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk vol_name=vol01, datastore=esx01-ssd02
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] getVMDK: file_exist=0
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] executeRequest 'get' completed with ret={'Error': 'Volume vol01 not found (file: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk)'}
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] After decr: counter.value=0
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Setting counter event
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 9, buffer 'b'{"cmd":"create","details":{"Name":"vol01","Opts":{"fstype":"ext4"}},"version":"2"}''
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 19:08:00 76262 [MainThread] [INFO   ] Started new thread : 593753995008 with target <function execRequestThread at 0x8a3cd67b70> and args (9, 77528, b'{"cmd":"create","details":{"Name":"vol01","Opts":{"fstype":"ext4"}},"version":"2"}')
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 593637518112)>, <Thread(VMChangeListener, started daemon 593724827392)>, <Thread(Thread-30, started 593753995008)>]
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] execRequestThread: req={'version': '2', 'cmd': 'create', 'details': {'Opts': {'fstype': 'ext4'}, 'Name': 'vol01'}}
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 19:08:00 76262 [Thread-30] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] returning default info
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Authorize: cmd=create opts=`{'fstype': 'ext4'}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 19:08:00 76262 [Thread-30] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] *** createVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk opts={'fstype': 'ext4'} vm_name=docker01 vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb tenant_uuid=11111111-1111-1111-1111-111111111111 datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] volume_datastore_path=[esx01-ssd02] dockvols/_DEFAULT/vol01.vmdk
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Successfully created /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk volume
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [WARNING] Volume size not specified
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] add to volumes table(11111111-1111-1111-1111-111111111111 /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76 vol01 100)
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Skipping Add volume to DB 11111111-1111-1111-1111-111111111111 (allow_all_access)
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] No access control, skipping volumes tracing in auth DB
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] executeRequest 'create' completed with ret=None
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] After decr: counter.value=0
01/02/18 19:08:00 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Setting counter event
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 10, buffer 'b'{"cmd":"attach","details":{"Name":"vol01"},"version":"2"}''
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 19:08:00 76262 [MainThread] [INFO   ] Started new thread : 593753995008 with target <function execRequestThread at 0x8a3cd67b70> and args (10, 77528, b'{"cmd":"attach","details":{"Name":"vol01"},"version":"2"}')
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 593637518112)>, <Thread(VMChangeListener, started daemon 593724827392)>, <Thread(Thread-31, started 593753995008)>]
01/02/18 19:08:00 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] execRequestThread: req={'version': '2', 'cmd': 'attach', 'details': {'Name': 'vol01'}}
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 19:08:00 76262 [Thread-31] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] returning default info
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 19:08:00 76262 [Thread-31] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Authorize: cmd=attach opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 19:08:01 76262 [Thread-31] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] *** disk_attach: VMDK /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk to VM 'docker01' , bios uuid = 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1)
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] Found vm name='docker01'
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] Attaching /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk as independent_persistent
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] findDeviceByPath: Looking for device /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] d.backing.fileName [esx01-ssd02] docker01/docker01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] findDeviceByPath: datastore=esx01-ssd02, backing_disk=docker01/docker01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] dvol_dir=/vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT datastore_prefix=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/ real_vol_dir=dockvols/11111111-1111-1111-1111-111111111111
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] backing_disk=docker01/docker01.vmdk virtual_disk=dockvols/11111111-1111-1111-1111-111111111111/vol01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] Adding a PVSCSI controller
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Added a PVSCSI controller, controller_id=1001
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [ERROR  ] Unhandled Exception:
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1838, in execRequestThread
    opts=opts)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1160, in executeRequest
    bios_uuid=vm_uuid, vc_uuid=vc_uuid)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 751, in attachVMDK
    return apply_action_VMDK(disk_attach, vmdk_path, vm_name, bios_uuid, vc_uuid)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 775, in apply_action_VMDK
    return action(vmdk_path, vm)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1558, in disk_attach
    controller_key, pci_slot_number[0])
TypeError: 'NoneType' object is not subscriptable
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] After decr: counter.value=0
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Setting counter event
01/02/18 19:08:01 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op returns 9, buffer 'b'{"cmd":"remove","details":{"Name":"vol01"},"version":"2"}''
01/02/18 19:08:01 76262 [MainThread] [DEBUG  ] After incr: counter.value=1
01/02/18 19:08:01 76262 [MainThread] [DEBUG  ] Clearing counter event
01/02/18 19:08:01 76262 [MainThread] [INFO   ] Started new thread : 593753995008 with target <function execRequestThread at 0x8a3cd67b70> and args (9, 77755, b'{"cmd":"remove","details":{"Name":"vol01"},"version":"2"}')
01/02/18 19:08:01 76262 [MainThread] [DEBUG  ] Currently active threads: [<_MainThread(MainThread, started 593637518112)>, <Thread(VMChangeListener, started daemon 593724827392)>, <Thread(Thread-32, started 593753995008)>]
01/02/18 19:08:01 76262 [MainThread] [DEBUG  ] lib.vmci_get_one_op: waiting for new request...
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] execRequestThread: req={'version': '2', 'cmd': 'remove', 'details': {'Name': 'vol01'}}
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] execRequestThread: client protocol version=2
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_url_from_config_path: config_path=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76/docker01/docker01.vmx config_ds_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_name: datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_name: res=['esx01-ssd02']
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] executeRequest: vm_datastore = esx01-ssd02, vm_datastore_url = /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Checking DB mode for /etc/vmware/vmdkops/auth-db...
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Config DB does not exist. mode NotConfigured
01/02/18 19:08:01 76262 [Thread-32] [INFO   ] Auth DB /etc/vmware/vmdkops/auth-db is missing, allowing all access
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] auth.get_tenant: allow_all: True, uuid: 42328823-bcf7-aced-6d5a-e2a5ddc3c5fb
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] returning default info
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] auth_api.get_default_datastore_url: for tenant with name=_DEFAULT
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_name: datastore_url=_VM_DS://
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_name: datastore_name=_VM_DS path to /vmfs/volumes/datastore_name does not exist
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] init_datastoreCache:  [('esx01-boot', '/vmfs/volumes/5a171f4d-90721f20-6a21-ac1f6b1b5c76', '/vmfs/volumes/esx01-boot/dockvols'), ('esx01-nvme', '/vmfs/volumes/5a1c477e-446e2ec1-64f3-ac1f6b1b5c76', '/vmfs/volumes/esx01-nvme/dockvols'), ('esx01-ssd01', '/vmfs/volumes/5a1ffd22-a70948ae-96ef-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd01/dockvols'), ('esx01-ssd02', '/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd02/dockvols'), ('esx01-ssd03', '/vmfs/volumes/5a298fbe-44acfc9d-8590-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd03/dockvols'), ('esx01-ssd04', '/vmfs/volumes/5a298fe2-c49798fd-651c-ac1f6b1b5c76', '/vmfs/volumes/esx01-ssd04/dockvols')]
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Returning /vmfs/volumes/esx01-boot/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Returning /vmfs/volumes/esx01-nvme/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd01/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols, returning
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd03/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Returning /vmfs/volumes/esx01-ssd04/dockvols, path isn't created yet.
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] get_datastore_name: After refresh get datastore_name=_VM_DS
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] executeRequest: vm uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb VC uuid=5032e1bb-0e93-d95e-7b96-7b3dde754af1 name=docker01, tenant_name=_DEFAULT, default_datastore=_VM_DS
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] executeRequest: vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, vm_name=docker01, tenant_name=11111111-1111-1111-1111-111111111111, tenant_uuid=_DEFAULT, default_datastore_url=_VM_DS:// datastore_url=_VM_DS://
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Authorize: cmd=remove opts=`{}' vm_uuid=42328823-bcf7-aced-6d5a-e2a5ddc3c5fb, datastore_url=_VM_DS://, privilege_ds_url=_VM_DS://, vm_datastore_url=/vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] auth_api.get_tenant_from_db name=_DEFAULT
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] auth_data.get_tenant: tenant_name=_DEFAULT
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] Found /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT, returning
01/02/18 19:08:01 76262 [Thread-32] [DEBUG  ] executeRequest for tenant _DEFAULT with path /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Trying to acquire lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Acquired lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] *** removeVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] *** cleanVMDK: /vmfs/volumes/esx01-ssd02/dockvols/_DEFAULT/vol01.vmdk
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] remove volumes from volumes table(11111111-1111-1111-1111-111111111111 /vmfs/volumes/5a213d55-c8819bdd-dea9-ac1f6b1b5c76 vol01)
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Skipping Rm volume from DB 11111111-1111-1111-1111-111111111111 (allow_all_access)
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Released lock: esx01-ssd02._DEFAULT.vol01
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [INFO   ] executeRequest 'remove' completed with ret=None
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] lib.vmci_reply: VMCI replied with errcode 0
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] After decr: counter.value=0
01/02/18 19:08:01 76262 [docker01-esx01-ssd02._DEFAULT.vol01] [DEBUG  ] Setting counter event

it still seems to not find the controller - at least it looks like its always when it picks the first item in the array no matter the type of operation.

@rsjorslev
Copy link
Author

@govint i Can provide remote access to the setup if required over zoom - just let me know.

@govint
Copy link
Contributor

govint commented Jan 6, 2018

Debugged this yesterday and the root cause seems a bit strange where, the fields of the VM configuration - key names - are in lower case on the ESX 6.5 U1 host. Since the code is explicitly searching for a specific string. the search fails and a None value is returned for the scsi controller's slot and bus number fields.

Will post the change for review today,

@rsjorslev
Copy link
Author

I can confirm that the fix from @govint works as expected, i can now create, delete and mount volumes on 6.5 U1 environment.

@shuklanirdesh82
Copy link
Contributor

fixed through #2051

# for free to subscribe to this conversation on GitHub. Already have an account? #.
Assignees

@govint govint

Labels
customer P0
Projects
None yet
Milestone
Wonder woman
Development

No branches or pull requests
3 participants
@rsjorslev @govint @shuklanirdesh82