Clone of existing volume fails

[ashahi1]

Clone of an existing volume fails with error - Error response from daemon: create CloneVolume: VolumeDriver.Create: Server returned an error: TypeError("'NoneType' object does not support item assignment",)

Steps:

1. Create a volume

   root@promc-2n-dhcp105-23:~# docker volume create -d vsphere --name MyVolume
   MyVolume
   root@promc-2n-dhcp105-23:~# docker volume ls
   DRIVER              VOLUME NAME
   vsphere:latest      MyVolume@Datastore1
   vfile:latest        vfilevolume488530

2. Clone a volume to create a new volume

   
   root@promc-2n-dhcp105-23:~# docker volume create --driver=vsphere --name=CloneVolume -o clone-from=MyVolume -o access=read-only
   Error response from daemon: create CloneVolume: VolumeDriver.Create: Server returned an error: TypeError("'NoneType' object does not support item assignment",)
   root@promc-2n-dhcp105-23:~#

vmdk_ops.log

02/06/18 19:22:55 1703101 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.CloneVolume] [INFO ] *** cloneVMDK: /vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/CloneVolume.vmdk opts = {'acc 02/06/18 19:22:55 1703101 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.CloneVolume] [WARNING] Internal: Tenant name symlink not found for path /vmfs/volumes/Datastore1/dockvols/_DEFAULT 02/06/18 19:22:55 1703101 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.CloneVolume] [ERROR ] Failed to access b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/CloneVolume-a84079d57d3e3 Traceback (most recent call last): File "/usr/lib/vmware/vmdkops/Python/kvESX.py", line 297, in load with open(meta_file, "r") as fh: FileNotFoundError: [Errno 2] No such file or directory: b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/CloneVolume-a84079d57d3e3be3.vmfd' 02/06/18 19:22:55 1703101 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.CloneVolume] [ERROR ] Unhandled Exception: Traceback (most recent call last): File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1843, in execRequestThread opts=opts) File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1148, in executeRequest vm_datastore=vm_datastore) File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 208, in createVMDK vm_datastore=vm_datastore) File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 394, in cloneVMDK vol_meta[kv.CREATED_BY] = vm_name TypeError: 'NoneType' object does not support item assignment

