You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Abhinandan Prateek (JIRA)" <ji...@apache.org> on 2014/06/02 09:10:01 UTC
[jira] [Updated] (CLOUDSTACK-6661) deployvm failed with NPE
[ https://issues.apache.org/jira/browse/CLOUDSTACK-6661?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Abhinandan Prateek updated CLOUDSTACK-6661:
-------------------------------------------
Assignee: Damodar Reddy T
> deployvm failed with NPE
> -------------------------
>
> Key: CLOUDSTACK-6661
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-6661
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: XenServer
> Affects Versions: 4.4.0
> Reporter: Jayapal Reddy
> Assignee: Damodar Reddy T
> Priority: Critical
> Fix For: 4.4.0
>
>
> While deploying vm observed the NPE
> java.lang.NullPointerException
> at com.cloud.hypervisor.XenServerGuru.implement(XenServerGuru.java:96)
> =====
> 2014-05-14 11:58:59,398 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (867392383@qtp-1655170479-7:ctx-2fd5e67f ctx-20936702) submit async job-178, details: AsyncJobVO {id:178, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 26, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"serviceofferingid":"baa62f3e-9f44-46ad-a137-7275bcaf8c99","sessionkey":"Li3x1YB3+DUERGcuaZ9plLrGSZc\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"e7d72675-2bf3-4bab-b673-d9d92a735603","httpmethod":"GET","templateid":"79f647d6-da5c-11e3-80cb-b51f7904a635","response":"json","id":"26","ctxDetails":"{\"com.cloud.template.VirtualMachineTemplate\":5,\"com.cloud.vm.VirtualMachine\":26,\"com.cloud.dc.DataCenter\":1,\"VirtualMachine\":\"ed6a3bef-8e60-4001-8fc9-d0bd1ad15312\",\"com.cloud.offering.ServiceOffering\":1}","hypervisor":"XenServer","iptonetworklist[0].networkid":"4bcc4888-3a5d-4736-8b3e-ad8204606dcd","_":"1400048939193","uuid":"ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","ctxAccountId":"2","ctxStartEventId":"197"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 1, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-05-14 11:58:59,399 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-7:job-178) Add job-178 into job monitoring
> 2014-05-14 11:58:59,399 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:job-178) Executing AsyncJobVO {id:178, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 26, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"serviceofferingid":"baa62f3e-9f44-46ad-a137-7275bcaf8c99","sessionkey":"Li3x1YB3+DUERGcuaZ9plLrGSZc\u003d","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"e7d72675-2bf3-4bab-b673-d9d92a735603","httpmethod":"GET","templateid":"79f647d6-da5c-11e3-80cb-b51f7904a635","response":"json","id":"26","ctxDetails":"{\"com.cloud.template.VirtualMachineTemplate\":5,\"com.cloud.vm.VirtualMachine\":26,\"com.cloud.dc.DataCenter\":1,\"VirtualMachine\":\"ed6a3bef-8e60-4001-8fc9-d0bd1ad15312\",\"com.cloud.offering.ServiceOffering\":1}","hypervisor":"XenServer","iptonetworklist[0].networkid":"4bcc4888-3a5d-4736-8b3e-ad8204606dcd","_":"1400048939193","uuid":"ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","ctxAccountId":"2","ctxStartEventId":"197"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 1, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2014-05-14 11:58:59,400 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-2fd5e67f ctx-20936702) ===END=== 10.252.192.19 -- GET command=deployVirtualMachine&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&zoneid=e7d72675-2bf3-4bab-b673-d9d92a735603&templateid=79f647d6-da5c-11e3-80cb-b51f7904a635&hypervisor=XenServer&serviceofferingid=baa62f3e-9f44-46ad-a137-7275bcaf8c99&iptonetworklist%5B0%5D.networkid=4bcc4888-3a5d-4736-8b3e-ad8204606dcd&_=1400048939193
> 2014-05-14 11:58:59,407 DEBUG [c.c.a.d.ParamProcessWorker] (API-Job-Executor-7:job-178 ctx-836ec730) Access granted to Acct[7aa84a4e-da5c-11e3-80cb-b51f7904a635-admin] to service offering:1 by RoleBasedEntityAccessChecker
> 2014-05-14 11:58:59,409 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-SystemCapability from cache: true
> 2014-05-14 11:58:59,409 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Root Access granted to Acct[7aa84a4e-da5c-11e3-80cb-b51f7904a635-admin] by RoleBasedEntityAccessChecker
> 2014-05-14 11:58:59,411 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:58:59,413 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-DomainResourceCapability from cache: false
> 2014-05-14 11:58:59,414 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-VirtualMachineTemplate5-UseEntry-deployVirtualMachine from cache: true
> 2014-05-14 11:58:59,414 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Access to {Tmpl[5-VHD-centos56-x86_64-xen} granted to Acct[7aa84a4e-da5c-11e3-80cb-b51f7904a635-admin] by RoleBasedEntityAccessChecker
> 2014-05-14 11:58:59,414 WARN [c.c.a.d.ParamGenericValidationWorker] (API-Job-Executor-7:job-178 ctx-836ec730) Received unknown parameters for command deployVirtualMachine. Unknown parameters : ctxdetails
> 2014-05-14 11:58:59,424 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-SystemCapability from cache: true
> 2014-05-14 11:58:59,424 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Root Access granted to Acct[7aa84a4e-da5c-11e3-80cb-b51f7904a635-admin] by RoleBasedEntityAccessChecker
> 2014-05-14 11:58:59,426 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:58:59,427 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (API-Job-Executor-7:job-178 ctx-836ec730) IAM access check for 2-null-null-DomainResourceCapability from cache: false
> 2014-05-14 11:58:59,439 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:58:59,444 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:58:59,458 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Deploy avoids pods: [], clusters: [], hosts: []
> 2014-05-14 11:58:59,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5620295
> 2014-05-14 11:58:59,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
> 2014-05-14 11:58:59,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Is ROOT volume READY (pool already allocated)?: No
> 2014-05-14 11:58:59,459 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-7:job-178 ctx-836ec730) Searching all possible resources under this Zone: 1
> 2014-05-14 11:58:59,460 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-7:job-178 ctx-836ec730) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2014-05-14 11:58:59,465 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-7:job-178 ctx-836ec730) Removing from the clusterId list these clusters from avoid set: []
> 2014-05-14 11:58:59,482 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Checking resources in Cluster: 1 under Pod: 1
> 2014-05-14 11:58:59,483 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
> 2014-05-14 11:58:59,486 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-2-Routing]]
> 2014-05-14 11:58:59,490 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-2-Routing]]
> 2014-05-14 11:58:59,490 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
> 2014-05-14 11:58:59,497 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Host: 2 has cpu capability (cpu:4, speed:3093) to support requested CPU: 1 and requested speed: 500
> 2014-05-14 11:58:59,498 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Checking if host: 2 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Hosts's actual total CPU: 12372 and CPU after applying overprovisioning: 12372
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Free CPU: 9372 , Requested CPU: 500
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Free RAM: 4463203328 , Requested RAM: 536870912
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 2, used: 3000, reserved: 0, actual total: 12372, total with overprovisioning: 12372; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-05-14 11:58:59,500 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 2, used: 2952790016, reserved: 0, total: 7415993344; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2014-05-14 11:58:59,500 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Found a suitable host, adding to list: 2
> 2014-05-14 11:58:59,500 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-7:job-178 ctx-836ec730 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2014-05-14 11:58:59,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Checking suitable pools for volume (Id, Type): (26,ROOT)
> 2014-05-14 11:58:59,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) We need to allocate new storagepool for this volume
> 2014-05-14 11:58:59,504 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Calling StoragePoolAllocators to find suitable pools
> 2014-05-14 11:58:59,506 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2014-05-14 11:58:59,506 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) ClusterScopeStoragePoolAllocator looking for storage pool
> 2014-05-14 11:58:59,506 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) Looking for pools in dc: 1 pod:1 cluster:1
> 2014-05-14 11:58:59,508 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) Found pools matching tags: [Pool[3|NetworkFilesystem]]
> 2014-05-14 11:58:59,511 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) Removing pool Pool[3|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
> 2014-05-14 11:58:59,512 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) Checking if storage pool is suitable, name: null ,poolId: 3
> 2014-05-14 11:58:59,518 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Checking pool 3 for storage, totalSize: 5902284816384, usedBytes: 1713564614656, usedPct: 0.2903222511220333, disable threshold: 0.85
> 2014-05-14 11:58:59,527 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Found storage pool pri of type NetworkFilesystem with overprovisioning factor 2
> 2014-05-14 11:58:59,527 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Total over provisioned capacity calculated is 2 * 5902284816384
> 2014-05-14 11:58:59,527 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Total capacity of the pool pri id: 3 is 11804569632768
> 2014-05-14 11:58:59,529 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Checking pool: 3 for volume allocation [Vol[26|vm=26|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 53435432960, askingSize : 21474836480, allocated disable threshold: 0.85
> 2014-05-14 11:58:59,529 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-7:job-178 ctx-836ec730) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2014-05-14 11:58:59,529 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-05-14 11:58:59,529 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Checking if host: 2 can access any suitable storage pool for volume: ROOT
> 2014-05-14 11:58:59,530 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Host: 2 can access pool: 3
> 2014-05-14 11:58:59,531 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Found a potential host id: 2 name: Rack1Pod1Host22 and associated storage pools for this VM
> 2014-05-14 11:58:59,532 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(26|ROOT-->Pool(3))]
> 2014-05-14 11:58:59,547 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-7:job-178 ctx-836ec730) Sync job-179 execution on object VmWorkJobQueue.26
> 2014-05-14 11:58:59,551 WARN [c.c.u.d.Merovingian2] (API-Job-Executor-7:job-178 ctx-836ec730) Was unable to find lock for the key vm_instance26 and thread id 2063508911
> 2014-05-14 11:59:00,077 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-39:ctx-cfac909e) Seq 2-6485183463413514300: Response Received:
> 2014-05-14 11:59:00,078 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-64f65db8) Seq 2-6485183463413514300: Received: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2014-05-14 11:59:01,155 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-60c1ccc2) Execute sync-queue item: SyncQueueItemVO {id:16, queueId: 105, contentType: AsyncJob, contentId: 179, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Wed May 14 11:58:59 IST 2014}
> 2014-05-14 11:59:01,156 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-60c1ccc2) Schedule queued job-179
> 2014-05-14 11:59:01,167 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-11:job-178/job-179) Add job-179 into job monitoring
> 2014-05-14 11:59:01,168 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-11:job-178/job-179) Executing AsyncJobVO {id:179, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAGnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAAAnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 1, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed May 14 11:58:59 IST 2014}
> 2014-05-14 11:59:01,169 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-11:job-178/job-179) Run VM work job: com.cloud.vm.VmWorkStart for VM 26, job origin: 178
> 2014-05-14 11:59:01,170 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":2,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":26,"handlerName":"VirtualMachineManagerImpl"}
> 2014-05-14 11:59:01,177 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
> 2014-05-14 11:59:01,177 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Successfully transitioned to start state for VM[User|i-2-26-QA] reservation id = 02e0ac56-b26c-4526-8161-2abb0e895e8b
> 2014-05-14 11:59:01,178 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Trying to deploy VM, vm has dcId: 1 and podId: null
> 2014-05-14 11:59:01,179 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 2, poolId: null
> 2014-05-14 11:59:01,179 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Deploy avoids pods: null, clusters: null, hosts: null
> 2014-05-14 11:59:01,188 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Deploy avoids pods: [], clusters: [], hosts: []
> 2014-05-14 11:59:01,190 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5620295
> 2014-05-14 11:59:01,190 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
> 2014-05-14 11:59:01,190 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Is ROOT volume READY (pool already allocated)?: No
> 2014-05-14 11:59:01,190 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 2
> 2014-05-14 11:59:01,191 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
> 2014-05-14 11:59:01,193 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking suitable pools for volume (Id, Type): (26,ROOT)
> 2014-05-14 11:59:01,194 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) We need to allocate new storagepool for this volume
> 2014-05-14 11:59:01,195 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) IAM access check for 2-null-null-SystemCapability from cache: true
> 2014-05-14 11:59:01,195 DEBUG [c.c.u.AccountManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Root Access granted to Acct[7aa84a4e-da5c-11e3-80cb-b51f7904a635-admin] by RoleBasedEntityAccessChecker
> 2014-05-14 11:59:01,195 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Calling StoragePoolAllocators to find suitable pools
> 2014-05-14 11:59:01,195 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2014-05-14 11:59:01,195 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) ClusterScopeStoragePoolAllocator looking for storage pool
> 2014-05-14 11:59:01,195 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Looking for pools in dc: 1 pod:1 cluster:1
> 2014-05-14 11:59:01,196 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Found pools matching tags: [Pool[3|NetworkFilesystem]]
> 2014-05-14 11:59:01,198 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Removing pool Pool[3|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
> 2014-05-14 11:59:01,199 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking if storage pool is suitable, name: null ,poolId: 3
> 2014-05-14 11:59:01,203 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking pool 3 for storage, totalSize: 5902284816384, usedBytes: 1713564614656, usedPct: 0.2903222511220333, disable threshold: 0.85
> 2014-05-14 11:59:01,210 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Found storage pool pri of type NetworkFilesystem with overprovisioning factor 2
> 2014-05-14 11:59:01,210 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Total over provisioned capacity calculated is 2 * 5902284816384
> 2014-05-14 11:59:01,210 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Total capacity of the pool pri id: 3 is 11804569632768
> 2014-05-14 11:59:01,211 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking pool: 3 for volume allocation [Vol[26|vm=26|ROOT]], maxSize : 11804569632768, totalAllocatedSize : 53435432960, askingSize : 21474836480, allocated disable threshold: 0.85
> 2014-05-14 11:59:01,211 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2014-05-14 11:59:01,211 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2014-05-14 11:59:01,211 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking if host: 2 can access any suitable storage pool for volume: ROOT
> 2014-05-14 11:59:01,212 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Host: 2 can access pool: 3
> 2014-05-14 11:59:01,213 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Found a potential host id: 2 name: Rack1Pod1Host22 and associated storage pools for this VM
> 2014-05-14 11:59:01,213 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(26|ROOT-->Pool(3))]
> 2014-05-14 11:59:01,213 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Deployment found - P0=VM[User|i-2-26-QA], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(26|ROOT-->Pool(3))]
> 2014-05-14 11:59:01,219 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 2 host id before state transition: null
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Hosts's actual total CPU: 12372 and CPU after applying overprovisioning: 12372
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) We are allocating VM, increasing the used capacity of this host:2
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Current Used CPU: 3000 , Free CPU:9372 ,Requested CPU: 500
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Current Used RAM: 2952790016 , Free RAM:4463203328 ,Requested RAM: 536870912
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) CPU STATS after allocation: for host: 2, old used: 3000, old reserved: 0, actual total: 12372, total with overprovisioning: 12372; new used:3500, reserved:0; requested cpu:500,alloc_from_last:false
> 2014-05-14 11:59:01,226 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) RAM STATS after allocation: for host: 2, old used: 2952790016, old reserved: 0, total: 7415993344; new used: 3489660928, reserved: 0; requested mem: 536870912,alloc_from_last:false
> 2014-05-14 11:59:01,227 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) VM is being created in podId: 1
> 2014-05-14 11:59:01,230 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Network id=204 is already implemented
> 2014-05-14 11:59:01,239 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:59:01,243 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Changing active number of nics for network id=204 on 1
> 2014-05-14 11:59:01,248 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Asking VirtualRouter to prepare for Nic[78-26-02e0ac56-b26c-4526-8161-2abb0e895e8b-10.1.1.253]
> 2014-05-14 11:59:01,259 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Lock is acquired for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(26|ROOT-->Pool(3))]
> 2014-05-14 11:59:01,262 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Lock is released for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(26|ROOT-->Pool(3))]
> 2014-05-14 11:59:01,269 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:59:01,282 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:59:01,287 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Applying dhcp entry in network Ntwk[4bcc4888-3a5d-4736-8b3e-ad8204606dcd|Guest|8]
> 2014-05-14 11:59:01,305 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514302: Sending { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:77:d6:00:06","vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:77:d6:00:06","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"169.254.1.100","router.name":"r-18-QA"},"wait":0}}] }
> 2014-05-14 11:59:01,306 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514302: Executing: { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:77:d6:00:06","vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:77:d6:00:06","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"169.254.1.100","router.name":"r-18-QA"},"wait":0}}] }
> 2014-05-14 11:59:01,306 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-64:ctx-7ddf4c20) Seq 2-6485183463413514302: Executing request
> 2014-05-14 11:59:01,306 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-64:ctx-7ddf4c20) Executing command in VR: /opt/cloud/bin/router_proxy.sh edithosts.sh 169.254.1.100 -m 02:00:77:d6:00:06 -4 10.1.1.253 -h QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312 -d 10.1.1.1 -n 10.1.1.1
> 2014-05-14 11:59:02,074 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-10384: Processing Seq 3-10384: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":15,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-05-14 11:59:02,079 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 3-10384: Sending Seq 3-10384: { Ans: , MgmtId: 1, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-05-14 11:59:02,428 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-f950f2c1) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048942424
> 2014-05-14 11:59:02,444 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-f950f2c1 ctx-7c56a903) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:02,451 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-f950f2c1 ctx-7c56a903) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048942424
> 2014-05-14 11:59:04,883 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-64:ctx-7ddf4c20) Seq 2-6485183463413514302: Response Received:
> 2014-05-14 11:59:04,885 DEBUG [c.c.a.t.Request] (DirectAgent-64:ctx-7ddf4c20) Seq 2-6485183463413514302: Processing: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
> 2014-05-14 11:59:04,885 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514302: Received: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-05-14 11:59:04,892 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:59:04,895 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Applying userdata and password entry in network Ntwk[4bcc4888-3a5d-4736-8b3e-ad8204606dcd|Guest|8]
> 2014-05-14 11:59:04,911 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514303: Sending { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-18-QA","router.ip":"169.254.1.100","router.guest.ip":"10.1.1.1"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-18-QA","router.ip":"169.254.1.100","router.guest.ip":"10.1.1.1"},"wait":0}}] }
> 2014-05-14 11:59:04,911 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514303: Executing: { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-18-QA","router.ip":"169.254.1.100","router.guest.ip":"10.1.1.1"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.253","vmName":"QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.name":"r-18-QA","router.ip":"169.254.1.100","router.guest.ip":"10.1.1.1"},"wait":0}}] }
> 2014-05-14 11:59:04,912 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-65:ctx-5029e63e) Seq 2-6485183463413514303: Executing request
> 2014-05-14 11:59:04,912 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-65:ctx-5029e63e) Executing command in VR: /opt/cloud/bin/router_proxy.sh savepassword.sh 169.254.1.100 -v 10.1.1.253 -p fnirq_cnffjbeq
> 2014-05-14 11:59:05,425 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-ab2cb26b) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048945423
> 2014-05-14 11:59:05,440 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-ab2cb26b ctx-6f236d19) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:05,447 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-ab2cb26b ctx-6f236d19) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048945423
> 2014-05-14 11:59:05,497 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-d3e0f441) VmStatsCollector is running...
> 2014-05-14 11:59:05,508 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-66:ctx-581a4a19) Seq 2-6485183463413514304: Executing request
> 2014-05-14 11:59:08,426 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-58cd10fa) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048948423
> 2014-05-14 11:59:08,447 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-58cd10fa ctx-b9c0b88e) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:08,454 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-58cd10fa ctx-b9c0b88e) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048948423
> 2014-05-14 11:59:09,491 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-65:ctx-5029e63e) JSON IS:{"10.1.1.253":[["userdata","user-data",null],["metadata","service-offering","Small Instance"],["metadata","availability-zone","zone1"],["metadata","local-ipv4","10.1.1.253"],["metadata","local-hostname","QA-ed6a3bef-8e60-4001-8fc9-d0bd1ad15312"],["metadata","public-ipv4","10.147.52.112"],["metadata","public-hostname","10.147.52.112"],["metadata","instance-id","ed6a3bef-8e60-4001-8fc9-d0bd1ad15312"],["metadata","vm-id","ed6a3bef-8e60-4001-8fc9-d0bd1ad15312"],["metadata","public-keys",null],["metadata","cloud-identifier","CloudStack-{062ce11b-9ec8-400e-997e-34d758b49c62}"]]}
> 2014-05-14 11:59:09,492 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-65:ctx-5029e63e) Executing command in VR: /opt/cloud/bin/router_proxy.sh vmdata.py 169.254.1.100 -d eyIxMC4xLjEuMjUzIjpbWyJ1c2VyZGF0YSIsInVzZXItZGF0YSIsbnVsbF0sWyJtZXRhZGF0YSIsInNlcnZpY2Utb2ZmZXJpbmciLCJTbWFsbCBJbnN0YW5jZSJdLFsibWV0YWRhdGEiLCJhdmFpbGFiaWxpdHktem9uZSIsInpvbmUxIl0sWyJtZXRhZGF0YSIsImxvY2FsLWlwdjQiLCIxMC4xLjEuMjUzIl0sWyJtZXRhZGF0YSIsImxvY2FsLWhvc3RuYW1lIiwiUUEtZWQ2YTNiZWYtOGU2MC00MDAxLThmYzktZDBiZDFhZDE1MzEyIl0sWyJtZXRhZGF0YSIsInB1YmxpYy1pcHY0IiwiMTAuMTQ3LjUyLjExMiJdLFsibWV0YWRhdGEiLCJwdWJsaWMtaG9zdG5hbWUiLCIxMC4xNDcuNTIuMTEyIl0sWyJtZXRhZGF0YSIsImluc3RhbmNlLWlkIiwiZWQ2YTNiZWYtOGU2MC00MDAxLThmYzktZDBiZDFhZDE1MzEyIl0sWyJtZXRhZGF0YSIsInZtLWlkIiwiZWQ2YTNiZWYtOGU2MC00MDAxLThmYzktZDBiZDFhZDE1MzEyIl0sWyJtZXRhZGF0YSIsInB1YmxpYy1rZXlzIixudWxsXSxbIm1ldGFkYXRhIiwiY2xvdWQtaWRlbnRpZmllciIsIkNsb3VkU3RhY2stezA2MmNlMTFiLTllYzgtNDAwZS05OTdlLTM0ZDc1OGI0OWM2Mn0iXV19
> 2014-05-14 11:59:11,232 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d230545e) Found 2 routers to update status.
> 2014-05-14 11:59:11,236 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d230545e) Found 0 networks to update RvR status.
> 2014-05-14 11:59:11,427 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-a51aa7ba) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048951424
> 2014-05-14 11:59:11,442 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-a51aa7ba ctx-dd20b6d2) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:11,447 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-a51aa7ba ctx-dd20b6d2) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048951424
> 2014-05-14 11:59:12,165 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-16:null) SeqA 3-10385: Processing Seq 3-10385: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":15,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
> 2014-05-14 11:59:12,171 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-16:null) SeqA 3-10385: Sending Seq 3-10385: { Ans: , MgmtId: 1, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-05-14 11:59:12,615 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-66:ctx-581a4a19) Vm cpu utilization 0.0
> 2014-05-14 11:59:12,615 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-66:ctx-581a4a19) Vm cpu utilization 0.0
> 2014-05-14 11:59:14,427 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-ece52eda) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048954425
> 2014-05-14 11:59:14,441 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-ece52eda ctx-b8889edb) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:14,446 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-ece52eda ctx-b8889edb) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048954425
> 2014-05-14 11:59:14,817 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-65:ctx-5029e63e) Seq 2-6485183463413514303: Response Received:
> 2014-05-14 11:59:14,818 DEBUG [c.c.a.t.Request] (DirectAgent-65:ctx-5029e63e) Seq 2-6485183463413514303: Processing: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
> 2014-05-14 11:59:14,819 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514303: Received: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, { Answer, Answer } }
> 2014-05-14 11:59:14,820 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Service SecurityGroup is not supported in the network id=204
> 2014-05-14 11:59:14,821 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Checking if we need to prepare 1 volumes for VM[User|i-2-26-QA]
> 2014-05-14 11:59:14,832 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) template 5 is already in store:1, type:Image
> 2014-05-14 11:59:14,835 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) template 5 is already in store:3, type:Primary
> 2014-05-14 11:59:14,852 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
> 2014-05-14 11:59:14,862 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514305: Sending { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"079cc5a8-48a4-4a80-8960-a8a57fea2e76","origUrl":"http://10.147.28.7/templates/builtin/centos56-x86_64.vhd.bz2","uuid":"79f647d6-da5c-11e3-80cb-b51f7904a635","id":5,"format":"VHD","accountId":1,"checksum":"905cec879afd9c9d22ecc8036131a180","hvm":false,"displayText":"CentOS 5.6(64-bit) no GUI (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"6b2f5840-b5f9-3a42-bfd8-a92b884984db","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/jayapal/pri-4.4","port":2049,"url":"NetworkFilesystem://10.147.28.7/export/home/jayapal/pri-4.4/?ROLE=Primary&STOREUUID=6b2f5840-b5f9-3a42-bfd8-a92b884984db"}},"name":"centos56-x86_64-xen","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b4102c65-8acc-4949-a819-a467f8f8ba1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"6b2f5840-b5f9-3a42-bfd8-a92b884984db","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/jayapal/pri-4.4","port":2049,"url":"NetworkFilesystem://10.147.28.7/export/home/jayapal/pri-4.4/?ROLE=Primary&STOREUUID=6b2f5840-b5f9-3a42-bfd8-a92b884984db"}},"name":"ROOT-26","size":21474836480,"volumeId":26,"vmName":"i-2-26-QA","accountId":2,"format":"VHD","id":26,"deviceId":0,"hypervisorType":"XenServer"}},"executeInSequence":false,"options":{},"wait":0}}] }
> 2014-05-14 11:59:14,864 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514305: Executing: { Cmd , MgmtId: 1, via: 2(Rack1Pod1Host22), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"079cc5a8-48a4-4a80-8960-a8a57fea2e76","origUrl":"http://10.147.28.7/templates/builtin/centos56-x86_64.vhd.bz2","uuid":"79f647d6-da5c-11e3-80cb-b51f7904a635","id":5,"format":"VHD","accountId":1,"checksum":"905cec879afd9c9d22ecc8036131a180","hvm":false,"displayText":"CentOS 5.6(64-bit) no GUI (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"6b2f5840-b5f9-3a42-bfd8-a92b884984db","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/jayapal/pri-4.4","port":2049,"url":"NetworkFilesystem://10.147.28.7/export/home/jayapal/pri-4.4/?ROLE=Primary&STOREUUID=6b2f5840-b5f9-3a42-bfd8-a92b884984db"}},"name":"centos56-x86_64-xen","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"b4102c65-8acc-4949-a819-a467f8f8ba1c","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"6b2f5840-b5f9-3a42-bfd8-a92b884984db","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/jayapal/pri-4.4","port":2049,"url":"NetworkFilesystem://10.147.28.7/export/home/jayapal/pri-4.4/?ROLE=Primary&STOREUUID=6b2f5840-b5f9-3a42-bfd8-a92b884984db"}},"name":"ROOT-26","size":21474836480,"volumeId":26,"vmName":"i-2-26-QA","accountId":2,"format":"VHD","id":26,"deviceId":0,"hypervisorType":"XenServer"}},"executeInSequence":false,"options":{},"wait":0}}] }
> 2014-05-14 11:59:14,864 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-67:ctx-71de6ced) Seq 2-6485183463413514305: Executing request
> 2014-05-14 11:59:16,014 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Resetting hosts suitable for reconnect
> 2014-05-14 11:59:16,015 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Completed resetting hosts suitable for reconnect
> 2014-05-14 11:59:16,015 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Acquiring hosts for clusters already owned by this management server
> 2014-05-14 11:59:16,017 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Completed acquiring hosts for clusters already owned by this management server
> 2014-05-14 11:59:16,017 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Acquiring hosts for clusters not owned by any management server
> 2014-05-14 11:59:16,017 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-a0aca381) Completed acquiring hosts for clusters not owned by any management server
> 2014-05-14 11:59:16,174 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-17:null) Ping from 3
> 2014-05-14 11:59:16,174 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-18:null) Ping from 4
> 2014-05-14 11:59:17,427 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-8f3f16de) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048957425
> 2014-05-14 11:59:17,442 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-8f3f16de ctx-0a602791) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:17,446 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-8f3f16de ctx-0a602791) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048957425
> 2014-05-14 11:59:20,428 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-3bbdc86b) ===START=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048960425
> 2014-05-14 11:59:20,443 DEBUG [o.a.c.i.RoleBasedEntityAccessChecker] (867392383@qtp-1655170479-7:ctx-3bbdc86b ctx-3ce93690) IAM access check for 2-null-null-DomainCapability from cache: false
> 2014-05-14 11:59:20,447 DEBUG [c.c.a.ApiServlet] (867392383@qtp-1655170479-7:ctx-3bbdc86b ctx-3ce93690) ===END=== 10.252.192.19 -- GET command=queryAsyncJobResult&jobId=01dddbe4-796d-4230-b96c-b6f9cc724a5d&response=json&sessionkey=Li3x1YB3%2BDUERGcuaZ9plLrGSZc%3D&_=1400048960425
> 2014-05-14 11:59:21,295 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-67:ctx-71de6ced) Succesfully created VDI: Uuid = 9fdaf9e4-3b87-4cf4-b811-1e1e57aa73cf
> 2014-05-14 11:59:21,296 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-67:ctx-71de6ced) Seq 2-6485183463413514305: Response Received:
> 2014-05-14 11:59:21,296 DEBUG [c.c.a.t.Request] (DirectAgent-67:ctx-71de6ced) Seq 2-6485183463413514305: Processing: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"name":"ROOT-26","size":21474836480,"path":"9fdaf9e4-3b87-4cf4-b811-1e1e57aa73cf","accountId":0,"id":0}},"result":true,"wait":0}}] }
> 2014-05-14 11:59:21,296 DEBUG [c.c.a.t.Request] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Seq 2-6485183463413514305: Received: { Ans: , MgmtId: 1, via: 2, Ver: v1, Flags: 10, { CopyCmdAnswer } }
> 2014-05-14 11:59:21,327 ERROR [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-11:job-178/job-179 ctx-d65ab318) Failed to start instance VM[User|i-2-26-QA]
> java.lang.NullPointerException
> at com.cloud.hypervisor.XenServerGuru.implement(XenServerGuru.java:96)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:995)
> at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5180)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5325)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:496)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:453)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
--
This message was sent by Atlassian JIRA
(v6.2#6252)