You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Abhinandan Prateek (JIRA)" <ji...@apache.org> on 2013/12/02 07:47:39 UTC
[jira] [Updated] (CLOUDSTACK-4593) [VMWARE] [Upgrade]Livestorage
Migration & VM Snapshot features are not fully functional after upgrade
[ https://issues.apache.org/jira/browse/CLOUDSTACK-4593?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Abhinandan Prateek updated CLOUDSTACK-4593:
-------------------------------------------
Assignee: Sateesh Chodapuneedi (was: Ram Ganesh)
> [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
> Assignee: Sateesh Chodapuneedi
> 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)