cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rayees Namathponnan (JIRA)" <j...@apache.org>
Subject [jira] [Reopened] (CLOUDSTACK-4358) [Automation] [vmware] Few VM deployment failed with IndexOutOfBoundsException at "VolumeManagerImpl.java:2534"
Date Tue, 20 Aug 2013 20:54:55 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-4358?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Rayees Namathponnan reopened CLOUDSTACK-4358:
---------------------------------------------


Issue found last run also, 

attached log please log in management-server.log.2013-08-19.gz
                
> [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.0
>
>         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

Mime
View raw message