vic-machine-{os} delete fails to cleanup properly if there are pulled images

[isyarov]

vic-machine-{os} delete fails to cleanup properly if there are pulled images.

The container VMs and volumes are removed, but the images are not deleted and the respective folder on the datastore remains. All files related to the VCH deployment are also not cleaned up.
If the VCH is created and deleted without pulling any images, everything is cleaned up properly.
The delete commad output is normal, but running it with the --debug 3 option produces:

DEBU[0013] Failed to delete "[datastore0] virtual-container-host/VIC": Cannot delete file [datastore0] virtual-container-host/VIC
DEBU[0017] Image store parent directory not empty, leaving in place.

This happens if the VCH is created on a vCenter server, i have not tried it on just an ESX.
Trying to delete the folder from the vSphere web client manually fails with:
"Cannot delete file [datastore0] virtual-container-host"
All other files related to the VCH can be deleted, but the image files cannot.
SSH-ing to the ESX and deleting the folder manually succeeds

The vic-machine version is: v1.4.0-dev-0-8d92ff7

Steps to reproduce:

1. Create a VCH in a vCenter server. I used the following command:

./vic-machine-linux create --target {vcenter-ip} --user {username} --password {password} --bridge-network vch-bridge --image-store datastore0 --volume-store datastore0/vol
umes:default --no-tlsverify --thumbprint {vcenter-cert-thumbprint} --name virtual-container-host

2. With a docker client execute:

docker --tls -H {VCH-IP}:2376 pull alpine

3. Delete the VCH. I used the following command:

./vic-machine-linux delete --target {vcenter-ip} --user {username} --password {password} --force --name virtual-container-host

[AngieCris]

@isyarov

The delete commad output is normal, but running it with the --debug 3 option produces:

Does running delete with debug level less than 3 work for you?
If possible can you provide the complete log output for vic-machine delete command for debug level 3?
Thanks.

[isyarov]

@AngieCris

This is the output from the delete command with --debug 3

./vic-machine-linux delete --target {vcenter-ip} --user {username} --password {password} --force --debug 3 --name virtual-container-host

INFO[0000] ### Removing VCH ####
DEBU[0001] Accepting host "***" thumbprint ***
DEBU[0001] Creating VMOMI session with thumbprint ***
DEBU[0002] Session Environment Info:                     API Type=VirtualCenter API Version=6.5 Build=7092793 Name="VMware vCenter Server" OS Type=linux-x64 Product ID=vpx UUID=06bc6ae8-96e6-4a8b-9017-3ed1c33418d1 Vendor="VMware, Inc." Version=6.5.0
DEBU[0002] vSphere resource cache populating...
DEBU[0002] Cached dc:
DEBU[0002] Cached cluster:
DEBU[0003] Cached host:
DEBU[0004] Cached pool:
DEBU[0004] Cached folders:
DEBU[0004] Error count populating vSphere cache: (1)
DEBU[0004] new validator Session.Populate: Failure finding ds (): default datastore resolves to multiple instances, please specify
INFO[0004] Validating target
DEBU[0004] Using default resource pool for compute resource: "/vcqaDC/host/cls/Resources"
DEBU[0007] properties: [config.extraConfig summary.runtime.connectionState]
DEBU[0007] Cannot find image stores from configuration; attempting to find from vm datastore
DEBU[0007] properties: [datastore summary.runtime.connectionState]
INFO[0010]
INFO[0010] VCH ID: VirtualMachine:vm-126
DEBU[0010] properties: [config.extraConfig summary.runtime.connectionState]
INFO[0010] Removing VMs
DEBU[0011] properties: [config.extraConfig summary.runtime.connectionState]
DEBU[0011] No disks found attached to VM
INFO[0011] Removing image stores
DEBU[0014] Failed to delete "[datastore0] virtual-container-host/VIC": Cannot delete file [datastore0] virtual-container-host/VIC
DEBU[0017] Image store parent directory not empty, leaving in place.
INFO[0017] Removing volume stores
DEBU[0017] Provided datastore URL: "[datastore0] volumes"
DEBU[0017] Parsed volume store path: "volumes"
INFO[0017] Deleting volume store "default" on Datastore "datastore0" at path "volumes"
INFO[0020] Removing appliance VM network devices
DEBU[0022] Remove network is not supported for vCenter
DEBU[0022] properties: [config.files.vmPathName summary.runtime.connectionState]
DEBU[0024] unexpected soap fault on task retry: {{{%!s(*types.LocalizedMethodFault=<nil>) []}} VIC}
INFO[0024] Unregistered VM to cleanup after failed destroy: "VirtualMachine:vm-126"
DEBU[0027] Failed to delete "[datastore0] virtual-container-host": Cannot delete file [datastore0] virtual-container-host
INFO[0027] Removing Resource Pool "virtual-container-host"
INFO[0028] ----------
INFO[0028] If firewall changes were made for VIC during install, they were not reverted during delete
INFO[0028] To modify firewall rules see vic-machine update firewall --help
INFO[0028] ----------
INFO[0028] Completed successfully

[AngieCris]

@isyarov
Thanks for the info!
As far as I know the whole delete VCH process goes like this:

1. Destroy the VCH VM
2. If step 1 fails, unregister the VM instead
3. If step 2 succeeds, manually cleanup all the datastore files (since unregister doesn't delete datastore files)

In your case, step 1 fails because of a MethodDisabledError from vSphere, and it goes to step 2, and then step 3 fails.

This process is probably not what it should be - there's a bug on our side that we disable destroy operation on VM at some point but we never re-enable it, so step 1 fails every time, and we end up doing unregister every time, and that's error prone since there're cases like yours where deleting datastore files fails....
I'm working on fixing the bug to avoid unnecessary VM unregister and datastore file cleanup. Hopefully that will fix things in the future.

But I'm not sure as for the underlying root cause of why deleting datastore files failed.
The error message Cannot delete file [datastore0] virtual-container-host in the log isn't very informational (and that should probably be improved).

It fails when deleting VMFS files. Code where the error message is thrown:
https://github.com/vmware/vic/blob/master/lib/install/management/store_files.go#L184

Pinging relevant people for better input:
@matthewavery do you happen to know the potential reasons why deleting datastore files fail? what additional information do we need to identify the root cause in this particular scenario?

[AngieCris]

I have reproduced the same behavior on my VC, with one container in a VCH with all minimal configurations.

DEBU[0012] Failed to delete "[datastore1] test_2": Cannot delete file [datastore1] test_2

Investigating into the root cause. Will keep any progress posted here