[
https://issues.apache.org/jira/browse/CLOUDSTACK-4358?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rayees Namathponnan reopened CLOUDSTACK-4358:
---------------------------------------------
Issue found with today run, also reopening
Attached logs, please search for job-646
2013-08-18 05:11:07,712 DEBUG [agent.transport.Request]
(Job-Executor-91:job-646 = [ be7da0ea-ae6f-4d9b-9883-14f165faaf51 ]) Seq
9-1588920457: Received: { Ans: , MgmtId: 9092
8106758026, via: 9, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2013-08-18 05:11:07,716 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END=== 10.223.240.195 -- GET
signature=wLOsNrmsL9c%2BIVQwHw3FEjAFRUE%3D&apiKey=Moyn9S9mP6pfTV1
YS9ku2nbPYsFwLfqjDhQ689mCrqWhqSFVN6GVMM1RUsqAsGdt1Bhu0Oi8KqlKUO06U9UrAw&command=queryAsyncJobResult&response=json&jobid=6b9babe4-b996-4e68-89f0-8f91dcb55ecb
2013-08-18 05:11:07,726 INFO [storage.volume.VolumeServiceImpl]
(Job-Executor-91:job-646 = [ be7da0ea-ae6f-4d9b-9883-14f165faaf51 ]) releasing
lock for VMTemplateStoragePool 7
2013-08-18 05:11:07,726 WARN [utils.db.Merovingian2] (Job-Executor-91:job-646
= [ be7da0ea-ae6f-4d9b-9883-14f165faaf51 ]) Was unable to find lock for the key
template_spool_ref7 and thread id 1805541990
2013-08-18 05:11:07,727 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-91:job-646 = [ be7da0ea-ae6f-4d9b-9883-14f165faaf51 ]) Unable to
create Vol[212|vm=181|ROOT]:Unable to copy template to primary storage due to
exception:Exception: javax.xml.ws.soap.SOAPFaultException
Message:
Required parameter spec is missing
> [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
>
>
> 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