vmdk_ops.log: 
[vmdk_ops.txt](https://github.com/vmware/vsphere-storage-for-docker/files/1700618/vmdk_ops.txt)

[govint]

The earliest logs in vmdk_ops starts at 02/05/18 20:56:37 and doesn't have the exception in it. If its repro'able can we get a new repro and get those logs?

KV seems to have error'ed getting the volume KV data and hence the none-type error.

[ashahi1]

@govint I have updated the new logs. Can you please take a look at it again?

Volume name: testvolume@Datastore1 Cloned volume: TestCloneVolume

Docker cli:

root@promc-2n-dhcp105-23:~# docker volume create -d vsphere --name testvol2
testvol2
root@promc-2n-dhcp105-23:~#
root@promc-2n-dhcp105-23:~# docker volume create -d vsphere --name testvolume
testvolume
root@promc-2n-dhcp105-23:~#
root@promc-2n-dhcp105-23:~# docker volume ls
DRIVER              VOLUME NAME
vsphere:latest      testvolume@Datastore1
root@promc-2n-dhcp105-23:~#
root@promc-2n-dhcp105-23:~# docker volume create --driver=vsphere --name=TestCloneVolume -o clone-from=testvolume -o access=read-only
Error response from daemon: create TestCloneVolume: VolumeDriver.Create: Server returned an error: TypeError("'NoneType' object does not support item assignment",)
root@promc-2n-dhcp105-23:~#

Admin cli:

[root@sc2-rdops-vm09-dhcp-35-191:~] esxcli storage guestvol volume ls
Volume           Datastore   VMGroup   Capacity  Used  Filesystem  Policy  Disk Format  Attached-to  Access      Attach-as               Created By         Created Date
---------------  ----------  --------  --------  ----  ----------  ------  -----------  -----------  ----------  ----------------------  -----------------  ------------------------
testvolume       Datastore1  _DEFAULT  100MB     13MB  ext4        N/A     thin         detached     read-write  independent_persistent  Ubuntu.16.04.vsan  Thu Feb  8 03:40:50 2018
TestCloneVolume  Datastore1  _DEFAULT  100MB     13MB  N/A         N/A     N/A          detached     read-write  independent_persistent  N/A                N/A
[root@sc2-rdops-vm09-dhcp-35-191:~]

Logs: vmdk_ops.log vsphere-storage-for-docker.log

[govint]

@ashahi1, sorry the vmdk_ops.log is now really outdated, the last log is from 11/29/17 22:05:47. Can you upload the one that has the errors in it.

So the volume is getting created ok but the KV file is somehow not accessible.

[ashahi1]

@govint

I clearly see the errors in the vmdk_ops.log

02/08/18 03:42:29 2170987 [MainThread] [INFO   ] Started new thread : 451980121856 with target <function execRequestThread at 0x693a64db70> and args (10, 2151986, b'{"cmd":"get","details":{"Name":"TestCloneVolume"},"version":"2"}')
02/08/18 03:42:29 2170987 [Thread-94] [INFO   ] db_mode='SingleNode (local DB exists)' cmd=get opts={} vmgroup=_DEFAULT datastore_url=_VM_DS:// is allowed to execute
02/08/18 03:42:29 2170987 [Thread-94] [WARNING] Internal: Tenant name symlink not found for path /vmfs/volumes/Datastore1/dockvols/_DEFAULT
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [INFO   ] executeRequest 'get' completed with ret={'Error': 'Volume TestCloneVolume not found (file: /vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume.vmdk)'}
02/08/18 03:42:29 2170987 [MainThread] [INFO   ] Started new thread : 451980121856 with target <function execRequestThread at 0x693a64db70> and args (5, 2151986, b'{"cmd":"create","details":{"Name":"TestCloneVolume","Opts":{"access":"read-only","clone-from":"testvolume"}},"version":"2"}')
02/08/18 03:42:29 2170987 [Thread-95] [WARNING] Volume size not specified
02/08/18 03:42:29 2170987 [Thread-95] [INFO   ] db_mode='SingleNode (local DB exists)' cmd=create opts={'access': 'read-only', 'clone-from': 'testvolume'} vmgroup=_DEFAULT datastore_url=_VM_DS:// is allowed to execute
02/08/18 03:42:29 2170987 [Thread-95] [WARNING] Internal: Tenant name symlink not found for path /vmfs/volumes/Datastore1/dockvols/_DEFAULT
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [INFO   ] *** createVMDK: /vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume.vmdk opts={'access': 'read-only', 'clone-from': 'testvolume'} vm_name=Ubuntu.16.04.vsan vm_uuid=421fb415-a913-1fc3-ab3d-7917981e29f4 tenant_uuid=11111111-1111-1111-1111-111111111111 datastore_url=/vmfs/volumes/5a714ba8-3ac5a3a5-d917-02004fe65eb3
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [INFO   ] *** cloneVMDK: /vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume.vmdk opts = {'access': 'read-only', 'clone-from': 'testvolume'} vm_uuid=421fb415-a913-1fc3-ab3d-7917981e29f4 datastore_url=/vmfs/volumes/5a714ba8-3ac5a3a5-d917-02004fe65eb3 vm_datastore_url=/vmfs/volumes/5a714ba8-3ac5a3a5-d917-02004fe65eb3 vm_datastore=Datastore1
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [INFO   ] db_mode='SingleNode (local DB exists)' cmd=attach opts={} vmgroup=_DEFAULT datastore_url=/vmfs/volumes/5a714ba8-3ac5a3a5-d917-02004fe65eb3 is allowed to execute
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [WARNING] Internal: Tenant name symlink not found for path /vmfs/volumes/Datastore1/dockvols/_DEFAULT
02/08/18 03:42:29 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [INFO   ] db_mode='SingleNode (local DB exists)' cmd=create opts={'access': 'read-only', 'clone-from': 'testvolume', 'size': '100MB'} vmgroup=_DEFAULT datastore_url=/vmfs/volumes/5a714ba8-3ac5a3a5-d917-02004fe65eb3 is allowed to execute
02/08/18 03:42:30 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [ERROR  ] Failed to access b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume-9e43caa431e9ee7e.vmfd'
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/Python/kvESX.py", line 297, in load
    with open(meta_file, "r") as fh:
FileNotFoundError: [Errno 2] No such file or directory: b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume-9e43caa431e9ee7e.vmfd'
02/08/18 03:42:30 2170987 [Ubuntu.16.04.vsan-Datastore1._DEFAULT.TestCloneVolume] [ERROR  ] Unhandled Exception:
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1843, in execRequestThread
    opts=opts)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 1148, in executeRequest
    vm_datastore=vm_datastore)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 208, in createVMDK
    vm_datastore=vm_datastore)
  File "/usr/lib/vmware/vmdkops/bin/vmdk_ops.py", line 394, in cloneVMDK
    vol_meta[kv.CREATED_BY] = vm_name
