Rayees Namathponnan created CLOUDSTACK-4358:
-----------------------------------------------
Summary: [Automation] Few VM deployment failed with
IndexOutOfBoundsException
Key: CLOUDSTACK-4358
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4358
Project: CloudStack
Issue Type: Test
Security Level: Public (Anyone can view this level - this is the default.)
Components: Automation, VMware
Affects Versions: 4.2.0
Reporter: Rayees Namathponnan
Fix For: 4.2.0
This issue observed while executing test case
integration.component.test_stopped_vm.TestDeployVMFromTemplate.test_deploy_vm_password_enabled
VM deployment failed with below error in MS
2013-08-15 06:25:04,040 DEBUG [storage.volume.VolumeServiceImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Acquire
lock on VMTemplateStoragePool 11 with timeout 3600 seconds
2013-08-15 06:25:04,041 INFO [storage.volume.VolumeServiceImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) lock is
acquired for VMTemplateStoragePool 11
2013-08-15 06:25:04,051 DEBUG [storage.motion.AncientDataMotionStrategy]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ])
copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
2013-08-15 06:25:04,065 DEBUG [agent.transport.Request]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Seq
9-1658651433: Sending { Cmd , MgmtId: 90928106758026, via: 9, Ver: v1, Flags:
100011, [{"org.apache.cloud
stack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/282/230/3e85ab63-d22b-33b3-9e5e-e246b7413fff.ova","origUrl":"http://nfs1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.
1-desktop-i386-nest-13.02.04.ova","uuid":"74cf2a78-5935-4c31-baca-d237f4fcf974","id":230,"format":"OVA","accountId":282,"checksum":"63d4a4350424504f416fcd989b6ef1b2","hvm":true,"displayText":"Cent
OS Template","imageDataStore":{"com.clou
d.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/automation/SC-CLOUD-QA03/secondary1","_role":"Image"}},"name":"230-282-0c4f6793-b7ab-334a-9a13-41f5580cdf90","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.st
orage.to.TemplateObjectTO":{"origUrl":"http://nfs1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.1-desktop-i386-nest-13.02.04.ova","uuid":"74cf2a78-5935-4c31-baca-d237f4fcf974","id":230,"format":"OVA","accountId":282,"checksum":"63d4a43504
24504f416fcd989b6ef1b2","hvm":true,"displayText":"Cent OS
Template","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4faf04c2-6dd8-3025-b43f-65d32cc49d02","id":1,"poolType":"NetworkFilesystem","host":"10.2
23.110.232","path":"/export/home/automation/SC-CLOUD-QA03/primary1","port":2049}},"name":"230-282-0c4f6793-b7ab-334a-9a13-41f5580cdf90","hypervisorType":"VMware"}},"executeInSequence":false,"wait":10800}}]
}
2013-08-15 06:25:04,099 DEBUG [agent.transport.Request]
(AgentManager-Handler-3:null) Seq 9-1658651433: Processing: { Ans: , MgmtId:
90928106758026, via: 9, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"r
esult":false,"details":"Unable to copy template to primary storage due to
exception:Exception: java.lang.IndexOutOfBoundsException\nMessage: Index: 0,
Size: 0\n","wait":0}}] }
2013-08-15 06:25:04,100 DEBUG [agent.transport.Request]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Seq
9-1658651433: Received: { Ans: , MgmtId: 90928106758026, via: 9, Ver: v1,
Flags: 10, { CopyCmdAnswer } }
2013-08-15 06:25:04,108 INFO [storage.volume.VolumeServiceImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ])
releasing lock for VMTemplateStoragePool 11
2013-08-15 06:25:04,108 WARN [utils.db.Merovingian2]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Was
unable to find lock for the key template_spool_ref11 and thread id 557745274
2013-08-15 06:25:04,108 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Unable
to create Vol[442|vm=388|ROOT]:Unable to copy template to primary storage due
to exception:Exce
ption: java.lang.IndexOutOfBoundsException
Message: Index: 0, Size: 0
2013-08-15 06:25:04,108 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Unable
to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
unreachable: Unable to create Vol[442|vm=388|ROOT]:Unable to copy template to
primary storage due to exception:Exception: java.lang.IndexOutOfBoundsException
Message: Index: 0, Size: 0
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2534)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2582)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:885)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:575)
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:3405)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1947)
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:722)
2013-08-15 06:25:04,112 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Cleaning
up resources for the vm VM[User|f57494f3-a7bc-42db-995e-8cb1a37d2c05] in
Starting state
2013-08-15 06:25:04,114 DEBUG [agent.transport.Request]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Seq
2-738400257: Sending { Cmd , MgmtId: 90928106758026, via: 2, Ver: v1, Flags:
100011, [{"com.cloud.agent.a
pi.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-282-388-TestVM","wait":0}}]
}
2013-08-15 06:25:04,114 DEBUG [agent.transport.Request]
(Job-Executor-151:job-1405 = [ 0c22bfca-fc58-42a0-a5eb-23def296accf ]) Seq
2-738400257: Executing: { Cmd , MgmtId: 90928106758026, via: 2, Ver: v1,
Flags: 100011, [{"com.cloud.agen
t.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-282-388-TestVM","wait":0}}]
}
2013-08-15 06:25:04,114 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-427:null) Seq 2-738400257: Executing request
2013-08-15 06:25:04,114 INFO [vmware.resource.VmwareResource]
(DirectAgent-427:10.223.250.130) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"vmName":"i-282-388-TestVM","wait":0}
2013-08-15 06:25:04,114 DEBUG [vmware.mo.HostMO]
(DirectAgent-427:10.223.250.130) find VM i-282-388-TestVM on host
2013-08-15 06:25:04,114 INFO [vmware.mo.HostMO]
(DirectAgent-427:10.223.250.130) VM i-282-388-TestVM not found in host cache
2013-08-15 06:25:04,114 DEBUG [vmware.mo.HostMO]
(DirectAgent-427:10.223.250.130) load VM cache on host
2013-08-15 06:25:04,189 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===START=== 10.223.240.195 -- GET
signature=CcJfTKC96KAEAnn4QsX3ugwmQjM%3D&apiKey=HT6afEipxhIsvPB-kqcrVxmMjNFze1HL2xaG0FX-eTigbuTTnL03DW8DdXi1MTaGBGzE5TKdy5l-s
KooRFzdNg&command=queryAsyncJobResult&response=json&jobid=5bd6a1a1-6b10-4606-91e1-b3b28bfbd28c
2013-08-15 06:25:04,207 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===END=== 10.223.240.195 -- GET
signature=CcJfTKC96KAEAnn4QsX3ugwmQjM%3D&apiKey=HT6afEipxhIsvPB-kqcrVxmMjNFze1HL2xaG0FX-eTigbuTTnL03DW8DdXi1MTaGBGzE5TKdy5l-sKo
oRFzdNg&command=queryAsyncJobResult&response=json&jobid=5bd6a1a1-6b10-4606-91e1-b3b28bfbd28c
2013-08-15 06:25:04,233 INFO [vmware.resource.VmwareResource]
(DirectAgent-427:10.223.250.130) VM i-282-388-TestVM is no longer in vSphere
Below log observed in SSVM
2013-08-15 08:19:36,974 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null)
Received response: Seq 9-324: { Ans: , MgmtId: 90928106758026, via: 9, Ver:
v1, Flags: 100010,
[{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Storage"
,"hostId":9,"wait":0},"result":true,"wait":0}}] }
2013-08-15 08:19:45,612 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Request:Seq 9-1658651075: { Cmd , MgmtId: 90928106758026, via: 9, Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"o
rg.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/187/223/c4af3045-3977-3930-80ca-16eeb018deb9.ova","origUrl":"http://nfs1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.1-desktop-i386-nest-13.02.04.ova","uuid":"9490e
c99-f2b8-4e38-b59a-7dbda52fe17f","id":223,"format":"OVA","accountId":187,"checksum":"63d4a4350424504f416fcd989b6ef1b2","hvm":true,"displayText":"Public
Template","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.
232:/export/home/automation/SC-CLOUD-QA03/secondary1","_role":"Image"}},"name":"223-187-598439f8-0b64-3dea-a8e1-876facb1ca43","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://nf
s1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.1-desktop-i386-nest-13.02.04.ova","uuid":"9490ec99-f2b8-4e38-b59a-7dbda52fe17f","id":223,"format":"OVA","accountId":187,"checksum":"63d4a4350424504f416fcd989b6ef1b2","hvm":true,"displayText"
:"Public
Template","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4faf04c2-6dd8-3025-b43f-65d32cc49d02","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/automation/SC-CL
OUD-QA03/primary1","port":2049}},"name":"223-187-598439f8-0b64-3dea-a8e1-876facb1ca43","hypervisorType":"VMware"}},"executeInSequence":false,"wait":10800}}]
}
2013-08-15 08:19:45,612 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Processing command: org.apache.cloudstack.storage.command.CopyCommand
2013-08-15 08:19:45,613 INFO
[storage.resource.VmwareSecondaryStorageResourceHandler]
(agentRequest-Handler-4:null) Open new VmwareContext. vCenter: 10.223.52.12,
user: Administrator, password: P*******
2013-08-15 08:19:46,292 WARN
[storage.resource.VmwareSecondaryStorageResourceHandler]
(agentRequest-Handler-4:null) Unable to retrive host network information due to
exception java.lang.NullPointerException, host: HostSystem-host-22
2013-08-15 08:19:46,299 ERROR [storage.resource.VmwareStorageProcessor]
(agentRequest-Handler-4:null) Unable to copy template to primary storage due to
exception:Exception: java.lang.IndexOutOfBoundsException
Message: Index: 0, Size: 0
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
at java.util.ArrayList.rangeCheck(ArrayList.java:571)
at java.util.ArrayList.get(ArrayList.java:349)
at
com.cloud.hypervisor.vmware.mo.DatacenterMO.getOwnerDatacenter(DatacenterMO.java:315)
at
com.cloud.hypervisor.vmware.mo.HostMO.getHyperHostDatacenter(HostMO.java:214)
at
com.cloud.storage.resource.VmwareStorageProcessor.copyTemplateToPrimaryStorage(VmwareStorageProcessor.java:211)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:70)
at
com.cloud.storage.resource.VmwareStorageSubsystemCommandHandler.execute(VmwareStorageSubsystemCommandHandler.java:147)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49)
at
com.cloud.storage.resource.VmwareSecondaryStorageResourceHandler.executeRequest(VmwareSecondaryStorageResourceHandler.java:99)
at
com.cloud.storage.resource.PremiumSecondaryStorageResource.executeRequest(PremiumSecondaryStorageResource.java:56)
at com.cloud.agent.Agent.processRequest(Agent.java:525)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:852)
at com.cloud.utils.nio.Task.run(Task.java:83)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-08-15 08:19:46,475 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Seq 9-1658651075: { Ans: , MgmtId: 90928106758026, via: 9, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unable
to copy template to primary storage due to exception:Exception:
java.lang.IndexOutOfBoundsException\nMessage: Index: 0, Size: 0\n","wait":0}}] }
2013-08-15 08:19:49,600 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Request:Seq 9-1658651076: { Cmd , MgmtId: 90928106758026, via: 9, Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/187/223/c4af3045-3977-3930-80ca-16eeb018deb9.ova","origUrl":"http://nfs1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.1-desktop-i386-nest-13.02.04.ova","uuid":"9490ec99-f2b8-4e38-b59a-7dbda52fe17f","id":223,"format":"OVA","accountId":187,"checksum":"63d4a4350424504f416fcd989b6ef1b2","hvm":true,"displayText":"Public
Template","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232:/export/home/automation/SC-CLOUD-QA03/secondary1","_role":"Image"}},"name":"223-187-598439f8-0b64-3dea-a8e1-876facb1ca43","hypervisorType":"VMware"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://nfs1.lab.vmops.com/templates/ubuntu/ubuntu-12.04.1-desktop-i386-nest-13.02.04.ova","uuid":"9490ec99-f2b8-4e38-b59a-7dbda52fe17f","id":223,"format":"OVA","accountId":187,"checksum":"63d4a4350424504f416fcd989b6ef1b2","hvm":true,"displayText":"Public
Template","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"16c8ee2e-3f26-3062-8878-b7d6c53c5797","id":2,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/automation/SC-CLOUD-QA03/primary2","port":2049}},"name":"223-187-598439f8-0b64-3dea-a8e1-876facb1ca43","hypervisorType":"VMware"}},"executeInSequence":false,"wait":10800}}]
}
2013-08-15 08:19:49,600 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Processing command: org.apache.cloudstack.storage.command.CopyCommand
2013-08-15 08:19:49,600 INFO
[storage.resource.VmwareSecondaryStorageResourceHandler]
(agentRequest-Handler-5:null) Open new VmwareContext. vCenter: 10.223.52.12,
user: Administrator, password: P*******
2013-08-15 08:19:49,610 WARN
[storage.resource.VmwareSecondaryStorageResourceHandler]
(agentRequest-Handler-5:null) Unable to retrive host network information due to
exception java.lang.NullPointerException, host: HostSystem-host-22
2013-08-15 08:19:49,614 ERROR [storage.resource.VmwareStorageProcessor]
(agentRequest-Handler-5:null) Unable to copy template to primary storage due to
exception:Exception: java.lang.IndexOutOfBoundsException
--
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
