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