????????????????
 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}}] }

回复