[
https://issues.apache.org/jira/browse/CLOUDSTACK-4358?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Kelven Yang resolved CLOUDSTACK-4358.
-------------------------------------
Resolution: Fixed
I believe IndexOutOfBoundsException issue is fixed by VMware session keep-alive
mechanism.
"Few VM deployment failed" may be caused by various reasons, if you see
automation failures like this, find the related exception both in management
server log and SSVM log and file bug separately.
> [Automation] [vmware] Few VM deployment failed with IndexOutOfBoundsException
> at "VolumeManagerImpl.java:2534"
> --------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4358
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4358
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Automation, VMware
> Affects Versions: 4.2.0
> Reporter: Rayees Namathponnan
> Assignee: Kelven Yang
> Priority: Blocker
> Fix For: 4.2.1
>
> Attachments: CLOUDSTACK-4358_Log2.rar, CLOUDSTACK-4358.rar,
> management-server.log.2013-08-19.gz
>
>
> 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
