You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Sateesh Chodapuneedi (JIRA)" <ji...@apache.org> on 2014/07/22 11:22:39 UTC
[jira] [Commented] (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:comment-tabpanel&focusedCommentId=14070057#comment-14070057 ]
Sateesh Chodapuneedi commented on CLOUDSTACK-4593:
--------------------------------------------------
This is involved change and is critical path at kernel of storage in vmware hypervisor.
We have work around that vm (which was created before upgrade) to be stopped and started once to avoid this issue.
As we have work around reducing priority to major.
> [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
> Priority: Critical
> Fix For: 4.4.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.2#6252)