Describe the bug A clear and concise description of what the bug is.

To Reproduce Steps to reproduce the behavior:

Create a PKS cluster do some testing, then delete it
Recreate the PKS cluster with same name as just deleted one

CPI Error Log ubuntu@opsmanager-2-10:~$ bosh task --cpi 2411 Using environment '192.168.100.9' as client 'ops_manager'

Task 2411

I, [2021-10-14T00:33:55.989791 #3847] INFO -- [req_id cpi-376405]: Starting info... I, [2021-10-14T00:33:55.990007 #3847] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:33:56.045884 #3847] INFO -- [req_id cpi-376405]: Finished info in 0.06 seconds I, [2021-10-14T00:33:56.065454 #3851] INFO -- [req_id cpi-590130]: Starting info... I, [2021-10-14T00:33:56.078989 #3851] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:33:56.124555 #3851] INFO -- [req_id cpi-590130]: Finished info in 0.06 seconds I, [2021-10-14T00:33:56.870054 #3855] INFO -- [req_id cpi-172936]: Starting info... I, [2021-10-14T00:33:56.882954 #3855] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:33:56.944915 #3855] INFO -- [req_id cpi-172936]: Finished info in 0.07 seconds I, [2021-10-14T00:33:57.051887 #3859] INFO -- [req_id cpi-127356]: Starting info... I, [2021-10-14T00:33:57.052123 #3859] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:33:57.097469 #3859] INFO -- [req_id cpi-127356]: Finished info in 0.05 seconds I, [2021-10-14T00:33:58.927219 #3865] INFO -- [req_id cpi-994655]: Starting create_vm... I, [2021-10-14T00:33:58.927390 #3865] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:34:02.195861 #3865] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:34:07.614527 #3865] DEBUG -- [req_id cpi-994655]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:34:07.742113 #3865] DEBUG -- [req_id cpi-994655]: Running method 'Login'... D, [2021-10-14T00:34:09.310814 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.320140 #3865] DEBUG -- [req_id cpi-994655]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:09.394981 #3865] INFO -- [req_id cpi-994655]: Using global ephemeral disk datastore pattern: ^(vdnetSharedStorage)$ I, [2021-10-14T00:34:09.395115 #3865] INFO -- [req_id cpi-994655]: Using global datastore pattern ^(vdnetSharedStorage)$ and global datastore cluster pattern ^()$ persistent: false D, [2021-10-14T00:34:09.395263 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.433661 #3865] INFO -- [req_id cpi-994655]: clusters: [] D, [2021-10-14T00:34:09.433856 #3865] DEBUG -- [req_id cpi-994655]: All clusters provided: {"os-compute-cluster-1"=>#<VSphereCloud::ClusterConfig:0x0000562c761ecd98 @name="os-compute-cluster-1", @config={"resource_pool"=>"PKSWorkerPool"}>} D, [2021-10-14T00:34:09.434722 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.580498 #3865] INFO -- [req_id cpi-994655]: Initiating VM Allocator with VM Placement Criteria: Disk Config: [Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS:] Req Memory: 4096 Mem Headroom: 128 I, [2021-10-14T00:34:09.580637 #3865] INFO -- [req_id cpi-994655]: Gathering vm placement resources for vm placement allocator pipeline D, [2021-10-14T00:34:09.717835 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.752815 #3865] DEBUG -- [req_id cpi-994655]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.808859 #3865] DEBUG -- [req_id cpi-994655]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.842861 #3865] DEBUG -- [req_id cpi-994655]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 190960, host group free memory: 190960 for free memory required: 4224 D, [2021-10-14T00:34:09.857649 #3865] DEBUG -- [req_id cpi-994655]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:09.857777 #3865] DEBUG -- [req_id cpi-994655]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:09.857957 #3865] INFO -- [req_id cpi-994655]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.054596 #3865] DEBUG -- [req_id cpi-994655]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: D, [2021-10-14T00:34:10.054853 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.069314 #3865] DEBUG -- [req_id cpi-994655]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.122085 #3865] DEBUG -- [req_id cpi-994655]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.151750 #3865] DEBUG -- [req_id cpi-994655]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 191583, host group free memory: 191583 for free memory required: 4224 D, [2021-10-14T00:34:10.151896 #3865] DEBUG -- [req_id cpi-994655]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:10.151959 #3865] DEBUG -- [req_id cpi-994655]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.152092 #3865] INFO -- [req_id cpi-994655]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.242010 #3865] DEBUG -- [req_id cpi-994655]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.242317 #3865] INFO -- [req_id cpi-994655]: Creating vm: vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 on <[Vim.ClusterComputeResource] domain-c9> stored in <[Vim.Datastore] datastore-15> D, [2021-10-14T00:34:10.242419 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.250997 #3865] DEBUG -- [req_id cpi-994655]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:10.336703 #3865] INFO -- [req_id cpi-994655]: Searching for stemcell sc-e071f887-2924-427d-9ad1-746a81a94e75 on datastore vdnetSharedStorage D, [2021-10-14T00:34:10.337023 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.360262 #3865] DEBUG -- [req_id cpi-994655]: Running method 'CreateContainerView'... D, [2021-10-14T00:34:10.719152 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindExtension'... I, [2021-10-14T00:34:10.747111 #3865] INFO -- [req_id cpi-994655]: Trying to find network pks-8117c759-0f27-4dc1-bd81-ba372c842596 for 1 time D, [2021-10-14T00:34:10.748526 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:11.573402 #3865] INFO -- [req_id cpi-994655]: Cloning vm: (VSphereCloud::Resources::VM (cid="sc-e071f887-2924-427d-9ad1-746a81a94e75")) to vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 D, [2021-10-14T00:34:11.573785 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:11.594818 #3865] DEBUG -- [req_id cpi-994655]: Running method 'CloneVM_Task'... D, [2021-10-14T00:34:11.644051 #3865] DEBUG -- [req_id cpi-994655]: Starting task 'VirtualMachine.clone'... D, [2021-10-14T00:34:15.746996 #3865] DEBUG -- [req_id cpi-994655]: Finished task 'VirtualMachine.clone' after 4.102750986 seconds D, [2021-10-14T00:34:15.839229 #3865] DEBUG -- [req_id cpi-994655]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:16.101122 #3865] INFO -- [req_id cpi-994655]: Using ephemeral disk unit number 1 I, [2021-10-14T00:34:16.110380 #3865] INFO -- [req_id cpi-994655]: Updating current agent env from vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' in datacenter 'folder-os-test-dc/os-test-dc' I, [2021-10-14T00:34:16.167549 #3865] INFO -- [req_id cpi-994655]: Cleaning current agent env from vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:34:16.241402 #3865] INFO -- [req_id cpi-994655]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:34:16.323874 #3865] INFO -- [req_id cpi-994655]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-a39479e0-66a7-44eb-956e-b4682dde9ab5/env.json?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:34:16.324062 #3865] DEBUG -- [req_id cpi-994655]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:34:16.361960 #3865] INFO -- [req_id cpi-994655]: Uploading file to https://192.161.243.45/folder/vm-a39479e0-66a7-44eb-956e-b4682dde9ab5/env.json?dsName=vdnetSharedStorage... I, [2021-10-14T00:34:16.404339 #3865] INFO -- [req_id cpi-994655]: Successfully uploaded file. I, [2021-10-14T00:34:16.499295 #3865] INFO -- [req_id cpi-994655]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:34:16.588402 #3865] INFO -- [req_id cpi-994655]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-a39479e0-66a7-44eb-956e-b4682dde9ab5/env.iso?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:34:16.588574 #3865] DEBUG -- [req_id cpi-994655]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:34:16.611903 #3865] INFO -- [req_id cpi-994655]: Uploading file to https://192.161.243.45/folder/vm-a39479e0-66a7-44eb-956e-b4682dde9ab5/env.iso?dsName=vdnetSharedStorage... I, [2021-10-14T00:34:16.663003 #3865] INFO -- [req_id cpi-994655]: Successfully uploaded file. D, [2021-10-14T00:34:16.702440 #3865] DEBUG -- [req_id cpi-994655]: Running method 'ReconfigVM_Task'... D, [2021-10-14T00:34:16.727980 #3865] DEBUG -- [req_id cpi-994655]: Starting task 'VirtualMachine.reconfigure'... D, [2021-10-14T00:34:17.752393 #3865] DEBUG -- [req_id cpi-994655]: Finished task 'VirtualMachine.reconfigure' after 1.024262956 seconds I, [2021-10-14T00:34:17.752620 #3865] INFO -- [req_id cpi-994655]: Powering on VM: (VSphereCloud::Resources::VM (cid="vm-a39479e0-66a7-44eb-956e-b4682dde9ab5")) D, [2021-10-14T00:34:17.792606 #3865] DEBUG -- [req_id cpi-994655]: Running method 'PowerOnMultiVM_Task'... D, [2021-10-14T00:34:17.815476 #3865] DEBUG -- [req_id cpi-994655]: Starting task 'Datacenter.powerOnVm'... D, [2021-10-14T00:34:18.858913 #3865] DEBUG -- [req_id cpi-994655]: Finished task 'Datacenter.powerOnVm' after 1.043247814 seconds D, [2021-10-14T00:34:18.869937 #3865] DEBUG -- [req_id cpi-994655]: Starting task 'Drm.ExecuteVmPowerOnLRO'... D, [2021-10-14T00:35:20.018069 #3865] DEBUG -- [req_id cpi-994655]: Finished task 'Drm.ExecuteVmPowerOnLRO' after 61.147823199 seconds I, [2021-10-14T00:35:24.418785 #3865] INFO -- [req_id cpi-994655]: Finished create_vm in 85.49 seconds D, [2021-10-14T00:35:24.419240 #3865] DEBUG -- [req_id cpi-994655]: Running method 'Logout'... I, [2021-10-14T00:35:25.731721 #3944] INFO -- [req_id cpi-428448]: Starting info... I, [2021-10-14T00:35:25.731892 #3944] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:35:25.767698 #3944] INFO -- [req_id cpi-428448]: Finished info in 0.04 seconds Rescued Unknown: Logical port for VM vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 with 'external_id' 5009c816-858a-4e1a-0080-a1b814b7a5a4 was expected in NSX-T but was not found. backtrace: /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/nsxt_provider.rb:414:in block in logical_ports' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/retryable.rb:28:inblock in retryer' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/retryable.rb:26:in loop' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/retryable.rb:26:inretryer' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/nsxt_provider.rb:382:in logical_ports' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/nsxt_provider.rb:193:inupdate_vm_metadata_on_logical_ports' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/helpers/hooks.rb:7:in call' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/helpers/hooks.rb:7:inblock (2 levels) in before' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/cloud.rb:588:in block in set_vm_metadata' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:inwith_thread_name' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/cloud/vsphere/cloud.rb:579:in set_vm_metadata' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/2.6.0/forwardable.rb:230:inset_vm_metadata' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in public_send' /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:inrun' /var/vcap/packages/vsphere_cpi/bin/vsphere_cpi:72:in <top (required)>' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:inload' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in kernel_load' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:inrun' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in exec' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:inrun' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in invoke_command' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:indispatch' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in dispatch' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:instart' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in start' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:inblock in <top (required)>' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in with_friendly_errors' /var/vcap/data/packages/ruby-2.6.5-r0.29.0/4f6548e0d4b95f1e43a512d8ab0ed596f826ec5c/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in<top (required)>' /var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in load' /var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in

'I, [2021-10-14T00:35:27.093765 #3946] INFO -- [req_id cpi-868324]: Starting set_vm_metadata... I, [2021-10-14T00:35:27.093942 #3946] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:35:28.500955 #3946] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:35:30.862520 #3946] DEBUG -- [req_id cpi-868324]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:35:30.922902 #3946] DEBUG -- [req_id cpi-868324]: Running method 'Login'... D, [2021-10-14T00:35:31.529843 #3946] DEBUG -- [req_id cpi-868324]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:35:31.537284 #3946] DEBUG -- [req_id cpi-868324]: Running method 'CreateContainerView'... D, [2021-10-14T00:35:31.568323 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.579125 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'director' already exists.'. W, [2021-10-14T00:35:31.579361 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'director' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.638923 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.654149 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.662103 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'deployment' already exists.'. W, [2021-10-14T00:35:31.662296 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'deployment' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.684401 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.692278 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.700524 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'id' already exists.'. W, [2021-10-14T00:35:31.700750 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'id' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.724554 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.732263 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.740145 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'job' already exists.'. W, [2021-10-14T00:35:31.740337 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'job' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.761246 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.768677 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.776242 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'instance_group' already exists.'. W, [2021-10-14T00:35:31.776445 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'instance_group' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.799771 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.808647 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.819474 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'index' already exists.'. W, [2021-10-14T00:35:31.819730 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'index' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.848133 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.856790 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.865891 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'name' already exists.'. W, [2021-10-14T00:35:31.866054 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'name' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.892416 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:31.901227 #3946] DEBUG -- [req_id cpi-868324]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:35:31.910022 #3946] WARN -- [req_id cpi-868324]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'created_at' already exists.'. W, [2021-10-14T00:35:31.910245 #3946] WARN -- [req_id cpi-868324]: Custom field definition already exists: The name 'created_at' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:35:31.937877 #3946] DEBUG -- [req_id cpi-868324]: Running method 'SetField'... D, [2021-10-14T00:35:36.810439 #3946] DEBUG -- [req_id cpi-868324]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:35:36.817155 #3946] INFO -- [req_id cpi-868324]: Checking if dvportgroup-183 is backed by NSXT I, [2021-10-14T00:35:36.894455 #3946] INFO -- [req_id cpi-868324]: DVPG dvportgroup-183 is backed by NSXT I, [2021-10-14T00:35:36.923778 #3946] INFO -- [req_id cpi-868324]: NIC with device key 4000 is backed by NSXT DVPG I, [2021-10-14T00:35:36.923995 #3946] INFO -- [req_id cpi-868324]: NSX-T networks found for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5': ["DVSwitch: 50 09 71 80 3e 48 1b d1-51 2f f6 5f bd 2c ce 95"] I, [2021-10-14T00:35:36.924136 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:36.996064 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:37.024805 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:38.050921 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:38.077027 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:38.105840 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:39.129231 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:39.158559 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:39.184906 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:40.212486 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:40.241395 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:40.267990 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:41.298530 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:41.357860 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:41.414263 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:42.443771 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:42.473541 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:42.501308 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:43.547338 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:43.575484 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:43.605168 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:44.630910 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:44.656026 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:44.680566 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:45.704688 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:45.738001 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:45.788402 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:46.831548 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:46.858573 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:46.884917 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:47.910298 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:47.937033 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:47.966102 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:48.990109 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:49.023642 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:49.049104 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:50.073543 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:50.101932 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:50.127194 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:51.155685 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:51.183446 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:51.217078 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:52.241650 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:52.271480 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:52.296559 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:53.321244 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:53.348905 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:53.374554 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:54.398257 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:54.426973 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:54.455989 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:55.483528 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:55.522336 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:55.551362 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:56.576538 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:56.606983 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:56.636795 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:57.666111 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:57.691675 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:57.718638 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:58.742854 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:58.768731 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:58.794879 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:35:59.821431 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:35:59.847322 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:35:59.879184 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:00.901925 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:00.930584 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:00.958986 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:01.989524 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:02.022237 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:02.049210 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:03.078219 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:03.105364 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:03.131046 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:04.158921 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:04.190793 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:04.220701 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:05.251313 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:05.299657 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:05.333624 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:06.365686 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:06.392913 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:06.423520 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:07.453751 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:07.487066 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:07.516614 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:08.539048 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:08.570944 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:08.595836 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:09.626408 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:09.659088 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:09.684965 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:10.712819 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:10.742342 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:10.768884 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:11.797886 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:11.822110 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:11.849193 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:12.872434 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:12.909534 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:12.968018 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:13.997862 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:14.025138 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:14.048543 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:15.073414 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:15.135304 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:15.491730 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:16.544376 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:16.576911 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:16.603409 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:17.630828 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:17.659266 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:17.683794 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:18.709572 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:18.737178 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:18.764070 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:19.793880 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:19.823024 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:19.850579 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:20.876468 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:20.914551 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:20.940614 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:21.969030 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:22.020295 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:22.051763 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:23.078968 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:23.115618 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:23.145996 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:24.178818 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:24.205360 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:24.232849 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:25.260208 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:25.294923 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:25.337675 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:26.373288 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:26.433715 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:26.479684 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:27.512735 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:27.552155 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:27.584394 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:28.620150 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:28.660330 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:28.693516 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:29.731016 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:29.763993 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:29.808577 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:30.849834 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:30.884680 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:30.925534 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:31.956187 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:32.016193 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:32.054994 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:33.090063 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:33.126182 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:33.158637 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:34.185520 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:34.249516 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:34.289149 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:35.322197 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:35.364256 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:35.395858 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:36.426720 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:36.467088 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:36.498567 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:37.536470 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:37.579007 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:37.610227 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:38.644120 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:38.684435 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:38.723846 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:39.750445 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:39.785215 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:39.809031 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:40.834638 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:40.868389 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:40.891629 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:41.917841 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:41.952298 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:41.995596 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:43.028863 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:43.058469 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:43.083384 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:44.108177 #3946] INFO -- [req_id cpi-868324]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:36:44.145442 #3946] INFO -- [req_id cpi-868324]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:36:44.177327 #3946] INFO -- [req_id cpi-868324]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:36:44.203483 #3946] INFO -- [req_id cpi-868324]: Finished set_vm_metadata in 77.11 seconds D, [2021-10-14T00:36:44.204123 #3946] DEBUG -- [req_id cpi-868324]: Running method 'Logout'... I, [2021-10-14T00:36:45.653894 #3964] INFO -- [req_id cpi-760589]: Starting info... I, [2021-10-14T00:36:45.654075 #3964] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:36:45.710245 #3964] INFO -- [req_id cpi-760589]: Finished info in 0.06 seconds I, [2021-10-14T00:33:59.836278 #3869] INFO -- [req_id cpi-435269]: Starting create_vm... I, [2021-10-14T00:33:59.836506 #3869] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:34:03.110319 #3869] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:34:08.186899 #3869] DEBUG -- [req_id cpi-435269]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:34:08.257170 #3869] DEBUG -- [req_id cpi-435269]: Running method 'Login'... D, [2021-10-14T00:34:09.303895 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.321581 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:09.429158 #3869] INFO -- [req_id cpi-435269]: Using global ephemeral disk datastore pattern: ^(vdnetSharedStorage)$ I, [2021-10-14T00:34:09.429307 #3869] INFO -- [req_id cpi-435269]: Using global datastore pattern ^(vdnetSharedStorage)$ and global datastore cluster pattern ^()$ persistent: false D, [2021-10-14T00:34:09.429440 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.494769 #3869] INFO -- [req_id cpi-435269]: clusters: [] D, [2021-10-14T00:34:09.494993 #3869] DEBUG -- [req_id cpi-435269]: All clusters provided: {"os-compute-cluster-1"=>#<VSphereCloud::ClusterConfig:0x000055b73fcc8bd8 @name="os-compute-cluster-1", @config={"resource_pool"=>"PKSWorkerPool"}>} D, [2021-10-14T00:34:09.496064 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.695627 #3869] INFO -- [req_id cpi-435269]: Initiating VM Allocator with VM Placement Criteria: Disk Config: [Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS:] Req Memory: 4096 Mem Headroom: 128 I, [2021-10-14T00:34:09.695769 #3869] INFO -- [req_id cpi-435269]: Gathering vm placement resources for vm placement allocator pipeline D, [2021-10-14T00:34:09.829630 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.865386 #3869] DEBUG -- [req_id cpi-435269]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.918524 #3869] DEBUG -- [req_id cpi-435269]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:10.052250 #3869] DEBUG -- [req_id cpi-435269]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 190960, host group free memory: 190960 for free memory required: 4224 D, [2021-10-14T00:34:10.052451 #3869] DEBUG -- [req_id cpi-435269]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:10.052556 #3869] DEBUG -- [req_id cpi-435269]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.052779 #3869] INFO -- [req_id cpi-435269]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.139972 #3869] DEBUG -- [req_id cpi-435269]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: D, [2021-10-14T00:34:10.140193 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.171613 #3869] DEBUG -- [req_id cpi-435269]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.201781 #3869] DEBUG -- [req_id cpi-435269]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.239287 #3869] DEBUG -- [req_id cpi-435269]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 191583, host group free memory: 191583 for free memory required: 4224 D, [2021-10-14T00:34:10.239449 #3869] DEBUG -- [req_id cpi-435269]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:10.239510 #3869] DEBUG -- [req_id cpi-435269]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.239638 #3869] INFO -- [req_id cpi-435269]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.401690 #3869] DEBUG -- [req_id cpi-435269]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.411085 #3869] INFO -- [req_id cpi-435269]: Creating vm: vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3 on <[Vim.ClusterComputeResource] domain-c9> stored in <[Vim.Datastore] datastore-15> D, [2021-10-14T00:34:10.411253 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.426337 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:10.520526 #3869] INFO -- [req_id cpi-435269]: Searching for stemcell sc-e071f887-2924-427d-9ad1-746a81a94e75 on datastore vdnetSharedStorage D, [2021-10-14T00:34:10.520697 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.535673 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CreateContainerView'... D, [2021-10-14T00:34:10.911913 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindExtension'... I, [2021-10-14T00:34:10.920834 #3869] INFO -- [req_id cpi-435269]: Trying to find network pks-8117c759-0f27-4dc1-bd81-ba372c842596 for 1 time D, [2021-10-14T00:34:10.921009 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:11.764611 #3869] INFO -- [req_id cpi-435269]: Cloning vm: (VSphereCloud::Resources::VM (cid="sc-e071f887-2924-427d-9ad1-746a81a94e75")) to vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3 D, [2021-10-14T00:34:11.764903 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:11.777017 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CloneVM_Task'... D, [2021-10-14T00:34:11.817733 #3869] DEBUG -- [req_id cpi-435269]: Starting task 'VirtualMachine.clone'... W, [2021-10-14T00:35:09.881492 #3869] WARN -- [req_id cpi-435269]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:35:10.883274 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:35:10.893486 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CloneVM_Task'... W, [2021-10-14T00:35:10.945996 #3869] WARN -- [req_id cpi-435269]: Retrying task 'VirtualMachine.clone', 1 attempts so far... W, [2021-10-14T00:36:08.898356 #3869] WARN -- [req_id cpi-435269]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:36:10.901079 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:36:10.914074 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CloneVM_Task'... W, [2021-10-14T00:36:10.954673 #3869] WARN -- [req_id cpi-435269]: Retrying task 'VirtualMachine.clone', 2 attempts so far... W, [2021-10-14T00:37:08.915626 #3869] WARN -- [req_id cpi-435269]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:37:12.920368 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:37:12.931425 #3869] DEBUG -- [req_id cpi-435269]: Running method 'CloneVM_Task'... W, [2021-10-14T00:37:12.959794 #3869] WARN -- [req_id cpi-435269]: Retrying task 'VirtualMachine.clone', 3 attempts so far... D, [2021-10-14T00:37:16.018568 #3869] DEBUG -- [req_id cpi-435269]: Finished task 'VirtualMachine.clone' after 3.058609244 seconds D, [2021-10-14T00:37:16.075481 #3869] DEBUG -- [req_id cpi-435269]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:37:16.184653 #3869] INFO -- [req_id cpi-435269]: Using ephemeral disk UUID 6000c292-37e6-bb78-84c3-bfd1b61f91b5 I, [2021-10-14T00:37:16.192805 #3869] INFO -- [req_id cpi-435269]: Updating current agent env from vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' in datacenter 'folder-os-test-dc/os-test-dc' I, [2021-10-14T00:37:16.240674 #3869] INFO -- [req_id cpi-435269]: Cleaning current agent env from vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:16.311198 #3869] INFO -- [req_id cpi-435269]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:37:16.387948 #3869] INFO -- [req_id cpi-435269]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3/env.json?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:37:16.388091 #3869] DEBUG -- [req_id cpi-435269]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:37:16.414664 #3869] INFO -- [req_id cpi-435269]: Uploading file to https://192.161.243.45/folder/vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3/env.json?dsName=vdnetSharedStorage... I, [2021-10-14T00:37:16.460578 #3869] INFO -- [req_id cpi-435269]: Successfully uploaded file. I, [2021-10-14T00:37:16.466111 #3869] INFO -- [req_id cpi-435269]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:37:16.543156 #3869] INFO -- [req_id cpi-435269]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3/env.iso?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:37:16.543344 #3869] DEBUG -- [req_id cpi-435269]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:37:16.562993 #3869] INFO -- [req_id cpi-435269]: Uploading file to https://192.161.243.45/folder/vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3/env.iso?dsName=vdnetSharedStorage... I, [2021-10-14T00:37:16.611911 #3869] INFO -- [req_id cpi-435269]: Successfully uploaded file. D, [2021-10-14T00:37:16.687549 #3869] DEBUG -- [req_id cpi-435269]: Running method 'ReconfigVM_Task'... D, [2021-10-14T00:37:16.713485 #3869] DEBUG -- [req_id cpi-435269]: Starting task 'VirtualMachine.reconfigure'... D, [2021-10-14T00:37:17.736665 #3869] DEBUG -- [req_id cpi-435269]: Finished task 'VirtualMachine.reconfigure' after 1.022986421 seconds I, [2021-10-14T00:37:17.736910 #3869] INFO -- [req_id cpi-435269]: Upgrading virtual hardware on VM D, [2021-10-14T00:37:17.736998 #3869] DEBUG -- [req_id cpi-435269]: Running method 'UpgradeVM_Task'... D, [2021-10-14T00:37:17.762125 #3869] DEBUG -- [req_id cpi-435269]: Starting task 'VirtualMachine.upgradeVirtualHardware'... D, [2021-10-14T00:37:18.784557 #3869] DEBUG -- [req_id cpi-435269]: Finished task 'VirtualMachine.upgradeVirtualHardware' after 1.022267325 seconds I, [2021-10-14T00:37:18.784722 #3869] INFO -- [req_id cpi-435269]: Powering on VM: (VSphereCloud::Resources::VM (cid="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3")) D, [2021-10-14T00:37:18.819587 #3869] DEBUG -- [req_id cpi-435269]: Running method 'PowerOnMultiVM_Task'... D, [2021-10-14T00:37:18.843199 #3869] DEBUG -- [req_id cpi-435269]: Starting task 'Datacenter.powerOnVm'... D, [2021-10-14T00:37:18.856210 #3869] DEBUG -- [req_id cpi-435269]: Finished task 'Datacenter.powerOnVm' after 0.012824297 seconds D, [2021-10-14T00:37:18.867812 #3869] DEBUG -- [req_id cpi-435269]: Starting task 'Drm.ExecuteVmPowerOnLRO'... D, [2021-10-14T00:37:19.888904 #3869] DEBUG -- [req_id cpi-435269]: Finished task 'Drm.ExecuteVmPowerOnLRO' after 1.020928368 seconds I, [2021-10-14T00:37:24.588215 #3869] INFO -- [req_id cpi-435269]: Finished create_vm in 204.75 seconds D, [2021-10-14T00:37:24.588788 #3869] DEBUG -- [req_id cpi-435269]: Running method 'Logout'... I, [2021-10-14T00:37:26.124680 #3990] INFO -- [req_id cpi-630672]: Starting info... I, [2021-10-14T00:37:26.124966 #3990] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:37:26.168112 #3990] INFO -- [req_id cpi-630672]: Finished info in 0.04 seconds I, [2021-10-14T00:37:27.580860 #3992] INFO -- [req_id cpi-195473]: Starting set_vm_metadata... I, [2021-10-14T00:37:27.581018 #3992] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:37:29.047603 #3992] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:37:31.543461 #3992] DEBUG -- [req_id cpi-195473]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:37:31.622356 #3992] DEBUG -- [req_id cpi-195473]: Running method 'Login'... D, [2021-10-14T00:37:32.058994 #3992] DEBUG -- [req_id cpi-195473]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:37:32.067682 #3992] DEBUG -- [req_id cpi-195473]: Running method 'CreateContainerView'... D, [2021-10-14T00:37:32.105142 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.114221 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'director' already exists.'. W, [2021-10-14T00:37:32.114449 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'director' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.148302 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.157628 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.167907 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'deployment' already exists.'. W, [2021-10-14T00:37:32.168092 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'deployment' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.207925 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.217657 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.226625 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'id' already exists.'. W, [2021-10-14T00:37:32.226855 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'id' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.272790 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.282165 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.292375 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'job' already exists.'. W, [2021-10-14T00:37:32.292541 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'job' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.378765 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.386581 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.393761 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'instance_group' already exists.'. W, [2021-10-14T00:37:32.393931 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'instance_group' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.419538 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.429203 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.436890 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'index' already exists.'. W, [2021-10-14T00:37:32.437091 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'index' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.462061 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.469558 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.478253 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'name' already exists.'. W, [2021-10-14T00:37:32.478443 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'name' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.502060 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:32.511157 #3992] DEBUG -- [req_id cpi-195473]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:37:32.518230 #3992] WARN -- [req_id cpi-195473]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'created_at' already exists.'. W, [2021-10-14T00:37:32.518425 #3992] WARN -- [req_id cpi-195473]: Custom field definition already exists: The name 'created_at' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:37:32.544483 #3992] DEBUG -- [req_id cpi-195473]: Running method 'SetField'... D, [2021-10-14T00:37:37.838123 #3992] DEBUG -- [req_id cpi-195473]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:37:37.845062 #3992] INFO -- [req_id cpi-195473]: Checking if dvportgroup-183 is backed by NSXT I, [2021-10-14T00:37:37.920716 #3992] INFO -- [req_id cpi-195473]: DVPG dvportgroup-183 is backed by NSXT I, [2021-10-14T00:37:37.951500 #3992] INFO -- [req_id cpi-195473]: NIC with device key 4000 is backed by NSXT DVPG I, [2021-10-14T00:37:37.951695 #3992] INFO -- [req_id cpi-195473]: NSX-T networks found for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3': ["DVSwitch: 50 09 71 80 3e 48 1b d1-51 2f f6 5f bd 2c ce 95"] I, [2021-10-14T00:37:37.951830 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:38.052846 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x00005636739deba8 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x00005636739ddfa0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x00005636739de6f8

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x00005636739dd7f8

@_last_sync_time=1634171855107, @compute_ids= ["moIdOnHost:54", "hostLocalId:54", "locationId:564d059b-7c58-8e3f-628d-931198c2b031", "instanceUuid:5009c9a1-ba2a-e510-d477-5e691f716e18", "externalId:5009c9a1-ba2a-e510-d477-5e691f716e18", "biosUuid:4209bcdd-ff49-62c7-d8bd-7bae17a21952"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009c9a1-ba2a-e510-d477-5e691f716e18", @guest_info=

<NSXT::GuestInfo:0x00005636739dcbf0 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x00005636739dd348

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:39.054325 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:39.095084 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673a40e20 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673a40218 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673a40970

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673a53a20

<NSXT::GuestInfo:0x0000563673a52e18 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673a53570

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:40.096441 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:40.141090 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673a83310 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673a82708 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673a82e60

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673a81f60

<NSXT::GuestInfo:0x0000563673a81358 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673a81ab0

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:41.142730 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:41.182204 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673ab9898 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673ab8c90 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673ab93e8

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673ab84e8

<NSXT::GuestInfo:0x0000563673acb890 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673ab8038

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:42.183314 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:42.236961 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673afbd60 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673afb158 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673afb8b0

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673afa9b0

<NSXT::GuestInfo:0x0000563673af9da8 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673afa500

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:43.238508 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:43.285527 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673b322e8 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673b316e0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673b31e38

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673b30f38

<NSXT::GuestInfo:0x0000563673b30330 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673b30a88

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:44.286935 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:44.329661 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673b64838 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673b73bd0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673b64388

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673b73428

<NSXT::GuestInfo:0x0000563673b72820 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673b72f78

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:45.331167 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:45.369946 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673ba6d78 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673ba6170 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673ba68c8

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673ba59c8

<NSXT::GuestInfo:0x0000563673ba4dc0 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673ba5518

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:46.370886 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:46.415623 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673bdd2b0 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673bdc6a8 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673bdce00

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673bebea0

<NSXT::GuestInfo:0x0000563673beb298 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673beb9f0

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:47.417118 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:47.478656 #3992] INFO -- [req_id cpi-195473]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000563673c1f7c8 @_last_sync_time=1634171775218, @compute_ids= ["moIdOnHost:41", "hostLocalId:41", "locationId:", "instanceUuid:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "externalId:5009ae22-c4a0-b6a1-463c-55f64e3e96d5", "biosUuid:42096292-fd94-628b-d7ab-7c061105efa3"], @display_name="vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3", @external_id="5009ae22-c4a0-b6a1-463c-55f64e3e96d5", @guest_info=

<NSXT::GuestInfo:0x0000563673c1ebc0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="41", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673c1f318

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000563673c1e418

<NSXT::GuestInfo:0x0000563673c1d810 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="54", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000563673c1df68

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:37:48.485573 #3992] INFO -- [req_id cpi-195473]: Searching for LogicalPorts for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3' I, [2021-10-14T00:37:48.538089 #3992] INFO -- [req_id cpi-195473]: Searching VIFs with 'owner_vm_id: 5009c9a1-ba2a-e510-d477-5e691f716e18' I, [2021-10-14T00:37:48.762808 #3992] INFO -- [req_id cpi-195473]: Searching LogicalPorts with 'attachment_id: 5bb78fe5-d343-4199-9f70-8f0b629c88c0' I, [2021-10-14T00:37:48.885056 #3992] INFO -- [req_id cpi-195473]: LogicalPorts found for vm 'vm-6c2f7e4d-f9ff-481a-b654-9d6a1a64c0c3': ["a3ffcb41-fc27-4568-a8d7-972ac28a233c"]' I, [2021-10-14T00:37:49.264291 #3992] INFO -- [req_id cpi-195473]: Finished set_vm_metadata in 21.68 seconds D, [2021-10-14T00:37:49.265094 #3992] DEBUG -- [req_id cpi-195473]: Running method 'Logout'... I, [2021-10-14T00:36:47.099819 #3966] INFO -- [req_id cpi-770422]: Starting delete_vm... I, [2021-10-14T00:36:47.100030 #3966] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:36:48.625442 #3966] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:36:51.139756 #3966] DEBUG -- [req_id cpi-770422]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:36:51.216480 #3966] DEBUG -- [req_id cpi-770422]: Running method 'Login'... I, [2021-10-14T00:36:51.705543 #3966] INFO -- [req_id cpi-770422]: Deleting vm: vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 D, [2021-10-14T00:36:51.705786 #3966] DEBUG -- [req_id cpi-770422]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:36:51.717399 #3966] DEBUG -- [req_id cpi-770422]: Running method 'CreateContainerView'... D, [2021-10-14T00:36:52.173571 #3966] DEBUG -- [req_id cpi-770422]: Running method 'PowerOffVM_Task'... D, [2021-10-14T00:36:52.202241 #3966] DEBUG -- [req_id cpi-770422]: Starting task 'VirtualMachine.powerOff'... D, [2021-10-14T00:36:53.229042 #3966] DEBUG -- [req_id cpi-770422]: Finished task 'VirtualMachine.powerOff' after 1.026592244 seconds I, [2021-10-14T00:36:53.342652 #3966] INFO -- [req_id cpi-770422]: Cleaning current agent env from vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' D, [2021-10-14T00:36:53.432785 #3966] DEBUG -- [req_id cpi-770422]: Running method 'DeleteDatastoreFile_Task'... D, [2021-10-14T00:36:53.459757 #3966] DEBUG -- [req_id cpi-770422]: Starting task 'FileManager.deleteFile'... D, [2021-10-14T00:36:54.491065 #3966] DEBUG -- [req_id cpi-770422]: Finished task 'FileManager.deleteFile' after 1.031093538 seconds D, [2021-10-14T00:36:54.491281 #3966] DEBUG -- [req_id cpi-770422]: Running method 'DeleteDatastoreFile_Task'... D, [2021-10-14T00:36:54.520079 #3966] DEBUG -- [req_id cpi-770422]: Starting task 'FileManager.deleteFile'... D, [2021-10-14T00:36:55.564946 #3966] DEBUG -- [req_id cpi-770422]: Finished task 'FileManager.deleteFile' after 1.044648262 seconds D, [2021-10-14T00:37:00.997814 #3966] DEBUG -- [req_id cpi-770422]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:37:01.006562 #3966] INFO -- [req_id cpi-770422]: Checking if dvportgroup-183 is backed by NSXT I, [2021-10-14T00:37:01.083999 #3966] INFO -- [req_id cpi-770422]: DVPG dvportgroup-183 is backed by NSXT I, [2021-10-14T00:37:01.111716 #3966] INFO -- [req_id cpi-770422]: NIC with device key 4000 is backed by NSXT DVPG I, [2021-10-14T00:37:01.111900 #3966] INFO -- [req_id cpi-770422]: NSX-T networks found for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5': ["DVSwitch: 50 09 71 80 3e 48 1b d1-51 2f f6 5f bd 2c ce 95"] I, [2021-10-14T00:37:01.112006 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:01.259634 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:01.340309 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:02.421129 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:02.536156 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:02.669892 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:03.715308 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:03.754272 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:03.788038 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:04.821883 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:04.863234 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:04.899263 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:05.943122 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:05.972947 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:06.004636 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:07.036761 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:07.065692 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:07.093923 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:08.123590 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:08.157944 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:08.196636 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:09.241222 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:09.281936 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:09.324032 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:10.357745 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:10.430598 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:10.479442 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:11.558920 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:11.615082 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:11.665152 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:12.697902 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:12.731634 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:12.762843 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:13.791598 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:13.828741 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:13.858074 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:14.891100 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:14.979449 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:15.011297 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:16.048509 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:16.082339 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:16.114934 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:17.146340 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:17.176833 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:17.228015 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:18.256738 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:18.286983 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:18.314204 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:19.339997 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:19.372750 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:19.401582 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:20.437701 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:20.497339 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:20.550379 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:21.586779 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:21.631153 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:21.660513 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:22.692140 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:22.725145 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:22.756741 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:23.786975 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:23.821747 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:23.852802 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:24.883460 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:24.918586 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:24.949952 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:25.974740 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:26.012715 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:26.050009 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:27.078570 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:27.119934 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:27.163622 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:28.196299 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:28.251094 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:28.297932 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:29.329857 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:29.366585 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:29.398168 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:30.429499 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:30.479797 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:30.521355 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:31.573769 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:31.614625 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:31.662932 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:32.712029 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:32.749913 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:32.800204 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:33.848337 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:33.883600 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:33.921202 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:34.957057 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:35.000890 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:35.036279 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:36.073274 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:36.121890 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:36.157533 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:37.266245 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:37.300629 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:37.334568 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:38.379285 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:38.417870 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:38.513983 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:39.562930 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:39.595753 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:39.631098 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:40.662753 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:40.695583 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:40.736679 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:41.783321 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:41.829933 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:41.873185 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:42.909826 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:42.947359 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:42.978812 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:44.006914 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:44.044281 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:44.105261 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:45.139130 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:45.180761 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:45.233512 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:46.311895 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:46.358511 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:46.407558 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:47.480835 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:47.513078 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:47.549710 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:48.585703 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:48.835577 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:48.889417 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:49.920337 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:49.959362 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:50.010047 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:51.045169 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:51.086348 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:51.124094 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:52.152026 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:52.182372 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:52.239469 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:53.273815 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:53.313114 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:53.347668 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:54.385623 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:54.418110 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:54.456228 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:55.498512 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:55.543345 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:55.575989 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:56.626301 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:56.664696 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:56.699506 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:57.728767 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:57.768704 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:57.813472 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:58.854722 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:58.893178 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:37:58.922740 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:37:59.958201 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:37:59.991681 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:00.043782 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:01.080022 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:01.115084 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:01.145975 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:02.197017 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:02.259153 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:02.294238 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:03.325707 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:03.368931 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:03.404914 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:04.439287 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:04.471517 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:04.502580 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:05.544019 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:05.582641 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:05.638271 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:06.742290 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:06.793158 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:06.825157 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:07.943358 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:07.984452 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:08.017052 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:09.055695 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:09.094156 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:09.130024 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:10.165740 #3966] INFO -- [req_id cpi-770422]: Searching for LogicalPorts for vm 'vm-a39479e0-66a7-44eb-956e-b4682dde9ab5' I, [2021-10-14T00:38:10.246598 #3966] INFO -- [req_id cpi-770422]: Searching VIFs with 'owner_vm_id: 5009c816-858a-4e1a-0080-a1b814b7a5a4' I, [2021-10-14T00:38:10.332756 #3966] INFO -- [req_id cpi-770422]: Searching LogicalPorts with 'attachment_id: 09297dfa-dbb5-4a95-af59-91b6c76f2649' I, [2021-10-14T00:38:10.389155 #3966] INFO -- [req_id cpi-770422]: Failed to remove VM from NSGroups: Logical port for VM vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 with 'external_id' 5009c816-858a-4e1a-0080-a1b814b7a5a4 was expected in NSX-T but was not found D, [2021-10-14T00:38:10.452115 #3966] DEBUG -- [req_id cpi-770422]: Running method 'Destroy_Task'... D, [2021-10-14T00:38:10.496260 #3966] DEBUG -- [req_id cpi-770422]: Starting task 'VirtualMachine.destroy'... D, [2021-10-14T00:39:14.216502 #3966] DEBUG -- [req_id cpi-770422]: Finished task 'VirtualMachine.destroy' after 63.719982736 seconds I, [2021-10-14T00:39:14.216928 #3966] INFO -- [req_id cpi-770422]: Deleted vm: vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 I, [2021-10-14T00:39:14.217242 #3966] INFO -- [req_id cpi-770422]: Finished delete_vm in 147.12 seconds D, [2021-10-14T00:39:14.219106 #3966] DEBUG -- [req_id cpi-770422]: Running method 'Logout'... I, [2021-10-14T00:33:59.199141 #3867] INFO -- [req_id cpi-613358]: Starting create_vm... I, [2021-10-14T00:33:59.199379 #3867] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:34:02.586898 #3867] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:34:07.888619 #3867] DEBUG -- [req_id cpi-613358]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:34:07.996593 #3867] DEBUG -- [req_id cpi-613358]: Running method 'Login'... D, [2021-10-14T00:34:09.301364 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.317057 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:09.375006 #3867] INFO -- [req_id cpi-613358]: Using global ephemeral disk datastore pattern: ^(vdnetSharedStorage)$ I, [2021-10-14T00:34:09.375120 #3867] INFO -- [req_id cpi-613358]: Using global datastore pattern ^(vdnetSharedStorage)$ and global datastore cluster pattern ^()$ persistent: false D, [2021-10-14T00:34:09.375217 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.420834 #3867] INFO -- [req_id cpi-613358]: clusters: [] D, [2021-10-14T00:34:09.421072 #3867] DEBUG -- [req_id cpi-613358]: All clusters provided: {"os-compute-cluster-1"=>#<VSphereCloud::ClusterConfig:0x0000563f986e6bc0 @name="os-compute-cluster-1", @config={"resource_pool"=>"PKSWorkerPool"}>} D, [2021-10-14T00:34:09.421206 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.584626 #3867] INFO -- [req_id cpi-613358]: Initiating VM Allocator with VM Placement Criteria: Disk Config: [Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS:] Req Memory: 4096 Mem Headroom: 128 I, [2021-10-14T00:34:09.584745 #3867] INFO -- [req_id cpi-613358]: Gathering vm placement resources for vm placement allocator pipeline D, [2021-10-14T00:34:09.727315 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.760431 #3867] DEBUG -- [req_id cpi-613358]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.813454 #3867] DEBUG -- [req_id cpi-613358]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.843609 #3867] DEBUG -- [req_id cpi-613358]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 190960, host group free memory: 190960 for free memory required: 4224 D, [2021-10-14T00:34:09.843793 #3867] DEBUG -- [req_id cpi-613358]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:09.843873 #3867] DEBUG -- [req_id cpi-613358]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:09.850898 #3867] INFO -- [req_id cpi-613358]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.063512 #3867] DEBUG -- [req_id cpi-613358]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: D, [2021-10-14T00:34:10.063756 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.085535 #3867] DEBUG -- [req_id cpi-613358]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.143663 #3867] DEBUG -- [req_id cpi-613358]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.179612 #3867] DEBUG -- [req_id cpi-613358]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 191583, host group free memory: 191583 for free memory required: 4224 D, [2021-10-14T00:34:10.179800 #3867] DEBUG -- [req_id cpi-613358]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:10.179884 #3867] DEBUG -- [req_id cpi-613358]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.180062 #3867] INFO -- [req_id cpi-613358]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.264112 #3867] DEBUG -- [req_id cpi-613358]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.264436 #3867] INFO -- [req_id cpi-613358]: Creating vm: vm-987ceaf0-8104-45c4-a9d9-5c3386433d15 on <[Vim.ClusterComputeResource] domain-c9> stored in <[Vim.Datastore] datastore-15> D, [2021-10-14T00:34:10.264513 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.276321 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:10.409650 #3867] INFO -- [req_id cpi-613358]: Searching for stemcell sc-e071f887-2924-427d-9ad1-746a81a94e75 on datastore vdnetSharedStorage D, [2021-10-14T00:34:10.409812 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.432906 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CreateContainerView'... D, [2021-10-14T00:34:10.810956 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindExtension'... I, [2021-10-14T00:34:10.842402 #3867] INFO -- [req_id cpi-613358]: Trying to find network pks-8117c759-0f27-4dc1-bd81-ba372c842596 for 1 time D, [2021-10-14T00:34:10.842601 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:11.683890 #3867] INFO -- [req_id cpi-613358]: Cloning vm: (VSphereCloud::Resources::VM (cid="sc-e071f887-2924-427d-9ad1-746a81a94e75")) to vm-987ceaf0-8104-45c4-a9d9-5c3386433d15 D, [2021-10-14T00:34:11.691902 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:11.710495 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... D, [2021-10-14T00:34:11.763143 #3867] DEBUG -- [req_id cpi-613358]: Starting task 'VirtualMachine.clone'... W, [2021-10-14T00:35:09.887400 #3867] WARN -- [req_id cpi-613358]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:35:10.893840 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:35:10.902831 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... W, [2021-10-14T00:35:10.947591 #3867] WARN -- [req_id cpi-613358]: Retrying task 'VirtualMachine.clone', 1 attempts so far... W, [2021-10-14T00:36:08.897999 #3867] WARN -- [req_id cpi-613358]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:36:10.899051 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:36:10.909820 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... W, [2021-10-14T00:36:10.944961 #3867] WARN -- [req_id cpi-613358]: Retrying task 'VirtualMachine.clone', 2 attempts so far... W, [2021-10-14T00:37:08.910648 #3867] WARN -- [req_id cpi-613358]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:37:12.915414 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:37:12.926271 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... W, [2021-10-14T00:37:12.976644 #3867] WARN -- [req_id cpi-613358]: Retrying task 'VirtualMachine.clone', 3 attempts so far... W, [2021-10-14T00:38:10.946289 #3867] WARN -- [req_id cpi-613358]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:38:18.951173 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:38:18.962111 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... W, [2021-10-14T00:38:19.008249 #3867] WARN -- [req_id cpi-613358]: Retrying task 'VirtualMachine.clone', 4 attempts so far... W, [2021-10-14T00:39:15.936168 #3867] WARN -- [req_id cpi-613358]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:39:31.951559 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:39:31.980834 #3867] DEBUG -- [req_id cpi-613358]: Running method 'CloneVM_Task'... W, [2021-10-14T00:39:32.018020 #3867] WARN -- [req_id cpi-613358]: Retrying task 'VirtualMachine.clone', 5 attempts so far... D, [2021-10-14T00:39:35.076322 #3867] DEBUG -- [req_id cpi-613358]: Finished task 'VirtualMachine.clone' after 3.057336964 seconds D, [2021-10-14T00:39:35.133989 #3867] DEBUG -- [req_id cpi-613358]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:39:35.257344 #3867] INFO -- [req_id cpi-613358]: Using ephemeral disk UUID 6000c292-753b-aa79-2a56-e3204eedc8d4 I, [2021-10-14T00:39:35.267555 #3867] INFO -- [req_id cpi-613358]: Updating current agent env from vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' in datacenter 'folder-os-test-dc/os-test-dc' I, [2021-10-14T00:39:35.369667 #3867] INFO -- [req_id cpi-613358]: Cleaning current agent env from vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:39:35.447659 #3867] INFO -- [req_id cpi-613358]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:39:35.559190 #3867] INFO -- [req_id cpi-613358]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-987ceaf0-8104-45c4-a9d9-5c3386433d15/env.json?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:39:35.559699 #3867] DEBUG -- [req_id cpi-613358]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:39:35.582900 #3867] INFO -- [req_id cpi-613358]: Uploading file to https://192.161.243.45/folder/vm-987ceaf0-8104-45c4-a9d9-5c3386433d15/env.json?dsName=vdnetSharedStorage... I, [2021-10-14T00:39:35.631172 #3867] INFO -- [req_id cpi-613358]: Successfully uploaded file. I, [2021-10-14T00:39:35.637950 #3867] INFO -- [req_id cpi-613358]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:39:35.721391 #3867] INFO -- [req_id cpi-613358]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-987ceaf0-8104-45c4-a9d9-5c3386433d15/env.iso?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:39:35.721581 #3867] DEBUG -- [req_id cpi-613358]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:39:35.741027 #3867] INFO -- [req_id cpi-613358]: Uploading file to https://192.161.243.45/folder/vm-987ceaf0-8104-45c4-a9d9-5c3386433d15/env.iso?dsName=vdnetSharedStorage... I, [2021-10-14T00:39:35.800207 #3867] INFO -- [req_id cpi-613358]: Successfully uploaded file. D, [2021-10-14T00:39:35.846515 #3867] DEBUG -- [req_id cpi-613358]: Running method 'ReconfigVM_Task'... D, [2021-10-14T00:39:35.880635 #3867] DEBUG -- [req_id cpi-613358]: Starting task 'VirtualMachine.reconfigure'... D, [2021-10-14T00:39:37.920530 #3867] DEBUG -- [req_id cpi-613358]: Finished task 'VirtualMachine.reconfigure' after 2.039653983 seconds I, [2021-10-14T00:39:37.920861 #3867] INFO -- [req_id cpi-613358]: Upgrading virtual hardware on VM D, [2021-10-14T00:39:37.920995 #3867] DEBUG -- [req_id cpi-613358]: Running method 'UpgradeVM_Task'... D, [2021-10-14T00:39:37.943471 #3867] DEBUG -- [req_id cpi-613358]: Starting task 'VirtualMachine.upgradeVirtualHardware'... D, [2021-10-14T00:39:38.969985 #3867] DEBUG -- [req_id cpi-613358]: Finished task 'VirtualMachine.upgradeVirtualHardware' after 1.02625845 seconds I, [2021-10-14T00:39:38.970215 #3867] INFO -- [req_id cpi-613358]: Powering on VM: (VSphereCloud::Resources::VM (cid="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15")) D, [2021-10-14T00:39:39.012966 #3867] DEBUG -- [req_id cpi-613358]: Running method 'PowerOnMultiVM_Task'... D, [2021-10-14T00:39:39.035670 #3867] DEBUG -- [req_id cpi-613358]: Starting task 'Datacenter.powerOnVm'... D, [2021-10-14T00:39:40.064044 #3867] DEBUG -- [req_id cpi-613358]: Finished task 'Datacenter.powerOnVm' after 1.028143665 seconds D, [2021-10-14T00:39:40.074892 #3867] DEBUG -- [req_id cpi-613358]: Starting task 'Drm.ExecuteVmPowerOnLRO'... D, [2021-10-14T00:39:40.086056 #3867] DEBUG -- [req_id cpi-613358]: Finished task 'Drm.ExecuteVmPowerOnLRO' after 0.010961013 seconds I, [2021-10-14T00:39:45.211488 #3867] INFO -- [req_id cpi-613358]: Finished create_vm in 346.01 seconds D, [2021-10-14T00:39:45.212191 #3867] DEBUG -- [req_id cpi-613358]: Running method 'Logout'... I, [2021-10-14T00:39:46.955341 #4112] INFO -- [req_id cpi-831182]: Starting info... I, [2021-10-14T00:39:46.955605 #4112] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:39:46.990011 #4112] INFO -- [req_id cpi-831182]: Finished info in 0.03 seconds I, [2021-10-14T00:39:48.457888 #4114] INFO -- [req_id cpi-821501]: Starting set_vm_metadata... I, [2021-10-14T00:39:48.458164 #4114] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:39:50.217575 #4114] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:39:52.777827 #4114] DEBUG -- [req_id cpi-821501]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:39:52.884297 #4114] DEBUG -- [req_id cpi-821501]: Running method 'Login'... D, [2021-10-14T00:39:53.318616 #4114] DEBUG -- [req_id cpi-821501]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:39:53.325714 #4114] DEBUG -- [req_id cpi-821501]: Running method 'CreateContainerView'... D, [2021-10-14T00:39:53.381282 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.391740 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'director' already exists.'. W, [2021-10-14T00:39:53.391932 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'director' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.428763 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.438285 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.449530 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'deployment' already exists.'. W, [2021-10-14T00:39:53.449742 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'deployment' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.485346 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.493466 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.503250 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'id' already exists.'. W, [2021-10-14T00:39:53.503475 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'id' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.545753 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.557580 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.569178 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'job' already exists.'. W, [2021-10-14T00:39:53.569686 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'job' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.611682 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.627354 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.637604 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'instance_group' already exists.'. W, [2021-10-14T00:39:53.637843 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'instance_group' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.670800 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.679004 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.688257 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'index' already exists.'. W, [2021-10-14T00:39:53.688438 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'index' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.768672 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.778851 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.787218 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'name' already exists.'. W, [2021-10-14T00:39:53.787413 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'name' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.811640 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:53.819565 #4114] DEBUG -- [req_id cpi-821501]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:39:53.828334 #4114] WARN -- [req_id cpi-821501]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'created_at' already exists.'. W, [2021-10-14T00:39:53.828499 #4114] WARN -- [req_id cpi-821501]: Custom field definition already exists: The name 'created_at' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:39:53.852622 #4114] DEBUG -- [req_id cpi-821501]: Running method 'SetField'... D, [2021-10-14T00:39:59.013320 #4114] DEBUG -- [req_id cpi-821501]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:39:59.020460 #4114] INFO -- [req_id cpi-821501]: Checking if dvportgroup-183 is backed by NSXT I, [2021-10-14T00:39:59.090535 #4114] INFO -- [req_id cpi-821501]: DVPG dvportgroup-183 is backed by NSXT I, [2021-10-14T00:39:59.120633 #4114] INFO -- [req_id cpi-821501]: NIC with device key 4000 is backed by NSXT DVPG I, [2021-10-14T00:39:59.120803 #4114] INFO -- [req_id cpi-821501]: NSX-T networks found for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15': ["DVSwitch: 50 09 71 80 3e 48 1b d1-51 2f f6 5f bd 2c ce 95"] I, [2021-10-14T00:39:59.120922 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:39:59.252752 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x000055851196fbe0 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x000055851196efb0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x000055851196f730

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x000055851196e7e0

@_last_sync_time=1634171900144, @compute_ids= ["moIdOnHost:55", "hostLocalId:55", "locationId:", "instanceUuid:50097d74-c677-9428-76e6-52d06d5c0d91", "externalId:50097d74-c677-9428-76e6-52d06d5c0d91", "biosUuid:4209e4e4-2544-163f-9c04-22903dbf7db5"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50097d74-c677-9428-76e6-52d06d5c0d91", @guest_info=

<NSXT::GuestInfo:0x000055851196dbb0 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x000055851196e330

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:00.254282 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:00.311100 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x00005585119ea200 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x00005585119e95f8 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x00005585119e9d50

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x00005585119e8bd0

<NSXT::GuestInfo:0x00005585119ef750 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x00005585119e8608

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:01.312690 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:01.353756 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511a4ad30 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511a49bd8 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511a4a880

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511a48bc0

<NSXT::GuestInfo:0x0000558511a27650 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511a27e20

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:02.355050 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:02.429751 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511a85c00 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511a84fd0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511a85728

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511a84828

<NSXT::GuestInfo:0x0000558511a9bb90 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511a84378

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:03.431150 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:03.468910 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511a89a08 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511a888b0 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511a89238

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511a88108

<NSXT::GuestInfo:0x0000558511ab34c0 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511ab3c68

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:04.470451 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:04.517344 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511b05db0 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511b05158 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511b05900

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511b049b0

<NSXT::GuestInfo:0x0000558511b53d80 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511b04500

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:05.519033 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:05.561222 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511b8e9a8 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511b8ce50 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511b8dff8

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511b6be08

<NSXT::GuestInfo:0x0000558511b6b1b0 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511b6b908

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:06.562954 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:06.605646 #4114] INFO -- [req_id cpi-821501]: Virtual Machines fetched : [#<NSXT::VirtualMachine:0x0000558511bc1a10 @_last_sync_time=1634171995313, @compute_ids= ["moIdOnHost:43", "hostLocalId:43", "locationId:564d0735-ca5d-66a3-50d5-dbcbef6e148e", "instanceUuid:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "externalId:50090a2a-28cb-f7f9-f2dd-4c8713cda88b", "biosUuid:42091c88-3aa8-c898-a335-0d9f5806fb44"], @display_name="vm-987ceaf0-8104-45c4-a9d9-5c3386433d15", @external_id="50090a2a-28cb-f7f9-f2dd-4c8713cda88b", @guest_info=

<NSXT::GuestInfo:0x0000558511bc0db8 @computer_name="", @os_name="">,

@host_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba", @local_id_on_host="43", @power_state="VM_RUNNING", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511bc1510

@is_valid=true,
@target_display_name="192.161.129.207",
@target_id="7c1f2c4e-43ea-463e-ab04-e1e64a5636ba",
@target_type="HostNode">,

@type="REGULAR">,

<NSXT::VirtualMachine:0x0000558511bc0610

<NSXT::GuestInfo:0x0000558511bd6e60 @computer_name="", @os_name="">,

@host_id="dc49e693-0dd9-4feb-b993-fb4421112214", @local_id_on_host="55", @power_state="VM_STOPPED", @resource_type="VirtualMachine", @source=

<NSXT::ResourceReference:0x0000558511bc0110

@is_valid=true,
@target_display_name="192.161.243.42",
@target_id="dc49e693-0dd9-4feb-b993-fb4421112214",
@target_type="HostNode">,

@type="REGULAR">]

I, [2021-10-14T00:40:07.607243 #4114] INFO -- [req_id cpi-821501]: Searching for LogicalPorts for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15' I, [2021-10-14T00:40:07.675573 #4114] INFO -- [req_id cpi-821501]: Searching VIFs with 'owner_vm_id: 50090a2a-28cb-f7f9-f2dd-4c8713cda88b' I, [2021-10-14T00:40:07.755746 #4114] INFO -- [req_id cpi-821501]: Searching LogicalPorts with 'attachment_id: 910cfa28-c633-4397-b228-e7df77d65ffe' I, [2021-10-14T00:40:07.815713 #4114] INFO -- [req_id cpi-821501]: LogicalPorts found for vm 'vm-987ceaf0-8104-45c4-a9d9-5c3386433d15': ["c7972cd1-6119-42c5-97d2-2f65898bfee0"]' I, [2021-10-14T00:40:08.164291 #4114] INFO -- [req_id cpi-821501]: Finished set_vm_metadata in 19.71 seconds D, [2021-10-14T00:40:08.165266 #4114] DEBUG -- [req_id cpi-821501]: Running method 'Logout'... I, [2021-10-14T00:34:00.082223 #3872] INFO -- [req_id cpi-556665]: Starting create_vm... I, [2021-10-14T00:34:00.082383 #3872] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:34:03.509840 #3872] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:34:08.265966 #3872] DEBUG -- [req_id cpi-556665]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:34:08.342341 #3872] DEBUG -- [req_id cpi-556665]: Running method 'Login'... D, [2021-10-14T00:34:09.305209 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.314062 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:09.399113 #3872] INFO -- [req_id cpi-556665]: Using global ephemeral disk datastore pattern: ^(vdnetSharedStorage)$ I, [2021-10-14T00:34:09.399247 #3872] INFO -- [req_id cpi-556665]: Using global datastore pattern ^(vdnetSharedStorage)$ and global datastore cluster pattern ^()$ persistent: false D, [2021-10-14T00:34:09.399356 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.496951 #3872] INFO -- [req_id cpi-556665]: clusters: [] D, [2021-10-14T00:34:09.499393 #3872] DEBUG -- [req_id cpi-556665]: All clusters provided: {"os-compute-cluster-1"=>#<VSphereCloud::ClusterConfig:0x000055bc372c2178 @name="os-compute-cluster-1", @config={"resource_pool"=>"PKSWorkerPool"}>} D, [2021-10-14T00:34:09.499559 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:09.665085 #3872] INFO -- [req_id cpi-556665]: Initiating VM Allocator with VM Placement Criteria: Disk Config: [Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS:] Req Memory: 4096 Mem Headroom: 128 I, [2021-10-14T00:34:09.665230 #3872] INFO -- [req_id cpi-556665]: Gathering vm placement resources for vm placement allocator pipeline D, [2021-10-14T00:34:09.795020 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:09.823315 #3872] DEBUG -- [req_id cpi-556665]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.873426 #3872] DEBUG -- [req_id cpi-556665]: Fetching Memory utilization for Resource Pool PKS D, [2021-10-14T00:34:09.905424 #3872] DEBUG -- [req_id cpi-556665]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 190960, host group free memory: 190960 for free memory required: 4224 D, [2021-10-14T00:34:09.911995 #3872] DEBUG -- [req_id cpi-556665]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:09.912136 #3872] DEBUG -- [req_id cpi-556665]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:09.912502 #3872] INFO -- [req_id cpi-556665]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.126293 #3872] DEBUG -- [req_id cpi-556665]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: D, [2021-10-14T00:34:10.126527 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.152721 #3872] DEBUG -- [req_id cpi-556665]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.184397 #3872] DEBUG -- [req_id cpi-556665]: Fetching Memory utilization for Resource Pool PKSWorkerPool D, [2021-10-14T00:34:10.205494 #3872] DEBUG -- [req_id cpi-556665]: Filter VM Placement Cluster: os-compute-cluster-1 Cluster free memory: 191583, host group free memory: 191583 for free memory required: 4224 D, [2021-10-14T00:34:10.205763 #3872] DEBUG -- [req_id cpi-556665]: Filter VM Placement Cluster: os-compute-cluster-1 hosts: datastores: [<Datastore: / vdtest>, <Datastore: / datastore>, <Datastore: / vdnetSharedStorage>, <Datastore: / datastore (1)>, <Datastore: / datastore (2)>] for combination of DS satisfying disk configurations D, [2021-10-14T00:34:10.205919 #3872] DEBUG -- [req_id cpi-556665]: Trying to find placement for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.206081 #3872] INFO -- [req_id cpi-556665]: Initiating Disk Allocator with Storage Criteria: Space Req: 32768 Target Pattern: ^(vdnetSharedStorage)$ Existing-DS Pattern: D, [2021-10-14T00:34:10.297379 #3872] DEBUG -- [req_id cpi-556665]: Found <Datastore: / vdnetSharedStorage> for Disk ==> Disk CID: Size:32768 Ephemeral:true Target-DS:^(vdnetSharedStorage)$ Existing-DS: I, [2021-10-14T00:34:10.297712 #3872] INFO -- [req_id cpi-556665]: Creating vm: vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59 on <[Vim.ClusterComputeResource] domain-c9> stored in <[Vim.Datastore] datastore-15> D, [2021-10-14T00:34:10.297826 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.308362 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CreateContainerView'... I, [2021-10-14T00:34:10.405518 #3872] INFO -- [req_id cpi-556665]: Searching for stemcell sc-e071f887-2924-427d-9ad1-746a81a94e75 on datastore vdnetSharedStorage D, [2021-10-14T00:34:10.418839 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:10.429136 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CreateContainerView'... D, [2021-10-14T00:34:10.818057 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindExtension'... I, [2021-10-14T00:34:10.837934 #3872] INFO -- [req_id cpi-556665]: Trying to find network pks-8117c759-0f27-4dc1-bd81-ba372c842596 for 1 time D, [2021-10-14T00:34:10.846628 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:34:11.656380 #3872] INFO -- [req_id cpi-556665]: Cloning vm: (VSphereCloud::Resources::VM (cid="sc-e071f887-2924-427d-9ad1-746a81a94e75")) to vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59 D, [2021-10-14T00:34:11.656594 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:34:11.665813 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... D, [2021-10-14T00:34:11.712286 #3872] DEBUG -- [req_id cpi-556665]: Starting task 'VirtualMachine.clone'... W, [2021-10-14T00:35:09.876669 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:35:10.879371 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:35:10.890042 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:35:10.938980 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 1 attempts so far... W, [2021-10-14T00:36:08.859702 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:36:10.862400 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:36:10.872472 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:36:10.906835 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 2 attempts so far... W, [2021-10-14T00:37:08.872576 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:37:12.877242 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:37:12.888745 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:37:12.924347 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 3 attempts so far... W, [2021-10-14T00:38:10.934314 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:38:18.935492 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:38:18.946840 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:38:18.988193 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 4 attempts so far... W, [2021-10-14T00:39:15.923678 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:39:31.932971 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:39:31.957091 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:39:31.988816 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 5 attempts so far... W, [2021-10-14T00:40:29.188880 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:41:01.221649 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:41:01.243870 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:41:01.288055 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 6 attempts so far... W, [2021-10-14T00:41:58.141855 #3872] WARN -- [req_id cpi-556665]: Error running task 'VirtualMachine.clone'. Failed with message 'An error occurred during host configuration.' and fault message ''. D, [2021-10-14T00:42:30.163414 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:42:30.187260 #3872] DEBUG -- [req_id cpi-556665]: Running method 'CloneVM_Task'... W, [2021-10-14T00:42:30.228412 #3872] WARN -- [req_id cpi-556665]: Retrying task 'VirtualMachine.clone', 7 attempts so far... D, [2021-10-14T00:42:33.296202 #3872] DEBUG -- [req_id cpi-556665]: Finished task 'VirtualMachine.clone' after 3.067496083 seconds D, [2021-10-14T00:42:33.359990 #3872] DEBUG -- [req_id cpi-556665]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:42:33.496058 #3872] INFO -- [req_id cpi-556665]: Using ephemeral disk UUID 6000c29d-6584-3d50-c1ea-42422cc4da63 I, [2021-10-14T00:42:33.507255 #3872] INFO -- [req_id cpi-556665]: Updating current agent env from vm 'vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59' in datacenter 'folder-os-test-dc/os-test-dc' I, [2021-10-14T00:42:33.562328 #3872] INFO -- [req_id cpi-556665]: Cleaning current agent env from vm 'vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59' I, [2021-10-14T00:42:33.642606 #3872] INFO -- [req_id cpi-556665]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:42:33.733438 #3872] INFO -- [req_id cpi-556665]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59/env.json?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:42:33.733630 #3872] DEBUG -- [req_id cpi-556665]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:42:33.758869 #3872] INFO -- [req_id cpi-556665]: Uploading file to https://192.161.243.45/folder/vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59/env.json?dsName=vdnetSharedStorage... I, [2021-10-14T00:42:33.811335 #3872] INFO -- [req_id cpi-556665]: Successfully uploaded file. I, [2021-10-14T00:42:33.827593 #3872] INFO -- [req_id cpi-556665]: Trying to upload file to Datastore through Host System I, [2021-10-14T00:42:33.911771 #3872] INFO -- [req_id cpi-556665]: Acquiring generic service ticket for URL: https://192.161.243.45/folder/vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59/env.iso?dsName=vdnetSharedStorage and Method: httpPut D, [2021-10-14T00:42:33.912445 #3872] DEBUG -- [req_id cpi-556665]: Running method 'AcquireGenericServiceTicket'... I, [2021-10-14T00:42:33.936266 #3872] INFO -- [req_id cpi-556665]: Uploading file to https://192.161.243.45/folder/vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59/env.iso?dsName=vdnetSharedStorage... I, [2021-10-14T00:42:33.992596 #3872] INFO -- [req_id cpi-556665]: Successfully uploaded file. D, [2021-10-14T00:42:34.045556 #3872] DEBUG -- [req_id cpi-556665]: Running method 'ReconfigVM_Task'... D, [2021-10-14T00:42:34.077330 #3872] DEBUG -- [req_id cpi-556665]: Starting task 'VirtualMachine.reconfigure'... D, [2021-10-14T00:42:35.105549 #3872] DEBUG -- [req_id cpi-556665]: Finished task 'VirtualMachine.reconfigure' after 1.028008773 seconds I, [2021-10-14T00:42:35.105896 #3872] INFO -- [req_id cpi-556665]: Upgrading virtual hardware on VM D, [2021-10-14T00:42:35.106082 #3872] DEBUG -- [req_id cpi-556665]: Running method 'UpgradeVM_Task'... D, [2021-10-14T00:42:35.132459 #3872] DEBUG -- [req_id cpi-556665]: Starting task 'VirtualMachine.upgradeVirtualHardware'... D, [2021-10-14T00:42:36.208885 #3872] DEBUG -- [req_id cpi-556665]: Finished task 'VirtualMachine.upgradeVirtualHardware' after 1.07619415 seconds I, [2021-10-14T00:42:36.209143 #3872] INFO -- [req_id cpi-556665]: Powering on VM: (VSphereCloud::Resources::VM (cid="vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59")) D, [2021-10-14T00:42:36.260187 #3872] DEBUG -- [req_id cpi-556665]: Running method 'PowerOnMultiVM_Task'... D, [2021-10-14T00:42:36.290127 #3872] DEBUG -- [req_id cpi-556665]: Starting task 'Datacenter.powerOnVm'... D, [2021-10-14T00:42:36.304665 #3872] DEBUG -- [req_id cpi-556665]: Finished task 'Datacenter.powerOnVm' after 0.014364854 seconds D, [2021-10-14T00:42:36.317316 #3872] DEBUG -- [req_id cpi-556665]: Starting task 'Drm.ExecuteVmPowerOnLRO'... D, [2021-10-14T00:44:37.615784 #3872] DEBUG -- [req_id cpi-556665]: Finished task 'Drm.ExecuteVmPowerOnLRO' after 121.298215347 seconds I, [2021-10-14T00:44:42.545900 #3872] INFO -- [req_id cpi-556665]: Finished create_vm in 642.46 seconds D, [2021-10-14T00:44:42.546865 #3872] DEBUG -- [req_id cpi-556665]: Running method 'Logout'... I, [2021-10-14T00:44:44.009945 #4254] INFO -- [req_id cpi-511430]: Starting info... I, [2021-10-14T00:44:44.010229 #4254] INFO -- : Fetching vSphere version to locate SDK I, [2021-10-14T00:44:44.041562 #4254] INFO -- [req_id cpi-511430]: Finished info in 0.03 seconds I, [2021-10-14T00:44:45.538753 #4256] INFO -- [req_id cpi-826051]: Starting set_vm_metadata... I, [2021-10-14T00:44:45.538983 #4256] INFO -- : Fetching vSphere version to locate SDK /var/vcap/data/packages/vsphere_cpi/7f06c02660756b11e5d0d6b42c1de5c9ce1e89d1/lib/ruby_vim_sdk/vmomi_support.rb:56: warning: constant ::Fixnum is deprecated I, [2021-10-14T00:44:47.032632 #4256] INFO -- : Loaded vSphere 7.0 SDK D, [2021-10-14T00:44:49.597189 #4256] DEBUG -- [req_id cpi-826051]: Running method 'RetrieveServiceContent'... D, [2021-10-14T00:44:49.681829 #4256] DEBUG -- [req_id cpi-826051]: Running method 'Login'... D, [2021-10-14T00:44:50.168653 #4256] DEBUG -- [req_id cpi-826051]: Running method 'FindByInventoryPath'... D, [2021-10-14T00:44:50.181727 #4256] DEBUG -- [req_id cpi-826051]: Running method 'CreateContainerView'... D, [2021-10-14T00:44:50.235395 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.248997 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'director' already exists.'. W, [2021-10-14T00:44:50.249317 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'director' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.292964 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.302468 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.315986 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'deployment' already exists.'. W, [2021-10-14T00:44:50.316210 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'deployment' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.352271 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.364360 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.376295 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'id' already exists.'. W, [2021-10-14T00:44:50.376555 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'id' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.419342 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.431796 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.444095 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'job' already exists.'. W, [2021-10-14T00:44:50.444377 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'job' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.490451 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.502563 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.516643 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'instance_group' already exists.'. W, [2021-10-14T00:44:50.516893 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'instance_group' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.553409 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.562037 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.572549 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'index' already exists.'. W, [2021-10-14T00:44:50.572736 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'index' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.665491 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.678525 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.687535 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'name' already exists.'. W, [2021-10-14T00:44:50.687778 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'name' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.713469 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:50.721087 #4256] DEBUG -- [req_id cpi-826051]: Running method 'AddCustomFieldDef'... W, [2021-10-14T00:44:50.729185 #4256] WARN -- [req_id cpi-826051]: Error running method 'AddCustomFieldDef'. Failed with message 'The name 'created_at' already exists.'. W, [2021-10-14T00:44:50.729399 #4256] WARN -- [req_id cpi-826051]: Custom field definition already exists: The name 'created_at' already exists.; Running method 'AddCustomFieldDef' D, [2021-10-14T00:44:50.756909 #4256] DEBUG -- [req_id cpi-826051]: Running method 'SetField'... D, [2021-10-14T00:44:56.264005 #4256] DEBUG -- [req_id cpi-826051]: Running method 'FindByInventoryPath'... I, [2021-10-14T00:44:56.271081 #4256] INFO -- [req_id cpi-826051]: Checking if dvportgroup-183 is backed by NSXT I, [2021-10-14T00:44:56.357588 #4256] INFO -- [req_id cpi-826051]: DVPG dvportgroup-183 is backed by NSXT I, [2021-10-14T00:44:56.387543 #4256] INFO -- [req_id cpi-826051]: NIC with device key 4000 is backed by NSXT DVPG I, [2021-10-14T00:44:56.387794 #4256] INFO -- [req_id cpi-826051]: NSX-T networks found for vm 'vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59': ["DVSwitch: 50 09 71 80 3e 48 1b d1-51 2f f6 5f bd 2c ce 95"] I, [2021-10-14T00:44:56.387968 #4256] INFO -- [req_id cpi-826051]: Searching for LogicalPorts for vm 'vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59' I, [2021-10-14T00:44:56.458025 #4256] INFO -- [req_id cpi-826051]: Searching VIFs with 'owner_vm_id: 500958a5-450f-1728-1aa6-437441e77a19' I, [2021-10-14T00:44:56.489445 #4256] INFO -- [req_id cpi-826051]: Searching LogicalPorts with 'attachment_id: 6726029a-6525-4eb4-ad98-fdffd98210d5' I, [2021-10-14T00:44:56.530422 #4256] INFO -- [req_id cpi-826051]: LogicalPorts found for vm 'vm-9fef6deb-86e1-417f-aa1a-878d8d9f3b59': ["b8c0e99c-87a2-43c7-8aed-02ae6b8977f3"]' I, [2021-10-14T00:44:56.774038 #4256] INFO -- [req_id cpi-826051]: Finished set_vm_metadata in 11.24 seconds D, [2021-10-14T00:44:56.775209 #4256] DEBUG -- [req_id cpi-826051]: Running method 'Logout'...

Task 2411 error

Capturing task '2411' output: Expected task '2411' to succeed but state is 'error'

Exit code 1

Expected behavior create pks clusters successfully

Screenshots no

Release Version & Related Info (please complete the following information): ubuntu@opsmanager-2-10:~$ bosh releases Using environment '192.168.100.9' as client 'ops_manager'

Name Version antrea 0.13.3-build.1 backup-and-restore-sdk 1.18.0 bosh-dns 1.29.0 bosh-metric-sink 0.3.18 bpm 1.1.11 kubo 1.13.0-buil kubo-service-adapter 1.12.0-build.312 kubo-windows 1.13.0-buil nsx-cf-cni 3.2.0.18707849 ~ 3.2.0.18696275 nsx-cf-cni-windows 3.2.0.18707849 ~ 3.2.0.18696275 pks-api 1.12.0-build.312 pks-nsx-t 1.82.0 pks-telemetry 2.0.0-build.508 pks-vrli 0.16.0 pks-vrops 0.21.1 pxc 0.37.0 sink-resources-release 3.0.0 syslog 11.7.5 ~ 11.6.1 system-metrics 2.0.12 uaa 74.5.25 vsphere-csi 2.3.0-build.55 wavefront-proxy 0.25.0 windows-gmsa 0.1.0-build.3 windows-syslog 1.1.3 windows-utilities 0.11.0 Commit Hash 0cea935 c5e3c2c f1433e0 a7dd64d 7cee2e9 d.6.bump-kubernetes-1.22.0+vmware.2 b8d196a 94912fb0 d.0.bump-kubernetes-1.22.0 46a9731 475185f+ ca789fd+ 475185f+ ca789fd+ f863b830 3859a19 353d5ce b8e17f3 80a2caf 352e319 ad4d5c4+ 107ad61 549977a d7d5a10 cdbc68d 9b3fe17+ 81ae841 non-git 05c1d2b 6466a01

Additional context Task 2411 [920/2910]

Task 2411 | 00:33:23 | Deprecation: Global 'properties' are deprecated. Please define 'properties' at the job level. Task 2411 | 00:33:26 | Preparing deployment: Preparing deployment Task 2411 | 00:33:28 | Warning: DNS address not available for the link provider instance: pivotal-container-service/93f6b920-e7b8-4a5e-beb3-6cad96af7b76 Task 2411 | 00:33:28 | Warning: DNS address not available for the link provider instance: pivotal-container-service/93f6b920-e7b8-4a5e-beb3-6cad96af7b76 Task 2411 | 00:33:28 | Warning: DNS address not available for the link provider instance: pivotal-container-service/93f6b920-e7b8-4a5e-beb3-6cad96af7b76 Task 2411 | 00:33:42 | Preparing deployment: Preparing deployment (00:00:16) Task 2411 | 00:33:42 | Preparing deployment: Rendering templates (00:00:09) Task 2411 | 00:33:52 | Preparing package compilation: Finding packages to compile (00:00:00) Task 2411 | 00:33:52 | Creating missing vms: master/688911f9-88a4-4e9e-bba3-4d4df2252b35 (0) Task 2411 | 00:33:52 | Creating missing vms: worker/2fc3befa-a7b9-4565-a293-d79802b160fa (1) Task 2411 | 00:33:52 | Creating missing vms: worker/630ad8ee-4f42-442b-8ba0-f88338433be1 (0) Task 2411 | 00:33:52 | Creating missing vms: worker/f15a9bbc-d286-4028-936e-b23ccf21ce79 (2) Task 2411 | 00:38:15 | Creating missing vms: worker/630ad8ee-4f42-442b-8ba0-f88338433be1 (0) (00:04:23) Task 2411 | 00:39:14 | Creating missing vms: master/688911f9-88a4-4e9e-bba3-4d4df2252b35 (0) (00:05:22) L Error: Unknown CPI error 'Unknown' with message 'Logical port for VM vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 with 'external_id' 5009c816-858a-4e1a-0080-a1b814b7a5a4 was expected in NSX-T but was not found' in 'set_vm_metadata' CPI method (CPI request ID: 'cpi-868324') Task 2411 | 00:40:34 | Creating missing vms: worker/f15a9bbc-d286-4028-936e-b23ccf21ce79 (2) (00:06:42) Task 2411 | 00:45:25 | Creating missing vms: worker/2fc3befa-a7b9-4565-a293-d79802b160fa (1) (00:11:33) Task 2411 | 00:45:25 | Error: Unknown CPI error 'Unknown' with message 'Logical port for VM vm-a39479e0-66a7-44eb-956e-b4682dde9ab5 with 'external_id' 5009c816-858a-4e1a-0080-a1b814b7a5a4 was expected in NSX-T but was not found' in 'set_vm_metadata' CPI method (CPI request ID: 'cpi-868324')

Task 2411 Started Thu Oct 14 00:33:23 UTC 2021 Task 2411 Finished Thu Oct 14 00:45:25 UTC 2021 Task 2411 Duration 00:12:02 Task 2411 error

Capturing task '2411' output: Expected task '2411' to succeed but state is 'error'

Exit code 1

cloudfoundry / bosh-vsphere-cpi-release

Failed to create PKS cluster with CPI error Logical port for xxx with 'external_id' *** was expected in NSX-T but was not found' in 'set_vm_metadata' CPI method (CPI request ID: 'cpi-868324') #307

<NSXT::GuestInfo:0x00005636739ddfa0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x00005636739de6f8

<NSXT::VirtualMachine:0x00005636739dd7f8

<NSXT::GuestInfo:0x00005636739dcbf0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x00005636739dd348

<NSXT::GuestInfo:0x0000563673a40218 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673a40970

<NSXT::VirtualMachine:0x0000563673a53a20

<NSXT::GuestInfo:0x0000563673a52e18 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673a53570

<NSXT::GuestInfo:0x0000563673a82708 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673a82e60

<NSXT::VirtualMachine:0x0000563673a81f60

<NSXT::GuestInfo:0x0000563673a81358 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673a81ab0

<NSXT::GuestInfo:0x0000563673ab8c90 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673ab93e8

<NSXT::VirtualMachine:0x0000563673ab84e8

<NSXT::GuestInfo:0x0000563673acb890 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673ab8038

<NSXT::GuestInfo:0x0000563673afb158 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673afb8b0

<NSXT::VirtualMachine:0x0000563673afa9b0

<NSXT::GuestInfo:0x0000563673af9da8 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673afa500

<NSXT::GuestInfo:0x0000563673b316e0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673b31e38

<NSXT::VirtualMachine:0x0000563673b30f38

<NSXT::GuestInfo:0x0000563673b30330 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673b30a88

<NSXT::GuestInfo:0x0000563673b73bd0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673b64388

<NSXT::VirtualMachine:0x0000563673b73428

<NSXT::GuestInfo:0x0000563673b72820 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673b72f78

<NSXT::GuestInfo:0x0000563673ba6170 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673ba68c8

<NSXT::VirtualMachine:0x0000563673ba59c8

<NSXT::GuestInfo:0x0000563673ba4dc0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673ba5518

<NSXT::GuestInfo:0x0000563673bdc6a8 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673bdce00

<NSXT::VirtualMachine:0x0000563673bebea0

<NSXT::GuestInfo:0x0000563673beb298 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673beb9f0

<NSXT::GuestInfo:0x0000563673c1ebc0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673c1f318

<NSXT::VirtualMachine:0x0000563673c1e418

<NSXT::GuestInfo:0x0000563673c1d810 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000563673c1df68

<NSXT::GuestInfo:0x000055851196efb0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x000055851196f730

<NSXT::VirtualMachine:0x000055851196e7e0

<NSXT::GuestInfo:0x000055851196dbb0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x000055851196e330

<NSXT::GuestInfo:0x00005585119e95f8 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x00005585119e9d50

<NSXT::VirtualMachine:0x00005585119e8bd0

<NSXT::GuestInfo:0x00005585119ef750 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x00005585119e8608

<NSXT::GuestInfo:0x0000558511a49bd8 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511a4a880

<NSXT::VirtualMachine:0x0000558511a48bc0

<NSXT::GuestInfo:0x0000558511a27650 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511a27e20

<NSXT::GuestInfo:0x0000558511a84fd0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511a85728

<NSXT::VirtualMachine:0x0000558511a84828

<NSXT::GuestInfo:0x0000558511a9bb90 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511a84378

<NSXT::GuestInfo:0x0000558511a888b0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511a89238

<NSXT::VirtualMachine:0x0000558511a88108

<NSXT::GuestInfo:0x0000558511ab34c0 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511ab3c68

<NSXT::GuestInfo:0x0000558511b05158 @computer_name="", @os_name="">,

<NSXT::ResourceReference:0x0000558511b05900

<NSXT::VirtualMachine:0x0000558511b049b0