[ https://issues.apache.org/jira/browse/CLOUDSTACK-4593?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ram Ganesh updated CLOUDSTACK-4593: ----------------------------------- Fix Version/s: 4.3.0 > [VMWARE] [Upgrade]Livestorage Migration & VM Snapshot features are not fully > functional after upgrade > ------------------------------------------------------------------------------------------------------ > > Key: CLOUDSTACK-4593 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4593 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the > default.) > Components: Storage Controller, Upgrade, VMware > Affects Versions: 4.2.1 > Reporter: Sailaja Mada > Fix For: 4.3.0 > > Attachments: apilogs.rar, clouddbback.dmp, mgmtlogs.rar > > > Steps: > Upgraded setup : > 307 Setup with 2 clusters ( Cluster1 – 2 ESXi 5.0 hosts , Cluster2 – Esxi 4.1 > host) > 1. 11 Vm’s deployed with 2 VM’s in stopped state > 2. VM’s with ROOT volume, 2 DATA volumes, 3 DATA volumes > 3. Snapshots , Template / volumes from this snapshot > 4. Detached volumes > 5. Empty volumes which are not attached to any instance > 6. Cluster with 2 primary storage's > Upgraded to 4.2 > I got into below failures with VM Snapshot if tried without Stop/Start of the > VM Post upgrade : > 2013-09-02 21:35:36,733 WARN [vmware.resource.VmwareResource] > (DirectAgent-320:10.102.192.23) StartCommand failed due to Exception: > java.lang.RuntimeException > Message: File <unspecified filename> was not found > java.lang.RuntimeException: File <unspecified filename> was not found > at > com.cloud.hypervisor.vmware.util.VmwareClient.waitForTask(VmwareClient.java:378) > at > com.cloud.hypervisor.vmware.mo.VirtualMachineMO.powerOn(VirtualMachineMO.java:188) > at > com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2966) > at > com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:519) > at > com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165) > at > java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-09-02 21:35:36,742 DEBUG [agent.manager.DirectAgentAttache] > (DirectAgent-320:null) Seq 6-949618439: Response Received: > 2013-09-02 21:35:43,972 INFO [storage.volume.VolumeServiceImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Volume > 52 is not referred anywhere, remove it from volumes table > 2013-09-02 21:35:43,981 ERROR [cloud.storage.VolumeManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) migrate > volume failed:copy volume from primary to secondary failed due to exception: > Exception: java.lang.Exception > Message: Unable to find related disk device for volume. volume path: > ROOT-14-30-000004 > 2013-09-02 21:35:43,990 INFO [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Unable > to contact resource. > com.cloud.exception.StorageUnavailableException: Resource [StoragePool:203] > is unreachable: migrate volume failed: copy volume from primary to secondary > failed due to exception: Exception: java.lang.Exception > Message: Unable to find related disk device for volume. volume path: > ROOT-14-30-000004 > at > com.cloud.storage.VolumeManagerImpl.migrateVolume(VolumeManagerImpl.java:2254) > at > com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at > com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2590) > at > com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888) > at > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) > at > org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237) > at > org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209) > at > com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406) > at > com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1948) > at > com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at > org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:120) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at > com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-09-02 21:35:44,008 DEBUG [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Cleaning > up resources for the vm VM[User|instance6withdefaulttempalte] in Starting > state > 2013-09-02 21:35:44,009 DEBUG [agent.transport.Request] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Seq > 8-343475044: Sending { Cmd , MgmtId: 227594284004867, via: 8, Ver: v1, > Flags: 100111, > [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-14-VM","wait":0}}] > } > 2013-09-02 21:35:44,009 DEBUG [agent.transport.Request] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Seq > 8-343475044: Executing: { Cmd , MgmtId: 227594284004867, via: 8, Ver: v1, > Flags: 100111, > [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-14-VM","wait":0}}] > } > 2013-09-02 21:35:44,010 DEBUG [agent.manager.DirectAgentAttache] > (DirectAgent-106:null) Seq 8-343475044: Executing request > 2013-09-02 21:35:44,010 INFO [vmware.resource.VmwareResource] > (DirectAgent-106:10.102.192.14) Executing resource StopCommand: > {"isProxy":false,"executeInSequence":true,"vmName":"i-3-14-VM","wait":0} > But finally VM got started moving to other host in the cluser: Note : There > is no gurantee that this feature works fine without restart of the VM . After > this chain info got updated (chain_info: > {"diskDeviceBusName":"ide0:1","diskChain":["[61105200a56c3a5f9c83783d3d36a9d1] > i-3-14-VM/436fd32b103746d29771a2b10df35cf2.vmdk"]}) > 2013-09-02 21:35:44,165 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Trying > to find a potenial host and associated storage pools from the suitable > host/pool lists for this VM > 2013-09-02 21:35:44,165 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Checking > if host: 1 can access any suitable storage pool for volume: ROOT > 2013-09-02 21:35:44,166 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Host: 1 > can access pool: 201 > 2013-09-02 21:35:44,168 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) Found a > potential host id: 1 name: 10.102.192.20 and associated storage pools for > this VM > 2013-09-02 21:35:44,169 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) > Returning Deployment Destination: > Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] > : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(30|ROOT-->Pool(201))] > 2013-09-02 21:35:44,169 DEBUG [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) > Deployment found - P0=VM[User|instance6withdefaulttempalte], > P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] > : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(30|ROOT-->Pool(201))] > 2013-09-02 21:35:44,176 DEBUG [cloud.server.StatsCollector] > (StatsCollector-3:null) HostStatsCollector is running... > 2013-09-02 21:35:44,191 DEBUG [cloud.capacity.CapacityManagerImpl] > (Job-Executor-75:job-151 = [ 3e8e2327-7c56-45ea-a653-ee5b89d75d57 ]) VM state > transitted from :Starting to Starting with event: OperationRetryvm's original > host id: 6 new host id: 1 host id before state transition: 8 > Second Scenario: > 1. Create a VM in 307 > 2. Do not perform any stop and start after upgrade to 4.2 > 3. Live storage migrate to second cluster , then take a volume snapshot > 4. Create the template from this volume snapshot after live storage migration > 5. Try deployment of the VM using this template. Deployment works and VM is > up & running( I could login and create files also) . > 6. But during deployment there were errors while creating the Volume. Later > it finds one more storage pool / host and creates volume on this new storage > pool. Finally deploy VM works fine, > ERROR: > 2013-09-02 23:51:11,130 INFO [storage.volume.VolumeServiceImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) > releasing lock for VMTemplateStoragePool 19 > 2013-09-02 23:51:11,131 WARN [utils.db.Merovingian2] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Was > unable to find lock for the key template_spool_ref19 and thread id 1340523980 > 2013-09-02 23:51:11,131 DEBUG [cloud.storage.VolumeManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Unable > to create Vol[59|vm=25|ROOT]:Unable to copy template to primary storage due > to exception:Exception: javax.xml.ws.soap.SOAPFaultException > Message: > Required parameter spec is missing > while parsing call information for method ImportVApp > 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 importVApp > on object of type vim.ResourcePool > at line 1, column 0 > 2013-09-02 23:51:11,131 INFO [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Unable > to contact resource. > com.cloud.exception.StorageUnavailableException: Resource [StoragePool:202] > is unreachable: Unable to create Vol[59|vm=25|ROOT]:Unable to copy template > to primary storage due to exception:Exception: > javax.xml.ws.soap.SOAPFaultException > Message: > Required parameter spec is missing > while parsing call information for method ImportVApp > 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 importVApp > on object of type vim.ResourcePool > at line 1, column 0 > at > com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2544) > at > com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2592) > at > com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888) > at > com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:578) > at > org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227) > at > org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209) > at > com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3406) > at > com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2966) > at > com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2952) > at > com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at > org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) > at > com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) > at java.lang.Thread.run(Thread.java:679) > 2013-09-02 23:51:11,139 DEBUG [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) > Cleaning up resources for the vm VM[User|xxxx] in Starting state > 2013-09-02 23:51:11,141 DEBUG [agent.transport.Request] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Seq > 6-949618915: Sending { Cmd , MgmtId: 227594284004867, via: 6, Ver: v1, > Flags: 100111, > [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-25-VM","wait":0}}] > } > 2013-09-02 23:51:11,141 DEBUG [agent.transport.Request] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Seq > 6-949618915: Executing: { Cmd , MgmtId: 227594284004867, via: 6, Ver: v1, > Flags: 100111, > [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-25-VM","wait":0}}] > } > 2013-09-02 23:51:11,141 DEBUG [agent.manager.DirectAgentAttache] > (DirectAgent-91:null) Seq 6-949618915: Executing request > 2013-09-02 23:51:11,141 INFO [vmware.resource.VmwareResource] > (DirectAgent-91:10.102.192.23) Executing resource StopCommand: > {"isProxy":false,"executeInSequence":true,"vmName":"i-3-25-VM","wait" > Deploy VM – PASS: > 2013-09-02 23:51:29,848 DEBUG [agent.manager.DirectAgentAttache] > (DirectAgent-82:null) Seq 2-618137852: Response Received: > 2013-09-02 23:51:29,849 DEBUG [agent.transport.Request] (DirectAgent-82:null) > Seq 2-618137852: Processing: { Ans: , MgmtId: 227594284004867, via: 2, Ver: > v1, Flags: 110, > [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":25,"name":"i-3-25-VM","bootloader":"HVM","type":"User","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"hostName":"xxxx","arch":"x86_64","os":"CentOS > 5.3 > (64-bit)","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"95b29c111ca96aee","params":{"nicAdapter":"E1000","vmware.reserve.cpu":"false","nestedVirtualizationFlag":"false","Message.ReservedCapacityFreed.Flag":"false","rootDiskController":"ide","vmware.reserve.mem":"false"},"uuid":"021f2108-2c83-485a-ab6a-e3eab3fc585c","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b14d9ecc-0474-4aa7-9b7d-3f8620381e64","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"61105200-a56c-3a5f-9c83-783d3d36a9d1","id":201,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/workps2","port":2049}},"name":"ROOT-25","size":2147483648,"path":"ROOT-25","volumeId":59,"vmName":"i-3-25-VM","accountId":3,"chainInfo":"{\"diskDeviceBusName\":\"ide0:1\",\"diskChain\":[\"[61105200a56c3a5f9c83783d3d36a9d1] > i-3-25-VM/ROOT-25.vmdk\",\"[61105200a56c3a5f9c83783d3d36a9d1] > 6a9fa9a8a4af3849a58167751abc214f/6a9fa9a8a4af3849a58167751abc214f.vmdk\"]}","format":"OVA","id":59,"hypervisorType":"VMware"}},"diskSeq":0,"type":"ROOT"},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"710aa816-6e4a-4f2e-b876-3bb901e881e4","ip":"10.1.1.12","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:4c:e2:00:0c","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://786","isolationUri":"vlan://786","isSecurityGroupEnabled":false}]},"result":true,"wait":0}}] > } > 2013-09-02 23:51:29,849 DEBUG [agent.transport.Request] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Seq > 2-618137852: Received: { Ans: , MgmtId: 227594284004867, via: 2, Ver: v1, > Flags: 110, { StartAnswer } } > 2013-09-02 23:51:29,852 DEBUG [agent.manager.AgentAttache] > (DirectAgent-82:null) Seq 2-618137852: No more commands found > 2013-09-02 23:51:29,872 INFO [cloud.storage.VolumeManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Update > volume disk chain info. vol: 59, ROOT-25 -> ROOT-25, null -> > {"diskDeviceBusName":"ide0:1","diskChain":["[61105200a56c3a5f9c83783d3d36a9d1] > i-3-25-VM/ROOT-25.vmdk","[61105200a56c3a5f9c83783d3d36a9d1] > 6a9fa9a8a4af3849a58167751abc214f/6a9fa9a8a4af3849a58167751abc214f.vmdk"]} > 2013-09-02 23:51:29,919 DEBUG [cloud.network.NetworkModelImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Service > SecurityGroup is not supported in the network id=204 > 2013-09-02 23:51:29,924 DEBUG [cloud.network.NetworkModelImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Service > SecurityGroup is not supported in the network id=204 > 2013-09-02 23:51:29,931 DEBUG [cloud.capacity.CapacityManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) VM > state transitted from :Starting to Running with event: OperationSucceededvm's > original host id: 2 new host id: 2 host id before state transition: 2 > 2013-09-02 23:51:29,932 DEBUG [cloud.vm.VirtualMachineManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Start > completed for VM VM[User|xxxx] > 2013-09-02 23:51:29,951 DEBUG [cloud.async.AsyncJobManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) > Complete async job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ], jobStatus: > 1, resultCode: 0, result: > org.apache.cloudstack.api.response.UserVmResponse@3ac3beea > 2013-09-02 23:51:29,963 DEBUG [cloud.async.AsyncJobManagerImpl] > (Job-Executor-106:job-182 = [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ]) Done > executing org.apache.cloudstack.api.command.user.vm.DeployVMCmd for job-182 = > [ ed8268f7-bb81-4f02-a94b-3500d4f1d5cf ] -- This message was sent by Atlassian JIRA (v6.1#6144)