TypeError: 'NoneType' object does not support item assignment
02/08/18 03:45:25 2175766 [MainThread] [INFO   ] Connecting to the local Service Instance as 'dcui' 
02/08/18 03:45:34 2175789 [MainThread] [INFO   ] Connecting to the local Service Instance as 'dcui' 
02/08/18 03:45:34 2175789 [MainThread] [ERROR  ] Failed to access b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume-9e43caa431e9ee7e.vmfd'
Traceback (most recent call last):
  File "/usr/lib/vmware/vmdkops/Python/kvESX.py", line 297, in load
    with open(meta_file, "r") as fh:
FileNotFoundError: [Errno 2] No such file or directory: b'/vmfs/volumes/Datastore1/dockvols/11111111-1111-1111-1111-111111111111/TestCloneVolume-9e43caa431e9ee7e.vmfd'

[carcampbell]

do you need more logs for this? We want to use this clone capability for backups of docker volumes since there doesn't seem to be other good options for that. I hit the same problem described here- the volume is actually created on the datastore but is corrupt/invalid. Here is output from docker volume inspect on the original (dvtest) and the clone (dvtest2) [root@cc-worker01 ~]# docker volume inspect dvtest [ { "Driver": "vsphere:latest", "Labels": {}, "Mountpoint": "/mnt/vmdk/dvtest/", "Name": "dvtest", "Options": { "size": "5gb" }, "Scope": "global", "Status": { "access": "read-write", "attach-as": "independent_persistent", "capacity": { "allocated": "101MB", "size": "5GB" }, "clone-from": "None", "created": "Tue Mar 6 20:30:16 2018", "created by VM": "cc-worker01", "datastore": "CC-Large-Datastore", "diskformat": "thin", "fstype": "ext4", "status": "detached" } } ] [root@cc-worker01 ~]# docker volume inspect dvtest2 [ { "Driver": "vsphere:latest", "Labels": null, "Mountpoint": "/mnt/vmdk/dvtest2/", "Name": "dvtest2", "Options": {}, "Scope": "global" } ]

[govint]

@carcampbell, please open a separate issue and post the ESX host side logs (/var/log/vmware/vmdk_ops.log) and the Linux side logs for the volume plugin. The issue posted earlier by @ashahi1 is related to a regression that has since been fixed (see , https://github.com/vmware/vsphere-storage-for-docker/releases/tag/0.21.1).

I'll be closing this issue and you can make a new one that we can debug. Please also include the version of the plugin and VIB you are using.

[govint]

Closing per earlier comment. Please open a new issue and provide the logs in that and the details listed in my earlier comment.