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