cloudstack-users-cn mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "xool" <170451...@qq.com>
Subject Unable to create a deployment for VM
Date Thu, 06 Nov 2014 08:48:29 GMT
请教以下两个问题
 1.虚拟机关闭后启动失败,UI界面出现以下提示:
Job failed due to exception Unable to create a deployment for VM[User|i-2-7-VM]
 2.创建新虚拟机失败,UI界面出现以下提示:
Unable to create a deployment for VM[User|i-2-19-VM], Please check the affinity groups provided, there may not be sufficient capacity to follow them
 
****出现以上错误时,在“将实例迁移到其他主机”的UI界面可以看到计算机服务器 都是(not suitable)状态。****
****尝试在其他LINUX系统下挂载主存储、辅助存储 都可正常写入 删除。****
 
cloudstack环境:
1.一台cloudstack4.4 服务器 192.168.10.1/24 ;
 2.两台计算机服务器node1 、node2
node1 192.168.10.2/24 内存 6G CPU 4*3.3G ,目前有一台虚拟机(内存 1G CPU 1G)  在上面跑
node2 192.168.10.3/24 内存32G CPU 8*2.5G ,目前有一台虚拟机(内存 1G CPU 1G) 在上面跑
 3.主存储(NFS)、辅助存储(NFS)都在node2上,各1TB空间;
 4.操作系统都是Centos 6.5
  
 以下是服务器的日志文件:
 2014-11-06 14:57:51,098 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 5
