geekza opened a new issue #3285: Cross cluster cold migration failed in vmware URL: https://github.com/apache/cloudstack/issues/3285 <!-- Verify first that your issue/request is not already reported on GitHub. Also test if the latest release and master branch are affected too. Always add information AFTER of these HTML comments, but no need to delete the comments. --> ##### ISSUE TYPE <!-- Pick one below and delete the rest --> * Bug Report ##### COMPONENT NAME <!-- Categorize the issue, e.g. API, VR, VPN, UI, etc. --> Management Server VMWare ~~~ ~~~ ##### CLOUDSTACK VERSION <!-- New line separated list of affected versions, commit ID for issues on master branch. --> ~~~ 4.9.3.1 ~~~ ##### CONFIGURATION <!-- Information about the configuration if relevant, e.g. basic network, advanced networking, etc. N/A otherwise --> 2 or more VMWare cluster under a pod Zone wide primary storage ##### OS / ENVIRONMENT <!-- Information about the environment if relevant, N/A otherwise --> VMWare vSphere 5.5 ##### SUMMARY <!-- Explain the problem/feature briefly --> CloudStack cannot find the cold migrated VM between cluster so tries to register and gets "The specified key, name, or identifier already exists." error from VMWare ##### STEPS TO REPRODUCE <!-- For bugs, show exactly how to reproduce the problem, using a minimal test-case. Use Screenshots if accurate. For new features, show how the feature would be used. --> 1- Stop a VM in 1st cluster 2- Start that VM in a host of the 2nd cluster <!-- Paste example playbooks or commands between quotes below --> ~~~ ~~~ <!-- You can also paste gist.github.com links for larger files --> ##### EXPECTED RESULTS <!-- What did you expect to happen when running the steps above? --> 1- CloudStack migrate VM from 1st cluster to 2nd cluster 2- CloudStack start VM ~~~ ~~~ ##### ACTUAL RESULTS <!-- What actually happened? --> 1- CloudStak finds the VM in 1st cluster 2- CloudStack unregister the VM from vCenter 3- CloudStack register the VM in 2nd cluster 4- It seems that CloudStack don't set "cloud.vm.internal.name" custom attribute for newly registered VM 5- So CloudStack couldn't find newly registered VM 6- CloudStack tries to rollback VM unregistration on 1st cluster 7- But due to existence of VM with same name on 2nd cluster, we get "The specified key, name, or identifier already exists." error from VMWare <!-- Paste verbatim command output between quotes below --> Related logs: ~~~ 2019-04-22 19:03:50,104 DEBUG [c.c.a.ApiServlet] (http-8443-25:ctx-a75f2300) (logid:c6899750) ===START=== 192.168.123.14 -- GET command=startVirtualMachine&response=json&id=258074b6-2192-46a9-a330-6eba27a424d0&hostid=de416fe9-fcdf-488e-8214-b90b26eeb196&_=1555943629664 2019-04-22 19:03:50,172 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-110:ctx-05e121fc job-68311) (logid:460e9744) Add job-68311 into job monitoring 2019-04-22 19:03:50,177 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (http-8443-25:ctx-a75f2300 ctx-e21b0a18) (logid:c6899750) submit async job-68311, details: AsyncJobVO {id:68311, userId: 993, accountId: 576, instanceType: VirtualMachine, instanceId: 904, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"id":"258074b6-2192-46a9-a330-6eba27a424d0","response":"json","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"258074b6-2192-46a9-a330-6eba27a424d0\",\"interface com.cloud.host.Host\":\"de416fe9-fcdf-488e-8214-b90b26eeb196\"}","cmdEventType":"VM.START","hostid":"de416fe9-fcdf-488e-8214-b90b26eeb196","ctxUserId":"993","httpmethod":"GET","_":"1555943629664","uuid":"258074b6-2192-46a9-a330-6eba27a424d0","ctxAccountId":"576","ctxStartEventId":"211291"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345051240548, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2019-04-22 19:03:50,178 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311) (logid:08e004e5) Executing AsyncJobVO {id:68311, userId: 993, accountId: 576, instanceType: VirtualMachine, instanceId: 904, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"id":"258074b6-2192-46a9-a330-6eba27a424d0","response":"json","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"258074b6-2192-46a9-a330-6eba27a424d0\",\"interface com.cloud.host.Host\":\"de416fe9-fcdf-488e-8214-b90b26eeb196\"}","cmdEventType":"VM.START","hostid":"de416fe9-fcdf-488e-8214-b90b26eeb196","ctxUserId":"993","httpmethod":"GET","_":"1555943629664","uuid":"258074b6-2192-46a9-a330-6eba27a424d0","ctxAccountId":"576","ctxStartEventId":"211291"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345051240548, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2019-04-22 19:03:50,180 DEBUG [c.c.a.ApiServlet] (http-8443-25:ctx-a75f2300 ctx-e21b0a18) (logid:c6899750) ===END=== 192.168.123.14 -- GET command=startVirtualMachine&response=json&id=258074b6-2192-46a9-a330-6eba27a424d0&hostid=de416fe9-fcdf-488e-8214-b90b26eeb196&_=1555943629664 2019-04-22 19:03:50,263 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=216 2019-04-22 19:03:50,288 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=217 2019-04-22 19:03:50,314 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=224 2019-04-22 19:03:50,325 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=216 2019-04-22 19:03:50,331 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=217 2019-04-22 19:03:50,337 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Service SecurityGroup is not supported in the network id=224 2019-04-22 19:03:50,337 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Destination Host to deploy the VM is specified, specifying a deployment plan to deploy the VM 2019-04-22 19:03:50,373 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Deploy avoids pods: [], clusters: [], hosts: [] 2019-04-22 19:03:50,375 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@7ebba820 2019-04-22 19:03:50,375 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Trying to allocate a host and storage pools from dc:4, pod:4,cluster:4, requested cpu: 1000, requested ram: 536870912 2019-04-22 19:03:50,376 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Is ROOT volume READY (pool already allocated)?: Yes 2019-04-22 19:03:50,376 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 115 2019-04-22 19:03:50,379 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Looking for suitable pools for this host under zone: 4, pod: 4, cluster: 4 2019-04-22 19:03:50,387 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Checking suitable pools for volume (Id, Type): (4360,ROOT) 2019-04-22 19:03:50,387 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Volume has pool already allocated, checking if pool can be reused, poolId: 88 2019-04-22 19:03:50,398 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Planner need not allocate a pool for this volume since its READY 2019-04-22 19:03:50,398 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2019-04-22 19:03:50,398 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Checking if host: 115 can access any suitable storage pool for volume: ROOT 2019-04-22 19:03:50,401 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Host: 115 can access pool: 88 2019-04-22 19:03:50,403 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Found a potential host id: 115 name: host02.cloud.local and associated storage pools for this VM 2019-04-22 19:03:50,607 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-110:ctx-05e121fc job-68311 ctx-828e4b6c) (logid:08e004e5) Sync job-68314 execution on object VmWorkJobQueue.904 2019-04-22 19:03:52,133 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Use router's private IP for SSH control. IP : 172.19.1.8 2019-04-22 19:03:52,133 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Transforming com.cloud.agent.api.routing.DhcpEntryCommand to ConfigItems 2019-04-22 19:03:52,460 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Processing FileConfigItem, copying 232 characters to vm_dhcp_entry.json took 327ms 2019-04-22 19:03:52,460 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Run command on VR: 172.19.1.8, script: update_config.py with args: vm_dhcp_entry.json 2019-04-22 19:03:54,954 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) update_config.py execution result: true 2019-04-22 19:03:54,954 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Processing ScriptConfigItem, executing update_config.py vm_dhcp_entry.json took 2494ms 2019-04-22 19:03:54,954 WARN [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-329:ctx-3f9355f8 host01.cloud.local, job-68311/job-68314, cmd: DhcpEntryCommand) (logid:08e004e5) Expected 1 answers while executing DhcpEntryCommand but received 2 2019-04-22 19:03:56,544 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-116:ctx-d5faea00 host01.cloud.local, job-68311/job-68314, cmd: VmDataCommand) (logid:08e004e5) update_config.py execution result: true 2019-04-22 19:03:56,544 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-116:ctx-d5faea00 host01.cloud.local, job-68311/job-68314, cmd: VmDataCommand) (logid:08e004e5) Processing ScriptConfigItem, executing update_config.py vm_metadata.json took 1284ms 2019-04-22 19:03:56,544 WARN [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-116:ctx-d5faea00 host01.cloud.local, job-68311/job-68314, cmd: VmDataCommand) (logid:08e004e5) Expected 1 answers while executing VmDataCommand but received 2 2019-04-22 19:03:56,550 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-116:ctx-d5faea00) (logid:08e004e5) Seq 70-5534642467061797825: Response Received: 2019-04-22 19:03:56,550 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (DirectAgent-116:ctx-d5faea00) (logid:08e004e5) Seq 70-5534642467061797825: MgmtId 345051257169: Resp: Routing to peer 2019-04-22 19:03:56,780 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Executing resource StartCommand: {"vm":{"id":904,"name":"i-576-904-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":285,"maxSpeed":1000,"minRam":536870912,"maxRam":536870912,"hostName":"testnet1","arch":"x86_64","os":"CentOS 6 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":true,"limitCpuUse":true,"enableDynamicallyScaleVm":true,"vncPassword":"xxxxxxxxx","params":{"memoryOvercommitRatio":"1","cpuNumber":"1","username":"root","cpuSpeed":"1000","Message.ReservedCapacityFreed.Flag":"false","dataDiskController":"lsisas1068","cpuOvercommitRatio":"3.5","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"lsisas1068","memory":"512","vmware.reserve.mem":"false"},"uuid":"258074b6-2192-46a9-a330-6eba27a424d0","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4045e9c4-b4c9-411e-a7be-4d40e5c8d4db","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"51114542-957d-34ed-8797-500eb2248d3e","id":88,"poolType":"VMFS","host":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","path":"/Cloud01/8K1-MIX-POOL-CLD_1","port":0,"url":"VMFS://VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1/Cloud01/8K1-MIX-POOL-CLD_1/?ROLE=Primary&STOREUUID=51114542-957d-34ed-8797-500eb2248d3e"}},"name":"ROOT-904","size":42949672960,"path":"ROOT-904","volumeId":4360,"vmName":"i-576-904-VM","accountId":1813,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[8K1-MIX-POOL-CLD_1] testnet1/ROOT-904.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":4360,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-904","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","volumeSize":"42949672960"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1000,"defaultNic":true,"pxeDisable":false,"nicUuid":"1a854cbe-2e4f-427c-abe0-3f7eb964aad4","uuid":"a1d08c31-d5e2-4fe8-a2f3-ed861e71f76f","ip":"45.32.12.45","netmask":"255.255.255.0","gateway":"45.32.12.1","mac":"06:93:a2:01:50:52","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1553","isolationUri":"vlan://1553","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":1,"networkRateMbps":10000,"defaultNic":false,"pxeDisable":false,"nicUuid":"f8f729bb-d6f7-4177-aa03-9b04ec935cae","uuid":"68800e8c-5370-44c0-8fff-04b4cb76bf15","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"02:00:4b:fc:01:6a","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1551","isolationUri":"vlan://1551","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":2,"networkRateMbps":1000,"defaultNic":false,"pxeDisable":false,"nicUuid":"b3f39341-6a98-4ebd-bb81-be4d690b237f","uuid":"e31feebf-34d1-4033-be13-9c49f07f01ea","ip":"192.168.125.227","netmask":"255.255.255.0","gateway":"192.168.125.1","mac":"02:00:01:1b:00:05","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1000","isolationUri":"vlan://1000","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"}]},"hostIp":"172.18.10.102","executeInSequence":true,"wait":0} 2019-04-22 19:03:56,909 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Using mapping name : CENTOS_64_GUEST 2019-04-22 19:03:56,939 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) find VM i-576-904-VM on host 2019-04-22 19:03:56,939 INFO [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) VM i-576-904-VM not found in host cache 2019-04-22 19:03:56,939 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) load VM cache on host 2019-04-22 19:03:56,776 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-6:null) (logid:) Seq 115-9169047366349636454: Routed from 345051257169 2019-04-22 19:03:56,777 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:null) (logid:) Seq 115-9169047366349636454: Sending { Cmd , MgmtId: 345051257169, via: 115, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":904,"name":"i-576-904-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":285,"maxSpeed":1000,"minRam":536870912,"maxRam":536870912,"hostName":"testnet1","arch":"x86_64","os":"CentOS 6 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":true,"limitCpuUse":true,"enableDynamicallyScaleVm":true,"vncPassword":"xxxxxxxxx","params":{"memoryOvercommitRatio":"1","cpuNumber":"1","username":"root","cpuSpeed":"1000","Message.ReservedCapacityFreed.Flag":"false","dataDiskController":"lsisas1068","cpuOvercommitRatio":"3.5","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"lsisas1068","memory":"512","vmware.reserve.mem":"false"},"uuid":"258074b6-2192-46a9-a330-6eba27a424d0","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4045e9c4-b4c9-411e-a7be-4d40e5c8d4db","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"51114542-957d-34ed-8797-500eb2248d3e","id":88,"poolType":"VMFS","host":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","path":"/Cloud01/8K1-MIX-POOL-CLD_1","port":0,"url":"VMFS://VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1/Cloud01/8K1-MIX-POOL-CLD_1/?ROLE=Primary&STOREUUID=51114542-957d-34ed-8797-500eb2248d3e"}},"name":"ROOT-904","size":42949672960,"path":"ROOT-904","volumeId":4360,"vmName":"i-576-904-VM","accountId":1813,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[8K1-MIX-POOL-CLD_1] testnet1/ROOT-904.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":4360,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-904","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","volumeSize":"42949672960"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1000,"defaultNic":true,"pxeDisable":false,"nicUuid":"1a854cbe-2e4f-427c-abe0-3f7eb964aad4","uuid":"a1d08c31-d5e2-4fe8-a2f3-ed861e71f76f","ip":"45.32.12.45","netmask":"255.255.255.0","gateway":"45.32.12.1","mac":"06:93:a2:01:50:52","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1553","isolationUri":"vlan://1553","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":1,"networkRateMbps":10000,"defaultNic":false,"pxeDisable":false,"nicUuid":"f8f729bb-d6f7-4177-aa03-9b04ec935cae","uuid":"68800e8c-5370-44c0-8fff-04b4cb76bf15","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"02:00:4b:fc:01:6a","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1551","isolationUri":"vlan://1551","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":2,"networkRateMbps":1000,"defaultNic":false,"pxeDisable":false,"nicUuid":"b3f39341-6a98-4ebd-bb81-be4d690b237f","uuid":"e31feebf-34d1-4033-be13-9c49f07f01ea","ip":"192.168.125.227","netmask":"255.255.255.0","gateway":"192.168.125.1","mac":"02:00:01:1b:00:05","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1000","isolationUri":"vlan://1000","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"}]},"hostIp":"172.18.10.102","executeInSequence":true,"wait":0}}] } 2019-04-22 19:03:56,778 DEBUG [c.c.a.t.Request] (AgentManager-Handler-6:null) (logid:) Seq 115-9169047366349636454: Executing: { Cmd , MgmtId: 345051257169, via: 115, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":904,"name":"i-576-904-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":285,"maxSpeed":1000,"minRam":536870912,"maxRam":536870912,"hostName":"testnet1","arch":"x86_64","os":"CentOS 6 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":true,"limitCpuUse":true,"enableDynamicallyScaleVm":true,"vncPassword":"xxxxxxxxx","params":{"memoryOvercommitRatio":"1","cpuNumber":"1","username":"root","cpuSpeed":"1000","Message.ReservedCapacityFreed.Flag":"false","dataDiskController":"lsisas1068","cpuOvercommitRatio":"3.5","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"lsisas1068","memory":"512","vmware.reserve.mem":"false"},"uuid":"258074b6-2192-46a9-a330-6eba27a424d0","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4045e9c4-b4c9-411e-a7be-4d40e5c8d4db","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"51114542-957d-34ed-8797-500eb2248d3e","id":88,"poolType":"VMFS","host":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","path":"/Cloud01/8K1-MIX-POOL-CLD_1","port":0,"url":"VMFS://VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1/Cloud01/8K1-MIX-POOL-CLD_1/?ROLE=Primary&STOREUUID=51114542-957d-34ed-8797-500eb2248d3e"}},"name":"ROOT-904","size":42949672960,"path":"ROOT-904","volumeId":4360,"vmName":"i-576-904-VM","accountId":1813,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[8K1-MIX-POOL-CLD_1] testnet1/ROOT-904.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":4360,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-904","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","volumeSize":"42949672960"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1000,"defaultNic":true,"pxeDisable":false,"nicUuid":"1a854cbe-2e4f-427c-abe0-3f7eb964aad4","uuid":"a1d08c31-d5e2-4fe8-a2f3-ed861e71f76f","ip":"45.32.12.45","netmask":"255.255.255.0","gateway":"45.32.12.1","mac":"06:93:a2:01:50:52","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1553","isolationUri":"vlan://1553","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":1,"networkRateMbps":10000,"defaultNic":false,"pxeDisable":false,"nicUuid":"f8f729bb-d6f7-4177-aa03-9b04ec935cae","uuid":"68800e8c-5370-44c0-8fff-04b4cb76bf15","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"02:00:4b:fc:01:6a","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1551","isolationUri":"vlan://1551","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":2,"networkRateMbps":1000,"defaultNic":false,"pxeDisable":false,"nicUuid":"b3f39341-6a98-4ebd-bb81-be4d690b237f","uuid":"e31feebf-34d1-4033-be13-9c49f07f01ea","ip":"192.168.125.227","netmask":"255.255.255.0","gateway":"192.168.125.1","mac":"02:00:01:1b:00:05","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1000","isolationUri":"vlan://1000","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"}]},"hostIp":"172.18.10.102","executeInSequence":true,"wait":0}}] } 2019-04-22 19:03:56,779 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-257:ctx-22dc3c3f) (logid:e609cc5d) Seq 115-9169047366349636454: Executing request 2019-04-22 19:03:56,780 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Executing resource StartCommand: {"vm":{"id":904,"name":"i-576-904-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":285,"maxSpeed":1000,"minRam":536870912,"maxRam":536870912,"hostName":"testnet1","arch":"x86_64","os":"CentOS 6 (64-bit)","platformEmulator":"centos64Guest","bootArgs":"","enableHA":true,"limitCpuUse":true,"enableDynamicallyScaleVm":true,"vncPassword":"xxxxxxxxx","params":{"memoryOvercommitRatio":"1","cpuNumber":"1","username":"root","cpuSpeed":"1000","Message.ReservedCapacityFreed.Flag":"false","dataDiskController":"lsisas1068","cpuOvercommitRatio":"3.5","nicAdapter":"Vmxnet3","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","rootDiskController":"lsisas1068","memory":"512","vmware.reserve.mem":"false"},"uuid":"258074b6-2192-46a9-a330-6eba27a424d0","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4045e9c4-b4c9-411e-a7be-4d40e5c8d4db","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"51114542-957d-34ed-8797-500eb2248d3e","id":88,"poolType":"VMFS","host":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","path":"/Cloud01/8K1-MIX-POOL-CLD_1","port":0,"url":"VMFS://VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1/Cloud01/8K1-MIX-POOL-CLD_1/?ROLE=Primary&STOREUUID=51114542-957d-34ed-8797-500eb2248d3e"}},"name":"ROOT-904","size":42949672960,"path":"ROOT-904","volumeId":4360,"vmName":"i-576-904-VM","accountId":1813,"chainInfo":"{\"diskDeviceBusName\":\"scsi0:0\",\"diskChain\":[\"[8K1-MIX-POOL-CLD_1] testnet1/ROOT-904.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":4360,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"VMware"}},"diskSeq":0,"path":"ROOT-904","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"VMFS datastore: /Cloud01/8K1-MIX-POOL-CLD_1","volumeSize":"42949672960"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":1000,"defaultNic":true,"pxeDisable":false,"nicUuid":"1a854cbe-2e4f-427c-abe0-3f7eb964aad4","uuid":"a1d08c31-d5e2-4fe8-a2f3-ed861e71f76f","ip":"45.32.12.45","netmask":"255.255.255.0","gateway":"45.32.12.1","mac":"06:93:a2:01:50:52","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1553","isolationUri":"vlan://1553","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":1,"networkRateMbps":10000,"defaultNic":false,"pxeDisable":false,"nicUuid":"f8f729bb-d6f7-4177-aa03-9b04ec935cae","uuid":"68800e8c-5370-44c0-8fff-04b4cb76bf15","netmask":"255.255.255.0","gateway":"192.168.0.1","mac":"02:00:4b:fc:01:6a","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1551","isolationUri":"vlan://1551","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"},{"deviceId":2,"networkRateMbps":1000,"defaultNic":false,"pxeDisable":false,"nicUuid":"b3f39341-6a98-4ebd-bb81-be4d690b237f","uuid":"e31feebf-34d1-4033-be13-9c49f07f01ea","ip":"192.168.125.227","netmask":"255.255.255.0","gateway":"192.168.125.1","mac":"02:00:01:1b:00:05","dns1":"67.123.136.4","dns2":"67.123.137.4","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1000","isolationUri":"vlan://1000","isSecurityGroupEnabled":false,"name":"SWCH02,1222,vmwaredvs"}]},"hostIp":"172.18.10.102","executeInSequence":true,"wait":0} 2019-04-22 19:03:56,909 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Using mapping name : CENTOS_64_GUEST 2019-04-22 19:03:56,939 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) find VM i-576-904-VM on host 2019-04-22 19:03:56,939 INFO [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) VM i-576-904-VM not found in host cache 2019-04-22 19:03:56,939 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) load VM cache on host 2019-04-22 19:03:57,166 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Found VM: i-576-904-VM on a host in a different cluster. Unregistering the exisitng VM. 2019-04-22 19:03:58,211 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Folder testnet1 exists on datastore 2019-04-22 19:03:58,218 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Search file testnet1.vmx on [8K1-MIX-POOL-CLD_1] 2019-04-22 19:03:58,339 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) File [8K1-MIX-POOL-CLD_1] testnet1.vmx does not exist on datastore 2019-04-22 19:03:58,339 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Searching file testnet1.vmx in [8K1-MIX-POOL-CLD_1] 2019-04-22 19:03:58,764 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Found file testnet1.vmx in datastore at [8K1-MIX-POOL-CLD_1] testnet1/ 2019-04-22 19:03:58,833 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Search file testnet1.vmx on [8K1-MIX-POOL-CLD_1] 2019-04-22 19:03:59,256 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) File [8K1-MIX-POOL-CLD_1] testnet1.vmx does not exist on datastore 2019-04-22 19:03:59,256 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Searching file testnet1.vmx in [8K1-MIX-POOL-CLD_1] 2019-04-22 19:03:59,415 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Found file testnet1.vmx in datastore at [8K1-MIX-POOL-CLD_1] testnet1/ 2019-04-22 19:04:02,439 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) find VM i-576-904-VM on host 2019-04-22 19:04:02,439 INFO [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) VM i-576-904-VM not found in host cache 2019-04-22 19:04:02,439 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) load VM cache on host 2019-04-22 19:04:02,461 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) find VM i-576-904-VM on host 2019-04-22 19:04:02,461 INFO [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) VM i-576-904-VM not found in host cache 2019-04-22 19:04:02,461 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) load VM cache on host 2019-04-22 19:04:02,488 INFO [c.c.h.v.u.VmwareHelper] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) [ignored]failed toi get message for exception: Failed to find the newly create or relocated VM. vmName: i-576-904-VM 2019-04-22 19:04:02,488 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) StartCommand failed due to Exception: java.lang.Exception Message: Failed to find the newly create or relocated VM. vmName: i-576-904-VM at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1652) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:464) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622) at java.lang.Thread.run(Thread.java:748) 2019-04-22 19:04:02,489 DEBUG [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Since VM start failed, registering back an existing VM: testnet1 that was unregistered 2019-04-22 19:04:02,582 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Search file testnet1.vmx on [8K1-MIX-POOL-CLD_1] 2019-04-22 19:04:03,326 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) File [8K1-MIX-POOL-CLD_1] testnet1.vmx does not exist on datastore 2019-04-22 19:04:03,326 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Searching file testnet1.vmx in [8K1-MIX-POOL-CLD_1] 2019-04-22 19:04:03,873 INFO [c.c.h.v.m.DatastoreMO] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Found file testnet1.vmx in datastore at [8K1-MIX-POOL-CLD_1] testnet1/ 2019-04-22 19:04:03,969 INFO [c.c.h.v.u.VmwareHelper] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) [ignored]failed toi get message for exception: The specified key, name, or identifier already exists. 2019-04-22 19:04:03,969 WARN [c.c.h.v.r.VmwareResource] (DirectAgent-257:ctx-22dc3c3f host02.cloud.local, job-68311/job-68314, cmd: StartCommand) (logid:08e004e5) Failed to register an existing VM: testnet1 due to Exception: java.lang.RuntimeException Message: The specified key, name, or identifier already exists. java.lang.RuntimeException: The specified key, name, or identifier already exists. at com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:354) at com.cloud.hypervisor.vmware.resource.VmwareResource.registerVm(VmwareResource.java:609) at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2042) at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:464) at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:315) at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103) at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53) at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622) at java.lang.Thread.run(Thread.java:748) 2019-04-22 19:04:03,971 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-257:ctx-22dc3c3f) (logid:08e004e5) Seq 115-9169047366349636454: Response Received: 2019-04-22 19:04:03,972 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (DirectAgent-257:ctx-22dc3c3f) (logid:08e004e5) Seq 115-9169047366349636454: MgmtId 345051257169: Resp: Routing to peer 2019-04-22 19:04:03,972 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-257:ctx-22dc3c3f) (logid:08e004e5) Seq 115-9169047366349636454: No more commands found 2019-04-22 19:04:04,008 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-8:null) (logid:) Seq 115-9169047366349636455: Routed from 345051257169 2019-04-22 19:04:04,008 DEBUG [c.c.a.t.Request] (AgentManager-Handler-8:null) (logid:) Seq 115-9169047366349636455: Sending { Cmd , MgmtId: 345051257169, via: 115, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"i-576-904-VM","executeInSequence":true,"wait":0}}] } 2019-04-22 19:04:04,008 DEBUG [c.c.a.t.Request] (AgentManager-Handler-8:null) (logid:) Seq 115-9169047366349636455: Executing: { Cmd , MgmtId: 345051257169, via: 115, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"i-576-904-VM","executeInSequence":true,"wait":0}}] } 2019-04-22 19:04:04,009 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-334:ctx-e72068cf) (logid:4a83787f) Seq 115-9169047366349636455: Executing request 2019-04-22 19:04:04,009 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-334:ctx-e72068cf host02.cloud.local, job-68311/job-68314, cmd: StopCommand) (logid:08e004e5) Executing resource StopCommand: {"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"i-576-904-VM","executeInSequence":true,"wait":0} 2019-04-22 19:04:04,039 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-334:ctx-e72068cf host02.cloud.local, job-68311/job-68314, cmd: StopCommand) (logid:08e004e5) find VM i-576-904-VM on host 2019-04-22 19:04:04,039 INFO [c.c.h.v.m.HostMO] (DirectAgent-334:ctx-e72068cf host02.cloud.local, job-68311/job-68314, cmd: StopCommand) (logid:08e004e5) VM i-576-904-VM not found in host cache 2019-04-22 19:04:04,039 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-334:ctx-e72068cf host02.cloud.local, job-68311/job-68314, cmd: StopCommand) (logid:08e004e5) load VM cache on host 2019-04-22 19:04:04,058 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-334:ctx-e72068cf host02.cloud.local, job-68311/job-68314, cmd: StopCommand) (logid:08e004e5) VM i-576-904-VM is no longer in vSphere 2019-04-22 19:04:04,059 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-334:ctx-e72068cf) (logid:08e004e5) Seq 115-9169047366349636455: Response Received: 2019-04-22 19:04:04,059 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (DirectAgent-334:ctx-e72068cf) (logid:08e004e5) Seq 115-9169047366349636455: MgmtId 345051257169: Resp: Routing to peer 2019-04-22 19:04:04,060 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-334:ctx-e72068cf) (logid:08e004e5) Seq 115-9169047366349636455: No more commands found ~~~
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services
