Sailaja Mada created CLOUDSTACK-4593:
----------------------------------------
Summary: [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
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 is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
