Repository navigation
VMware: VM operations fail after inter-cluster storage migration #4838
Description
Activity
- changed the title
[-]VMware: VM operations fail after Inter-cluster storage migration[/-][+]VMware: VM operations fail after inter-cluster storage migration[/+]on Mar 17, 2021 @nvazquez I'm able to reproduce this on 4.14.1 as well,
2021-03-18 10:47:51,161 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) (logid:) Seq 6-5096948878276558866: Processing: { Ans: , MgmtId: 32987093664547, via: 6, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"copy volume from primary to secondary failed due to exception: Exception: com.sun.xml.ws.fault.ServerSOAPFaultException\nMessage: Client received SOAP Fault from server: \nRequired property fileName is missing from data object of type VirtualDiskFlatVer2BackingInfo\n\nwhile parsing serialized DataObject of type vim.vm.device.VirtualDisk.FlatVer2BackingInfo\nat line 1, column 331\n\nwhile parsing property \"backing\" of static type VirtualDeviceBackingInfo\n\nwhile parsing serialized DataObject of type vim.vm.device.VirtualDisk\nat line 1, column 233\n\nwhile parsing property \"device\" of static type VirtualDevice\n\nwhile parsing serialized DataObject of type vim.vm.device.VirtualDeviceSpec\nat line 1, column 193\n\nwhile parsing property \"deviceChange\" of static type ArrayOfVirtualDeviceConfigSpec\n\nwhile parsing serialized DataObject of type vim.vm.ConfigSpec\nat line 1, column 187\n\nwhile parsing call information for method ReconfigVM_Task\nat line 1, column 110\n\nwhile parsing SOAP body\nat line 1, column 102\n\nwhile parsing SOAP envelope\nat line 1, column 38\n\nwhile parsing HTTP request for method reconfigure\non object of type vim.VirtualMachine\nat line 1, column 0 Please see the server log to find more detail regarding exact cause of the failure.\n","wait":0}}] } 2021-03-18 10:47:51,162 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Seq 6-5096948878276558866: Received: { Ans: , MgmtId: 32987093664547, via: 6(s-3-VM), Ver: v1, Flags: 10, { CopyCmdAnswer } } 2021-03-18 10:47:51,165 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) copy to image store failed: copy volume from primary to secondary failed due to exception: Exception: com.sun.xml.ws.fault.ServerSOAPFaultException Message: Client received SOAP Fault from server: Required property fileName is missing from data object of type VirtualDiskFlatVer2BackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk.FlatVer2BackingInfo at line 1, column 331 while parsing property "backing" of static type VirtualDeviceBackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk at line 1, column 233 while parsing property "device" of static type VirtualDevice while parsing serialized DataObject of type vim.vm.device.VirtualDeviceSpec at line 1, column 193 while parsing property "deviceChange" of static type ArrayOfVirtualDeviceConfigSpec while parsing serialized DataObject of type vim.vm.ConfigSpec at line 1, column 187 while parsing call information for method ReconfigVM_Task at line 1, column 110 while parsing SOAP body at line 1, column 102 while parsing SOAP envelope at line 1, column 38 while parsing HTTP request for method reconfigure on object of type vim.VirtualMachine at line 1, column 0 Please see the server log to find more detail regarding exact cause of the failure. 2021-03-18 10:47:51,177 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) getCommandHostDelegation: class org.apache.cloudstack.storage.command.DeleteCommand 2021-03-18 10:47:51,177 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) We are returning the default host to execute commands because the command is not of Copy type. 2021-03-18 10:47:51,178 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Seq 6-5096948878276558867: Sending { Cmd , MgmtId: 32987093664547, via: 6(s-3-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"63a1d382-a940-4fa7-8883-d43b7ec81568","volumeType":"ROOT","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"NFS://10.0.32.4/acs/secondary/ref-trl-578-v-M7-abhishek-kumar/ref-trl-578-v-M7-abhishek-kumar-sec1","_role":"Image"}},"name":"ROOT-5","size":2147483648,"volumeId":5,"vmName":"i-2-5-VM","accountId":2,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[84fbeee887b0381ea9a174e230cdf243] i-2-5-VM/ROOT-5.vmdk\",\"[84fbeee887b0381ea9a174e230cdf243] 882af2a1543c3d2c82cc671824a30f86/882af2a1543c3d2c82cc671824a30f86.vmdk\"]}","format":"OVA","provisioningType":"THIN","id":5,"deviceId":0,"hypervisorType":"VMware","directDownload":false}},"wait":0}}] } 2021-03-18 10:47:51,221 DEBUG [c.c.a.t.Request] (AgentManager-Handler-2:null) (logid:) Seq 6-5096948878276558867: Processing: { Ans: , MgmtId: 32987093664547, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"Object with null install path does not exist on image store , no need to delete","wait":0}}] } 2021-03-18 10:47:51,222 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Seq 6-5096948878276558867: Received: { Ans: , MgmtId: 32987093664547, via: 6(s-3-VM), Ver: v1, Flags: 10, { Answer } } 2021-03-18 10:47:51,223 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Volume 5 is not found on image store 1, so no need to delete 2021-03-18 10:47:51,231 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@a881511), no need to delete from object in store ref table 2021-03-18 10:47:51,240 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1 2021-03-18 10:47:51,243 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = 2147483648 2021-03-18 10:47:51,249 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Marking volume that was never created as destroyed: Vol[7|vm=null|ROOT] 2021-03-18 10:47:51,252 ERROR [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Migrate volume failed:copy volume from primary to secondary failed due to exception: Exception: com.sun.xml.ws.fault.ServerSOAPFaultException Message: Client received SOAP Fault from server: Required property fileName is missing from data object of type VirtualDiskFlatVer2BackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk.FlatVer2BackingInfo at line 1, column 331 while parsing property "backing" of static type VirtualDeviceBackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk at line 1, column 233 while parsing property "device" of static type VirtualDevice while parsing serialized DataObject of type vim.vm.device.VirtualDeviceSpec at line 1, column 193 while parsing property "deviceChange" of static type ArrayOfVirtualDeviceConfigSpec while parsing serialized DataObject of type vim.vm.ConfigSpec at line 1, column 187 while parsing call information for method ReconfigVM_Task at line 1, column 110 while parsing SOAP body at line 1, column 102 while parsing SOAP envelope at line 1, column 38 while parsing HTTP request for method reconfigure on object of type vim.VirtualMachine at line 1, column 0 Please see the server log to find more detail regarding exact cause of the failure. 2021-03-18 10:47:51,252 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:ctx-c13d51d0 job-45/job-47 ctx-2b7429c1) (logid:c09c0bd8) Unable to contact resource. com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Migrate volume failed: copy volume from primary to secondary failed due to exception: Exception: com.sun.xml.ws.fault.ServerSOAPFaultException Message: Client received SOAP Fault from server: Required property fileName is missing from data object of type VirtualDiskFlatVer2BackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk.FlatVer2BackingInfo at line 1, column 331 while parsing property "backing" of static type VirtualDeviceBackingInfo while parsing serialized DataObject of type vim.vm.device.VirtualDisk at line 1, column 233 while parsing property "device" of static type VirtualDevice while parsing serialized DataObject of type vim.vm.device.VirtualDeviceSpec at line 1, column 193 while parsing property "deviceChange" of static type ArrayOfVirtualDeviceConfigSpec while parsing serialized DataObject of type vim.vm.ConfigSpec at line 1, column 187 while parsing call information for method ReconfigVM_Task at line 1, column 110 while parsing SOAP body at line 1, column 102 while parsing SOAP envelope at line 1, column 38 while parsing HTTP request for method reconfigure on object of type vim.VirtualMachine at line 1, column 0 Please see the server log to find more detail regarding exact cause of the failure. at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.migrateVolume(VolumeOrchestrator.java:990) at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1408) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1133) at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5287) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5454) at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102) at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:603) 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 org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:551) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834)Checking on master. Should happen there 🤞
@nvazquez working fine on the master. I'm not able to reproduce there,
Storage pools
(localcloud) SBCM5> > list storagepools filter=id,name,clusterid,clustername,scope, { "count": 2, "storagepool": [ { "clusterid": "b246199b-174b-4881-acdd-e1614554c883", "clustername": "10.0.35.220/Trillian/p1-c2", "id": "9c8729f3-8885-3e25-afae-6e8ba31fc48b", "name": "ps2", "scope": "CLUSTER" }, { "clusterid": "8f2bb91a-cb1a-4f52-9b5a-5d8f53bb4042", "clustername": "p1-c1", "id": "d655eab5-8199-3cc7-95ac-e5ffa68da70b", "name": "ps1", "scope": "CLUSTER" } ] }VM
(localcloud) SBCM5> > list virtualmachines id=c0043b7d-93b8-475f-8ff4-8c04a79be69f filter=id,name,hostid,hostname { "count": 1, "virtualmachine": [ { "hostid": "c3590057-9726-449c-9268-caabf15c92c9", "hostname": "10.0.32.225", "id": "c0043b7d-93b8-475f-8ff4-8c04a79be69f", "name": "t1" } ] }Host details to find cluster
(localcloud) SBCM5> > list hosts id=c3590057-9726-449c-9268-caabf15c92c9 filter=id,name,clusterid,clustername, { "count": 1, "host": [ { "clusterid": "8f2bb91a-cb1a-4f52-9b5a-5d8f53bb4042", "clustername": "p1-c1", "id": "c3590057-9726-449c-9268-caabf15c92c9", "name": "10.0.32.225" } ] }Stop VM
(localcloud) SBCM5> > stop virtualmachine id=c0043b7d-93b8-475f-8ff4-8c04a79be69f filter=id,name,state {}Storage migration
(localcloud) SBCM5> > migrate virtualmachine virtualmachineid=c0043b7d-93b8-475f-8ff4-8c04a79be69f storageid=9c8729f3-8885-3e25-afae-6e8ba31fc48b { "virtualmachine": { "account": "admin", "affinitygroup": [], "cpunumber": 1, "cpuspeed": 500, "cpuused": "52%", "created": "2021-03-18T12:23:45+0000", "details": { "Message.ReservedCapacityFreed.Flag": "false", "cpuOvercommitRatio": "2.0", "dataDiskController": "osdefault", "memoryOvercommitRatio": "1.0", "rootDiskController": "ide" }, "diskioread": 57, "diskiowrite": 34, "diskkbsread": 2209, "diskkbswrite": 255, "displayname": "t1", "displayvm": true, "domain": "ROOT", "domainid": "61567101-87de-11eb-a346-1e00b6000460", "guestosid": "615cf7b8-87de-11eb-a346-1e00b6000460", "haenable": false, "hypervisor": "VMware", "id": "c0043b7d-93b8-475f-8ff4-8c04a79be69f", "instancename": "i-2-5-VM", "isdynamicallyscalable": false, "memory": 512, "memoryintfreekbs": 393216, "memorykbs": 524288, "memorytargetkbs": 524288, "name": "t1", "networkkbsread": 0, "networkkbswrite": 0, "nic": [ { "extradhcpoption": [], "gateway": "10.1.1.1", "id": "004fd0b6-68b0-46ff-9588-dc4ebef28358", "ipaddress": "10.1.1.91", "isdefault": true, "macaddress": "02:00:17:78:00:01", "netmask": "255.255.255.0", "networkid": "64dfde30-152d-40bc-be15-a480e09ef36f", "networkname": "test", "secondaryip": [], "traffictype": "Guest", "type": "Isolated" } ], "osdisplayname": "CentOS 5.3 (64-bit)", "ostypeid": "615cf7b8-87de-11eb-a346-1e00b6000460", "passwordenabled": false, "pooltype": "NetworkFilesystem", "rootdeviceid": 0, "rootdevicetype": "ROOT", "securitygroup": [], "serviceofferingid": "423053f5-0195-4196-9544-f30cf843d755", "serviceofferingname": "Small Instance", "state": "Stopped", "tags": [], "templatedisplaytext": "CentOS 5.3(64-bit) no GUI (vSphere)", "templateid": "61596d4f-87de-11eb-a346-1e00b6000460", "templatename": "CentOS 5.3(64-bit) no GUI (vSphere)", "userid": "76aa39e8-87de-11eb-a346-1e00b6000460", "username": "admin", "zoneid": "6607b15e-5ca2-4d99-af51-3b1590698754", "zonename": "pr4378-t173-vmware-65u2" } }Start migrated VM
(localcloud) SBCM5> > start virtualmachine id=c0043b7d-93b8-475f-8ff4-8c04a79be69f { "virtualmachine": { "account": "admin", "affinitygroup": [], "cpunumber": 1, "cpuspeed": 500, "cpuused": "52%", "created": "2021-03-18T12:23:45+0000", "details": { "Message.ReservedCapacityFreed.Flag": "false", "cpuOvercommitRatio": "2.0", "dataDiskController": "osdefault", "memoryOvercommitRatio": "1.0", "rootDiskController": "ide" }, "diskioread": 57, "diskiowrite": 34, "diskkbsread": 2209, "diskkbswrite": 255, "displayname": "t1", "displayvm": true, "domain": "ROOT", "domainid": "61567101-87de-11eb-a346-1e00b6000460", "guestosid": "615cf7b8-87de-11eb-a346-1e00b6000460", "haenable": false, "hostid": "877fff60-d5c8-415e-82ad-65330a845a11", "hostname": "10.0.33.209", "hypervisor": "VMware", "id": "c0043b7d-93b8-475f-8ff4-8c04a79be69f", "instancename": "i-2-5-VM", "isdynamicallyscalable": false, "jobid": "1b8e7636-6444-4884-a91c-547c069bd442", "jobstatus": 0, "memory": 512, "memoryintfreekbs": 393216, "memorykbs": 524288, "memorytargetkbs": 524288, "name": "t1", "networkkbsread": 0, "networkkbswrite": 0, "nic": [ { "broadcasturi": "vlan://1951", "extradhcpoption": [], "gateway": "10.1.1.1", "id": "004fd0b6-68b0-46ff-9588-dc4ebef28358", "ipaddress": "10.1.1.91", "isdefault": true, "isolationuri": "vlan://1951", "macaddress": "02:00:17:78:00:01", "netmask": "255.255.255.0", "networkid": "64dfde30-152d-40bc-be15-a480e09ef36f", "networkname": "test", "secondaryip": [], "traffictype": "Guest", "type": "Isolated" } ], "osdisplayname": "CentOS 5.3 (64-bit)", "ostypeid": "615cf7b8-87de-11eb-a346-1e00b6000460", "passwordenabled": false, "pooltype": "NetworkFilesystem", "rootdeviceid": 0, "rootdevicetype": "ROOT", "securitygroup": [], "serviceofferingid": "423053f5-0195-4196-9544-f30cf843d755", "serviceofferingname": "Small Instance", "state": "Running", "tags": [], "templatedisplaytext": "CentOS 5.3(64-bit) no GUI (vSphere)", "templateid": "61596d4f-87de-11eb-a346-1e00b6000460", "templatename": "CentOS 5.3(64-bit) no GUI (vSphere)", "userid": "76aa39e8-87de-11eb-a346-1e00b6000460", "username": "admin", "zoneid": "6607b15e-5ca2-4d99-af51-3b1590698754", "zonename": "pr4378-t173-vmware-65u2" } }We closed this as compared to 4.14 this wasn't found out as a regression. However, our colleague @andrijapanicsb did some testing and confirmed it as a regression compared to 4.11.3. Re-opening this on Andrija's remark. We'll track this against 4.15.1.
Reacted by Michael- added a commit that references this issue
on Apr 10, 2021 - added a commit that references this issue
on Apr 24, 2021
ISSUE TYPE
COMPONENT NAME
CLOUDSTACK VERSION
CONFIGURATION
OS / ENVIRONMENT
SUMMARY
After performing a storage migration of a VM from one cluster to another, it is not possible to start a VM
STEPS TO REPRODUCE
EXPECTED RESULTS
ACTUAL RESULTS