After performing a storage migration of a VM from one cluster to another, it is not possible to start a VM
STEPS TO REPRODUCE
Create VM on cluster 1 (host 1, pool 1)
Stop VM
Migrate instance to pool 2
Start VM
EXPECTED RESULTS
VM is running
ACTUAL RESULTS
VM disk cannot be found
2021-03-17 17:09:26,591 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-14:ctx-6c9cf0b4 job-73/job-75 ctx-e05b0cda) (logid:4dd5fc60) 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.ServerSOAPFaultExc
eption
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:1119)
at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1543)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1151)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5464)
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:5631)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
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 were you able to check the behaviour with master and 4.14? I think 4.14 might be having a similar problem and this should be fixed in master with #4385
@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)
Hi @nvazquez
is there a reason why this issue will not going to be fixed in 4.15.1. after all, even it is classified as BLOCKER and a fix is already available?
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.
Activity
shwstppr commented on Mar 18, 2021
@nvazquez were you able to check the behaviour with master and 4.14? I think 4.14 might be having a similar problem and this should be fixed in master with #4385
shwstppr commented on Mar 18, 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 🤞
shwstppr commented on Mar 18, 2021
@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" } }nvazquez commented on Mar 19, 2021
Thanks @shwstppr! Closing it
mib1185 commented on Mar 19, 2021
Hi @nvazquez
is there a reason why this issue will not going to be fixed in 4.15.1. after all, even it is classified as BLOCKER and a fix is already available?
yadvr commented on Mar 29, 2021
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.
vmware: fix inter-cluster stopped vm migration
vmware: fix inter-cluster stopped vm migration
vmware: fix inter-cluster stopped vm migration
vmware: fix inter-cluster stopped vm and volume migration (#4895)
yadvr commented on Apr 10, 2021
Fixed in #4895
vmware: fix stopped VM volume migration (#4758)