2014-11-06 14:57:52,477 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 6-1904: Processing Seq 6-1904:  { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-11-06 14:57:52,490 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) SeqA 6-1904: Sending Seq 6-1904:  { Ans: , MgmtId: 233916160448482, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-06 14:57:56,161 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-b0f5ac29) ===START===  192.168.10.223 -- GET  command=deployVirtualMachine&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&zoneid=af89fee6-74b6-4f43-b971-d7159eb00a4b&templateid=97585d8e-51d5-46c4-b43a-071b69dee618&hypervisor=KVM&serviceofferingid=c756d147-2e19-49bb-a0d5-38e009b4b8fa&diskofferingid=bfb3caf6-0306-479b-b819-f54238e533e9&affinitygroupids=67670c73-a76f-49b1-91db-7150520376d7&securitygroupids=63406080-6008-11e4-8bad-51d63eb3c8ce&displayname=VPNSER&name=VPNSER&_=1415257074042
2014-11-06 14:57:56,221 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocating in the DB for vm
2014-11-06 14:57:56,230 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocating entries for VM: VM[User|i-2-20-VM]
2014-11-06 14:57:56,230 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocating nics for VM[User|i-2-20-VM]
2014-11-06 14:57:56,231 DEBUG [o.a.c.e.o.NetworkOrchestrator] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocating nic for vm VM[User|i-2-20-VM] in network Ntwk[f0420e4e-f018-409a-ad21-606a77170f80|Guest|6] with requested profile NicProfile[0-0-null-null-null
2014-11-06 14:57:56,237 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocating disks for VM[User|i-2-20-VM]
2014-11-06 14:57:56,244 DEBUG [c.c.v.VirtualMachineManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Allocation completed for VM: VM[User|i-2-20-VM]
2014-11-06 14:57:56,244 DEBUG [c.c.v.UserVmManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) Successfully allocated DB entry for VM[User|i-2-20-VM]
2014-11-06 14:57:56,391 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) submit async job-211, details: AsyncJobVO {id:211, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 20, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"sessionkey":"NZGSe2vvRNJmVzxlhqoSjOoMIOw\u003d","serviceofferingid":"c756d147-2e19-49bb-a0d5-38e009b4b8fa","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"af89fee6-74b6-4f43-b971-d7159eb00a4b","affinitygroupids":"67670c73-a76f-49b1-91db-7150520376d7","httpmethod":"GET","templateid":"97585d8e-51d5-46c4-b43a-071b69dee618","securitygroupids":"63406080-6008-11e4-8bad-51d63eb3c8ce","id":"20","response":"json","ctxDetails":"{\"org.apache.cloudstack.affinity.AffinityGroup\":\"67670c73-a76f-49b1-91db-7150520376d7\",\"com.cloud.template.VirtualMachineTemplate\":\"97585d8e-51d5-46c4-b43a-071b69dee618\",\"com.cloud.vm.VirtualMachine\":\"c76dba75-5d67-40d2-8eec-b31825e1b849\",\"com.cloud.network.security.SecurityGroup\":\"63406080-6008-11e4-8bad-51d63eb3c8ce\",\"com.cloud.offering.DiskOffering\":\"bfb3caf6-0306-479b-b819-f54238e533e9\",\"com.cloud.dc.DataCenter\":\"af89fee6-74b6-4f43-b971-d7159eb00a4b\",\"com.cloud.offering.ServiceOffering\":\"c756d147-2e19-49bb-a0d5-38e009b4b8fa\"}","hypervisor":"KVM","name":"VPNSER","_":"1415257074042","uuid":"c76dba75-5d67-40d2-8eec-b31825e1b849","ctxAccountId":"2","diskofferingid":"bfb3caf6-0306-479b-b819-f54238e533e9","ctxStartEventId":"385","displayname":"VPNSER"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-06 14:57:56,392 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-31:ctx-ae6016e8 job-211) Add job-211 into job monitoring
2014-11-06 14:57:56,392 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211) Executing AsyncJobVO {id:211, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 20, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"sessionkey":"NZGSe2vvRNJmVzxlhqoSjOoMIOw\u003d","serviceofferingid":"c756d147-2e19-49bb-a0d5-38e009b4b8fa","cmdEventType":"VM.CREATE","ctxUserId":"2","zoneid":"af89fee6-74b6-4f43-b971-d7159eb00a4b","affinitygroupids":"67670c73-a76f-49b1-91db-7150520376d7","httpmethod":"GET","templateid":"97585d8e-51d5-46c4-b43a-071b69dee618","securitygroupids":"63406080-6008-11e4-8bad-51d63eb3c8ce","id":"20","response":"json","ctxDetails":"{\"org.apache.cloudstack.affinity.AffinityGroup\":\"67670c73-a76f-49b1-91db-7150520376d7\",\"com.cloud.template.VirtualMachineTemplate\":\"97585d8e-51d5-46c4-b43a-071b69dee618\",\"com.cloud.vm.VirtualMachine\":\"c76dba75-5d67-40d2-8eec-b31825e1b849\",\"com.cloud.network.security.SecurityGroup\":\"63406080-6008-11e4-8bad-51d63eb3c8ce\",\"com.cloud.offering.DiskOffering\":\"bfb3caf6-0306-479b-b819-f54238e533e9\",\"com.cloud.dc.DataCenter\":\"af89fee6-74b6-4f43-b971-d7159eb00a4b\",\"com.cloud.offering.ServiceOffering\":\"c756d147-2e19-49bb-a0d5-38e009b4b8fa\"}","hypervisor":"KVM","name":"VPNSER","_":"1415257074042","uuid":"c76dba75-5d67-40d2-8eec-b31825e1b849","ctxAccountId":"2","diskofferingid":"bfb3caf6-0306-479b-b819-f54238e533e9","ctxStartEventId":"385","displayname":"VPNSER"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-06 14:57:56,392 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-b0f5ac29 ctx-68cde18c) ===END===  192.168.10.223 -- GET  command=deployVirtualMachine&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&zoneid=af89fee6-74b6-4f43-b971-d7159eb00a4b&templateid=97585d8e-51d5-46c4-b43a-071b69dee618&hypervisor=KVM&serviceofferingid=c756d147-2e19-49bb-a0d5-38e009b4b8fa&diskofferingid=bfb3caf6-0306-479b-b819-f54238e533e9&affinitygroupids=67670c73-a76f-49b1-91db-7150520376d7&securitygroupids=63406080-6008-11e4-8bad-51d63eb3c8ce&displayname=VPNSER&name=VPNSER&_=1415257074042
2014-11-06 14:57:56,468 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Processing affinity group SERVERS for VM Id: 20
2014-11-06 14:57:56,470 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Added host 1 to avoid set, since VM 6 is present on the host
2014-11-06 14:57:56,472 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Added host 1 to avoid set, since VM 7 is present on the host, in Stopped state but has reserved capacity
2014-11-06 14:57:56,473 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Added host 4 to avoid set, since VM 18 is present on the host
2014-11-06 14:57:56,478 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Deploy avoids pods: [], clusters: [], hosts: [1, 4]
2014-11-06 14:57:56,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@531b3965
2014-11-06 14:57:56,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 1000, requested ram: 1073741824
2014-11-06 14:57:56,479 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Is ROOT volume READY (pool already allocated)?: No
2014-11-06 14:57:56,479 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Searching all possible resources under this Zone: 1
2014-11-06 14:57:56,480 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2014-11-06 14:57:56,482 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Removing from the clusterId list these clusters from avoid set: []
2014-11-06 14:57:56,488 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Checking resources in Cluster: 1 under Pod: 1
2014-11-06 14:57:56,489 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-11-06 14:57:56,491 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-4-Routing], Host[-1-Routing]]
2014-11-06 14:57:56,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-4-Routing], Host[-1-Routing]]
2014-11-06 14:57:56,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2014-11-06 14:57:56,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Host name: node1.cloud.com, hostId: 4 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:57:56,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Host name: node2.cloud.com, hostId: 1 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:57:56,495 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2014-11-06 14:57:56,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) No suitable hosts found
2014-11-06 14:57:56,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) No suitable hosts found under this Cluster: 1
2014-11-06 14:57:56,496 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-11-06 14:57:56,497 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Searching all possible resources under this Zone: 1
2014-11-06 14:57:56,497 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2014-11-06 14:57:56,499 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Removing from the clusterId list these clusters from avoid set: [1]
2014-11-06 14:57:56,500 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2014-11-06 14:57:56,502 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Destroying vm VM[User|i-2-20-VM] as it failed to create on Host with Id:null
2014-11-06 14:57:56,532 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
2014-11-06 14:57:56,632 WARN  [o.a.c.alerts] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5)  alertType:: 8 // dataCenterId:: 1 // podId:: null // clusterId:: null // message:: Failed to deploy Vm with Id: 20, on Host with Id: null
2014-11-06 14:57:56,725 INFO  [o.a.c.a.c.a.v.DeployVMCmdByAdmin] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2014-11-06 14:57:56,726 INFO  [o.a.c.a.c.a.v.DeployVMCmdByAdmin] (API-Job-Executor-31:ctx-ae6016e8 job-211 ctx-473f08e5) Unable to create a deployment for VM[User|i-2-20-VM], Please check the affinity groups provided, there may not be sufficient capacity to follow them
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-20-VM]Scope=interface com.cloud.dc.DataCenter; id=1
        at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.reserveVirtualMachine(VMEntityManagerImpl.java:214)
        at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.reserve(VirtualMachineEntityImpl.java:200)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3462)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3117)
        at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3105)
        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 org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
        at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy207.startVirtualMachine(Unknown Source)
        at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:48)
        at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:141)
        at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
        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:460)
        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:745)
