cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Likitha Shetty (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CLOUDSTACK-4253) [VMWARE] Failed to deploy one of the VM with NPE when tried deploy two VM's at the same time (While acquiring lock on Storage pool)
Date Fri, 16 Aug 2013 05:28:47 GMT

    [ https://issues.apache.org/jira/browse/CLOUDSTACK-4253?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13741940#comment-13741940
] 

Likitha Shetty commented on CLOUDSTACK-4253:
--------------------------------------------

The new error seems related to https://issues.apache.org/jira/browse/CLOUDSTACK-4358.
                
> [VMWARE] Failed to deploy one of the VM with NPE when tried deploy two VM's at the same
time (While acquiring lock on Storage pool)
> -----------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: CLOUDSTACK-4253
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4253
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: VMware
>    Affects Versions: 4.2.0
>            Reporter: Sailaja Mada
>            Assignee: edison su
>            Priority: Critical
>             Fix For: 4.2.0
>
>         Attachments: apilog.log, db.dmp, management-server.log
>
>
> Steps:
> 1. Configure ADv zone with Standard Vswitch with VMWARE cluster of 2 hosts.
> 2. Create an account 
> 3. Tried to deploy VM using this account
> 4. When its created, tried to create one more instance 
> Observation:
> 1. Second instance got created . But first instance failed to deploy with NPE:
> 2013-08-12 22:04:58,956 INFO  [storage.volume.VolumeServiceImpl] (Job-Executor-49:job-112
= [ ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Unable to acquire lock on VMTemplateStoragePool
10
> 2013-08-12 22:04:58,959 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-49:job-112
= [ ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Failed to start instance VM[User|cdcuser1i2]
> java.lang.NullPointerException
>         at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:416)
>         at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:538)
>         at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2493)
>         at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2550)
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:884)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:574)
>         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:3402)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2962)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2948)
>         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:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:679)
> 2013-08-12 22:04:58,962 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Asking BareMetalUserdata to prepare for Nic[66-31-2a3aba48-b63f-456b-be81-03f18bd9862a-10.1.1.199]
> 2013-08-12 22:04:58,967 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Service SecurityGroup is not supported in the
network id=214
> 2013-08-12 22:04:58,969 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Checking if we need to prepare 1 volumes for VM[User|cdcuser1i1]
> 2013-08-12 22:04:58,973 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-49:job-112
= [ ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Cleaning up resources for the vm VM[User|cdcuser1i2]
in Starting state
> 2013-08-12 22:04:58,979 DEBUG [agent.transport.Request] (Job-Executor-49:job-112 = [
ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Seq 8-104267875: Sending  { Cmd , MgmtId: 90310994128556,
via: 8, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-5-33-VM","wait":0}}]
}
> 2013-08-12 22:04:58,979 DEBUG [agent.transport.Request] (Job-Executor-49:job-112 = [
ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Seq 8-104267875: Executing:  { Cmd , MgmtId: 90310994128556,
via: 8, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-5-33-VM","wait":0}}]
}
> 2013-08-12 22:04:58,979 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-156:null)
Seq 8-104267875: Executing request
> 2013-08-12 22:04:58,979 INFO  [vmware.resource.VmwareResource] (DirectAgent-156:10.102.192.18)
Executing resource StopCommand: {"isProxy":false,"executeInSequence":false,"vmName":"i-5-33-VM","wait":0}
> 2013-08-12 22:04:58,980 DEBUG [vmware.mo.HostMO] (DirectAgent-156:10.102.192.18) find
VM i-5-33-VM on host
> 2013-08-12 22:04:58,980 INFO  [vmware.mo.HostMO] (DirectAgent-156:10.102.192.18) VM i-5-33-VM
not found in host cache
> 2013-08-12 22:04:58,980 DEBUG [vmware.mo.HostMO] (DirectAgent-156:10.102.192.18) load
VM cache on host
> 2013-08-12 22:04:59,002 DEBUG [storage.image.TemplateDataFactoryImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) template 7 is already in store:2, type:Image
> 2013-08-12 22:04:59,003 INFO  [vmware.resource.VmwareResource] (DirectAgent-156:10.102.192.18)
VM i-5-33-VM is no longer in vSphere
> 2013-08-12 22:04:59,004 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-156:null)
Seq 8-104267875: Response Received:
> 2013-08-12 22:04:59,004 DEBUG [agent.transport.Request] (DirectAgent-156:null) Seq 8-104267875:
Processing:  { Ans: , MgmtId: 90310994128556, via: 8, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"details":"VM
i-5-33-VM is no longer in vSphere","wait":0}}] }
> 2013-08-12 22:04:59,004 DEBUG [agent.transport.Request] (Job-Executor-49:job-112 = [
ad5f8d28-2cd7-4a4a-9dd5-91b92af66fc0 ]) Seq 8-104267875: Received:  { Ans: , MgmtId: 90310994128556,
via: 8, Ver: v1, Flags: 10, { StopAnswer } }
> 2013-08-12 22:04:59,012 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Not found (templateId:7poolId:202) in template_spool_ref,
persisting it
> 2013-08-12 22:04:59,309 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-160:null)
Seq 8-104267876: Executing request
> 2013-08-12 22:04:59,310 INFO  [vmware.resource.VmwareResource] (DirectAgent-160:10.102.192.18)
Executing resource DhcpEntryCommand: {"vmMac":"02:00:23:5f:00:03","vmIpAddress":"10.1.1.208","vmName":"cdcuser1i2","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:23:5f:00:03","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.name":"r-32-VM","router.ip":"10.102.195.144"},"wait":0}
> 2013-08-12 22:04:59,310 DEBUG [vmware.resource.VmwareResource] (DirectAgent-160:10.102.192.18)
Run command on domR 10.102.195.144, /root/edithosts.sh  -m 02:00:23:5f:00:03 -4 10.1.1.208
-h cdcuser1i2 -d 10.1.1.1 -n 10.1.1.1
> 2013-08-12 22:04:59,310 DEBUG [vmware.resource.VmwareResource] (DirectAgent-160:10.102.192.18)
Use router's private IP for SSH control. IP : 10.102.195.144
> 2013-08-12 22:04:59,481 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null)
Seq 7-1169424630: Processing:  { Ans: , MgmtId: 90310994128556, via: 7, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unable
to execute PrimaryStorageDownloadCommand due to exception","wait":0}}] }
> 2013-08-12 22:04:59,482 DEBUG [agent.transport.Request] (Job-Executor-48:job-111 = [
e68c85d0-363d-4976-a137-5f98636ffea2 ]) Seq 7-1169424630: Received:  { Ans: , MgmtId: 90310994128556,
via: 7, Ver: v1, Flags: 10, { CopyCmdAnswer } }
> 2013-08-12 22:04:59,557 INFO  [storage.volume.VolumeServiceImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) releasing lock for VMTemplateStoragePool 11
> 2013-08-12 22:04:59,558 WARN  [utils.db.Merovingian2] (Job-Executor-48:job-111 = [ e68c85d0-363d-4976-a137-5f98636ffea2
]) Was unable to find lock for the key template_spool_ref11 and thread id 1273873440
> 2013-08-12 22:04:59,558 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Unable to create Vol[39|vm=31|ROOT]:Unable to
execute PrimaryStorageDownloadCommand due to exception
> 2013-08-12 22:04:59,558 INFO  [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Unable to contact resource.
> com.cloud.exception.StorageUnavailableException: Resource [StoragePool:202] is unreachable:
Unable to create Vol[39|vm=31|ROOT]:Unable to execute PrimaryStorageDownloadCommand due to
exception
>         at com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2501)
>         at com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2550)
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:884)
>         at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:574)
>         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:3402)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2962)
>         at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2948)
>         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:1146)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
>         at java.lang.Thread.run(Thread.java:679)
> 2013-08-12 22:04:59,562 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-48:job-111
= [ e68c85d0-363d-4976-a137-5f98636ffea2 ]) Cleaning up resources for the vm VM[User|cdcuser1i1]
in Starting state
> 2013-08-12 22:04:59,564 DEBUG [agent.transport.Request] (Job-Executor-48:job-111 = [
e68c85d0-363d-4976-a137-5f98636ffea2 ]) Seq 9-1419444308: Sending  { Cmd , MgmtId: 90310994128556,
via: 9, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-5-31-VM","wait":0}}]
}
> 2013-08-12 22:04:59,564 DEBUG [agent.transport.Request] (Job-Executor-48:job-111 = [
e68c85d0-363d-4976-a137-5f98636ffea2 ]) Seq 9-1419444308: Executing:  { Cmd , MgmtId: 90310994128556,
via: 9, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-5-31-VM","wait":0}}]
}
> 2013-08-12 22:04:59,564 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-331:null)
Seq 9-1419444308: Executing request
> 2013-08-12 22:04:59,564 INFO  [vmware.resource.VmwareResource] (DirectAgent-331:10.102.192.23)
Executing resource StopCommand: {"isProxy":false,"executeInSequence":false,"vmName":"i-5-31-VM","wait":0}
> 2013-08-12 22:04:59,565 DEBUG [vmware.mo.HostMO] (DirectAgent-331:10.102.192.23) find
VM i-5-31-VM on host

--
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