[
https://issues.apache.org/jira/browse/CLOUDSTACK-6661?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13998617#comment-13998617
]
Sailaja Mada commented on CLOUDSTACK-6661:
------------------------------------------
This issue is reproducible consistently with Windows 2012 R2 64 bit instance.
2014-05-15 13:14:12,066 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) Seq 1-3522377858557149379:
Sending { Cmd , MgmtId: 55355881446856, via: 1(cldstk-R720-10), Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"d75694b2-d7f4-48a2-8bfc-3aafd073c005","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bd93a9ac-e84c-36db-b4fe-80d406208de5","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.101","path":"/Sailaja/vgpups1","port":2049,"url":"NetworkFilesystem://10.102.192.101/Sailaja/vgpups1/?ROLE=Primary&STOREUUID=bd93a9ac-e84c-36db-b4fe-80d406208de5"}},"name":"ROOT-6","size":21474836480,"volumeId":6,"vmName":"i-3-6-VM","accountId":3,"format":"VHD","id":6,"deviceId":0,"hypervisorType":"XenServer"}},"wait":0}}]
}
2014-05-15 13:14:12,066 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) Seq 1-3522377858557149379:
Executing: { Cmd , MgmtId: 55355881446856, via: 1(cldstk-R720-10), Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"d75694b2-d7f4-48a2-8bfc-3aafd073c005","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"bd93a9ac-e84c-36db-b4fe-80d406208de5","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.101","path":"/Sailaja/vgpups1","port":2049,"url":"NetworkFilesystem://10.102.192.101/Sailaja/vgpups1/?ROLE=Primary&STOREUUID=bd93a9ac-e84c-36db-b4fe-80d406208de5"}},"name":"ROOT-6","size":21474836480,"volumeId":6,"vmName":"i-3-6-VM","accountId":3,"format":"VHD","id":6,"deviceId":0,"hypervisorType":"XenServer"}},"wait":0}}]
}
2014-05-15 13:14:12,067 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-17:ctx-94d64fbb) Seq 1-3522377858557149379: Executing request
2014-05-15 13:14:12,091 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-17:ctx-94d64fbb) SR retrieved for
bd93a9ac-e84c-36db-b4fe-80d406208de5
2014-05-15 13:14:12,098 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-17:ctx-94d64fbb) Checking bd93a9ac-e84c-36db-b4fe-80d406208de5 or
SR f60239ff-6b5e-c627-4bef-aaa0999ca70b on
XS[4861cedc-f7fc-40fc-a330-9b57be4cd387-10.102.192.10]
2014-05-15 13:14:12,906 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-17:ctx-94d64fbb) Seq 1-3522377858557149379: Response Received:
2014-05-15 13:14:12,907 DEBUG [c.c.a.t.Request] (DirectAgent-17:ctx-94d64fbb)
Seq 1-3522377858557149379: Processing: { Ans: , MgmtId: 55355881446856, via:
1, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"name":"ROOT-6","size":21474836480,"path":"746b1abf-e304-49c6-813e-14b8058e8147","accountId":0,"id":0}},"result":true,"wait":0}}]
}
2014-05-15 13:14:12,907 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) Seq 1-3522377858557149379:
Received: { Ans: , MgmtId: 55355881446856, via: 1, Ver: v1, Flags: 10, {
CreateObjectAnswer } }
2014-05-15 13:14:12,975 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) template 204 is already in
store:1, type:Image
2014-05-15 13:14:12,990 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) Failed to start instance
VM[User|i-3-6-VM]
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)
2014-05-15 13:14:12,997 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-5:job-26/job-27 ctx-974ae1d9) Cleaning up resources for the
vm VM[User|i-3-6-VM] in Starting state
> 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
> 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)