2014-11-06 14:57:56,727 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211) Complete async job-211, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":533,"errortext":"Unable to create a deployment for VM[User|i-2-20-VM], Please check the affinity groups provided, there may not be sufficient capacity to follow them"}
2014-11-06 14:57:56,758 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-31:ctx-ae6016e8 job-211) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-211
2014-11-06 14:57:56,775 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-31:ctx-ae6016e8 job-211) Remove job-211 from job monitoring
2014-11-06 14:57:56,881 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-7cbc2e5d) VmStatsCollector is running...
2014-11-06 14:57:56,967 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7cbc2e5d) Seq 1-7708192237221314767: Received:  { Ans: , MgmtId: 233916160448482, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-11-06 14:57:57,006 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7cbc2e5d) Seq 4-7863003474412175877: Received:  { Ans: , MgmtId: 233916160448482, via: 4, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-11-06 14:57:57,309 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-e0072ac0) AutoScaling Monitor is running...
2014-11-06 14:57:57,426 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 4
2014-11-06 14:57:57,428 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) Process host VM state report from ping process. host: 4
2014-11-06 14:57:57,431 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) Process VM state report. host: 4, number of records in report: 2
2014-11-06 14:57:57,431 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) VM state report. host: 4, vm id: 16, power state: PowerOn
2014-11-06 14:57:57,433 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) VM power state does not change, skip DB writing. vm id: 16
2014-11-06 14:57:57,433 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) VM state report. host: 4, vm id: 18, power state: PowerOn
2014-11-06 14:57:57,435 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) VM power state does not change, skip DB writing. vm id: 18
2014-11-06 14:57:57,438 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-4:null) Done with process of VM state report. host: 4
2014-11-06 14:57:58,274 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 6
2014-11-06 14:57:59,425 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-250f7310) ===START===  192.168.10.223 -- GET  command=queryAsyncJobResult&jobId=e4195b42-89ab-4eb9-bbde-b76e09817ef8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257077309
2014-11-06 14:57:59,469 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-250f7310 ctx-2fe68821) ===END===  192.168.10.223 -- GET  command=queryAsyncJobResult&jobId=e4195b42-89ab-4eb9-bbde-b76e09817ef8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257077309
2014-11-06 14:57:59,486 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-7f06b49d) ===START===  192.168.10.223 -- GET  command=listVirtualMachines&id=c76dba75-5d67-40d2-8eec-b31825e1b849&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257077361
2014-11-06 14:57:59,507 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-7f06b49d ctx-76ed4bc9) ===END===  192.168.10.223 -- GET  command=listVirtualMachines&id=c76dba75-5d67-40d2-8eec-b31825e1b849&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257077361
2014-11-06 14:58:02,479 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 6-1906: Processing Seq 6-1906:  { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-11-06 14:58:02,492 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 6-1906: Sending Seq 6-1906:  { Ans: , MgmtId: 233916160448482, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-06 14:58:02,608 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-2511b00a) StorageCollector is running...
2014-11-06 14:58:02,670 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-2511b00a) Seq 5-6578633155681452113: Received:  { Ans: , MgmtId: 233916160448482, via: 5, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-06 14:58:02,817 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-2511b00a) Seq 4-7863003474412175878: Received:  { Ans: , MgmtId: 233916160448482, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-06 14:58:04,415 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-187caae8) Zone 1 is ready to launch secondary storage VM
2014-11-06 14:58:04,450 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-eb5b7246) Zone 1 is ready to launch console proxy
2014-11-06 14:58:09,233 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-d2cc069d) ===START===  192.168.10.223 -- GET  command=listZones&id=af89fee6-74b6-4f43-b971-d7159eb00a4b&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087117
2014-11-06 14:58:09,244 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-d2cc069d ctx-83967998) ===END===  192.168.10.223 -- GET  command=listZones&id=af89fee6-74b6-4f43-b971-d7159eb00a4b&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087117
2014-11-06 14:58:09,292 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-d621ef4c) ===START===  192.168.10.223 -- GET  command=listNetworks&id=f0420e4e-f018-409a-ad21-606a77170f80&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087135
2014-11-06 14:58:09,316 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-d621ef4c ctx-7df12977) ===END===  192.168.10.223 -- GET  command=listNetworks&id=f0420e4e-f018-409a-ad21-606a77170f80&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087135
2014-11-06 14:58:09,331 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-0a502a9f) ===START===  192.168.10.223 -- GET  command=listVirtualMachines&id=5b0262e6-d018-4fe0-a60b-a60aba6358a8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087215
2014-11-06 14:58:09,351 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-0a502a9f ctx-bccfd9a5) ===END===  192.168.10.223 -- GET  command=listVirtualMachines&id=5b0262e6-d018-4fe0-a60b-a60aba6358a8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087215
2014-11-06 14:58:09,372 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-185f2e2f) ===START===  192.168.10.223 -- GET  command=listOsTypes&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087257
2014-11-06 14:58:09,505 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-185f2e2f ctx-0fcd115c) ===END===  192.168.10.223 -- GET  command=listOsTypes&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257087257
2014-11-06 14:58:09,749 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-fce86fab) HostStatsCollector is running...
2014-11-06 14:58:10,340 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-fce86fab) Seq 1-7708192237221314768: Received:  { Ans: , MgmtId: 233916160448482, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-06 14:58:10,882 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-fce86fab) Seq 4-7863003474412175879: Received:  { Ans: , MgmtId: 233916160448482, via: 4, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-06 14:58:11,968 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e0036cdb) Found 0 routers to update status.
2014-11-06 14:58:11,969 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-e0036cdb) Found 0 networks to update RvR status.
2014-11-06 14:58:12,480 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 6-1907: Processing Seq 6-1907:  { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-11-06 14:58:12,509 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 6-1907: Sending Seq 6-1907:  { Ans: , MgmtId: 233916160448482, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-06 14:58:12,789 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-c2777e57) ===START===  192.168.10.223 -- GET  command=startVirtualMachine&id=5b0262e6-d018-4fe0-a60b-a60aba6358a8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257090673
2014-11-06 14:58:12,844 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-21:ctx-c2777e57 ctx-924654e9) submit async job-212, details: AsyncJobVO {id:212, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 7, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"response":"json","id":"5b0262e6-d018-4fe0-a60b-a60aba6358a8","sessionkey":"NZGSe2vvRNJmVzxlhqoSjOoMIOw\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"5b0262e6-d018-4fe0-a60b-a60aba6358a8\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1415257090673","uuid":"5b0262e6-d018-4fe0-a60b-a60aba6358a8","ctxAccountId":"2","ctxStartEventId":"389"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-06 14:58:12,845 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-32:ctx-5be5d260 job-212) Add job-212 into job monitoring
2014-11-06 14:58:12,845 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212) Executing AsyncJobVO {id:212, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 7, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"response":"json","id":"5b0262e6-d018-4fe0-a60b-a60aba6358a8","sessionkey":"NZGSe2vvRNJmVzxlhqoSjOoMIOw\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"5b0262e6-d018-4fe0-a60b-a60aba6358a8\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1415257090673","uuid":"5b0262e6-d018-4fe0-a60b-a60aba6358a8","ctxAccountId":"2","ctxStartEventId":"389"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-06 14:58:12,845 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-c2777e57 ctx-924654e9) ===END===  192.168.10.223 -- GET  command=startVirtualMachine&id=5b0262e6-d018-4fe0-a60b-a60aba6358a8&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257090673
2014-11-06 14:58:12,893 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Processing affinity group SERVERS for VM Id: 7
2014-11-06 14:58:12,895 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Added host 1 to avoid set, since VM 6 is present on the host
2014-11-06 14:58:12,896 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Added host 4 to avoid set, since VM 18 is present on the host
2014-11-06 14:58:12,901 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Deploy avoids pods: [], clusters: [], hosts: [1, 4]
2014-11-06 14:58:12,902 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@531b3965
2014-11-06 14:58:12,902 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2014-11-06 14:58:12,902 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-06 14:58:12,902 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) This VM has last host_id specified, trying to choose the same host: 1
2014-11-06 14:58:12,903 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) The last host of this VM is in avoid set
2014-11-06 14:58:12,903 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Cannot choose the last host to deploy this VM
2014-11-06 14:58:12,903 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Searching resources only under specified Cluster: 1
2014-11-06 14:58:12,908 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Checking resources in Cluster: 1 under Pod: 1
2014-11-06 14:58:12,910 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-11-06 14:58:12,912 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-1-Routing], Host[-4-Routing]]
2014-11-06 14:58:12,916 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-1-Routing], Host[-4-Routing]]
2014-11-06 14:58:12,916 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2014-11-06 14:58:12,916 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Host name: node2.cloud.com, hostId: 1 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:58:12,916 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Host name: node1.cloud.com, hostId: 4 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:58:12,916 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2014-11-06 14:58:12,916 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) No suitable hosts found
2014-11-06 14:58:12,916 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) No suitable hosts found under this Cluster: 1
2014-11-06 14:58:12,917 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-11-06 14:58:12,917 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Searching resources only under specified Cluster: 1
2014-11-06 14:58:12,918 DEBUG [c.c.d.FirstFitPlanner] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) The specified cluster is in avoid set, returning.
2014-11-06 14:58:12,925 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Sync job-213 execution on object VmWorkJobQueue.7
2014-11-06 14:58:12,927 WARN  [c.c.u.d.Merovingian2] (API-Job-Executor-32:ctx-5be5d260 job-212 ctx-099bd96f) Was unable to find lock for the key vm_instance7 and thread id 1370073987
2014-11-06 14:58:14,227 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-a9482b96) Execute sync-queue item: SyncQueueItemVO {id:50, queueId: 16, contentType: AsyncJob, contentId: 213, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Thu Nov 06 14:58:12 CST 2014}
2014-11-06 14:58:14,227 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-a9482b96) Schedule queued job-213
2014-11-06 14:58:14,261 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Add job-213 into job monitoring
2014-11-06 14:58:14,261 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Executing AsyncJobVO {id:213, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAB3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Nov 06 14:58:12 CST 2014}
2014-11-06 14:58:14,261 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Run VM work job: com.cloud.vm.VmWorkStart for VM 7, job origin: 212
2014-11-06 14:58:14,262 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":2,"accountId":2,"vmId":7,"handlerName":"VirtualMachineManagerImpl"}
2014-11-06 14:58:14,267 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 1 new host id: null host id before state transition: null
2014-11-06 14:58:14,268 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Successfully transitioned to start state for VM[User|i-2-7-VM] reservation id = 7e29ee01-e323-4364-a012-f7920a4404bc
2014-11-06 14:58:14,295 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Deploy avoids pods: null, clusters: null, hosts: null
2014-11-06 14:58:14,297 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Root volume is ready, need to place VM in volume's cluster
2014-11-06 14:58:14,297 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Vol[9|vm=7|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2014-11-06 14:58:14,299 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Processing affinity group SERVERS for VM Id: 7
2014-11-06 14:58:14,301 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Added host 1 to avoid set, since VM 6 is present on the host
2014-11-06 14:58:14,303 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Added host 4 to avoid set, since VM 18 is present on the host
2014-11-06 14:58:14,309 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Deploy avoids pods: [], clusters: [], hosts: [1, 4]
2014-11-06 14:58:14,310 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@531b3965
2014-11-06 14:58:14,310 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2014-11-06 14:58:14,310 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-06 14:58:14,310 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) This VM has last host_id specified, trying to choose the same host: 1
2014-11-06 14:58:14,311 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) The last host of this VM is in avoid set
2014-11-06 14:58:14,311 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Cannot choose the last host to deploy this VM
2014-11-06 14:58:14,311 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Searching resources only under specified Cluster: 1
2014-11-06 14:58:14,315 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Checking resources in Cluster: 1 under Pod: 1
2014-11-06 14:58:14,315 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
2014-11-06 14:58:14,318 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to check for allocation: [Host[-4-Routing], Host[-1-Routing]]
2014-11-06 14:58:14,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Found 2 hosts for allocation after prioritization: [Host[-4-Routing], Host[-1-Routing]]
2014-11-06 14:58:14,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2014-11-06 14:58:14,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Host name: node1.cloud.com, hostId: 4 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:58:14,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Host name: node2.cloud.com, hostId: 1 is in avoid set, skipping this and trying other available hosts
2014-11-06 14:58:14,322 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2014-11-06 14:58:14,322 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) No suitable hosts found
2014-11-06 14:58:14,322 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) No suitable hosts found under this Cluster: 1
2014-11-06 14:58:14,323 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2014-11-06 14:58:14,323 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Searching resources only under specified Cluster: 1
2014-11-06 14:58:14,324 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) The specified cluster is in avoid set, returning.
2014-11-06 14:58:14,326 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Processing affinity group SERVERS for VM Id: 7
2014-11-06 14:58:14,328 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Added host 1 to avoid set, since VM 6 is present on the host
2014-11-06 14:58:14,329 DEBUG [o.a.c.a.HostAntiAffinityProcessor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Added host 4 to avoid set, since VM 18 is present on the host
2014-11-06 14:58:14,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Deploy avoids pods: [], clusters: [1], hosts: [1, 4]
2014-11-06 14:58:14,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@531b3965
2014-11-06 14:58:14,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 1000, requested ram: 1073741824
2014-11-06 14:58:14,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Is ROOT volume READY (pool already allocated)?: No
2014-11-06 14:58:14,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) This VM has last host_id specified, trying to choose the same host: 1
2014-11-06 14:58:14,336 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) The last host of this VM is in avoid set
2014-11-06 14:58:14,336 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Cannot choose the last host to deploy this VM
2014-11-06 14:58:14,336 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Searching resources only under specified Pod: 1
2014-11-06 14:58:14,336 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2014-11-06 14:58:14,338 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Removing from the clusterId list these clusters from avoid set: [1]
2014-11-06 14:58:14,339 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2014-11-06 14:58:14,384 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 1 new host id: null host id before state transition: null
2014-11-06 14:58:14,402 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2014-11-06 14:58:14,402 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213 ctx-e40e229b) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2014-11-06 14:58:14,402 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 7, job origin: 212
2014-11-06 14:58:14,402 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Unable to complete AsyncJobVO {id:213, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAB3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 233916160448482, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Nov 06 14:58:12 CST 2014}, job origin:212
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947)
        at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
        at sun.reflect.GeneratedMethodAccessor356.invoke(Unknown Source)
        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:5340)
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
        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:460)
        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:745)
2014-11-06 14:58:14,404 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Complete async job-213, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItNy1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2014-11-06 14:58:14,435 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Done executing com.cloud.vm.VmWorkStart for job-213
2014-11-06 14:58:14,504 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Sync queue (16) is currently empty
2014-11-06 14:58:14,504 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-50:ctx-e91af4f6 job-212/job-213) Remove job-213 from job monitoring
2014-11-06 14:58:14,520 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-32:ctx-5be5d260 job-212) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
java.lang.RuntimeException: Job failed due to exception Unable to create a deployment for VM[User|i-2-7-VM]
        at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
        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:460)
        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:745)
2014-11-06 14:58:14,520 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212) Complete async job-212, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Job failed due to exception Unable to create a deployment for VM[User|i-2-7-VM]"}
2014-11-06 14:58:14,535 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-32:ctx-5be5d260 job-212) Done executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-212
2014-11-06 14:58:14,552 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-32:ctx-5be5d260 job-212) Remove job-212 from job monitoring
2014-11-06 14:58:15,894 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-efc39156) ===START===  192.168.10.223 -- GET  command=queryAsyncJobResult&jobId=ec7d6b37-a44c-4164-b713-7be4d2130fa2&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257093779
2014-11-06 14:58:15,938 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-efc39156 ctx-188cbc5d) ===END===  192.168.10.223 -- GET  command=queryAsyncJobResult&jobId=ec7d6b37-a44c-4164-b713-7be4d2130fa2&response=json&sessionkey=NZGSe2vvRNJmVzxlhqoSjOoMIOw%3D&_=1415257093779
2014-11-06 14:58:17,018 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Resetting hosts suitable for reconnect
2014-11-06 14:58:17,019 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Completed resetting hosts suitable for reconnect
2014-11-06 14:58:17,019 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Acquiring hosts for clusters already owned by this management server
2014-11-06 14:58:17,020 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Completed acquiring hosts for clusters already owned by this management server
2014-11-06 14:58:17,020 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Acquiring hosts for clusters not owned by any management server
2014-11-06 14:58:17,020 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-c1138698) Completed acquiring hosts for clusters not owned by any management server
2014-11-06 14:58:22,481 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 6-1908: Processing Seq 6-1908:  { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-11-06 14:58:22,494 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 6-1908: Sending Seq 6-1908:  { Ans: , MgmtId: 233916160448482, via: 6, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
Mime
  • Unnamed multipart/alternative (inline, 8-Bit, 0 bytes)
View raw message