OSDir


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Cannot create Instance in Isolated VPC...Error - Insufficient capacity...


Hi
I have been struggling with this for many days.
I can create Instances on a Shared Network, but when I create Instances in
an Isolated VPC network I get the following error as shown in the logs
below.
Any help would be greatly appreciated.  I am stuck on this and cannot
proceed.

I have bolded the exceptions as well.

Thank You


Mukarram Syed


2018-06-25 03:08:17,547 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Host: 1 can access pool: 1
2018-06-25 03:08:17,548 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Found a potential host id: 1 name: acskvm1-cc and
associated storage pools for this VM
2018-06-25 03:08:17,548 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(36|ROOT-->Pool(1))]
2018-06-25 03:08:17,548 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Deployment found  - P0=VM[User|i-2-24-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(36|ROOT-->Pool(1))]
2018-06-25 03:08:17,555 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 1 host id before
state transition: null
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Hosts's actual total CPU: 123200 and CPU after applying
overprovisioning: 123200
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) We are allocating VM, increasing the used capacity of this
host:1
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Current Used CPU: 4000 , Free CPU:119200 ,Requested CPU:
500
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Current Used RAM: 4026531840 , Free RAM:405812969472
,Requested RAM: 536870912
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) CPU STATS after allocation: for host: 1, old used: 4000,
old reserved: 0, actual total: 123200, total with overprovisioning: 123200;
new used:4500, reserved:0; requested cpu:500,alloc_from_last:false
2018-06-25 03:08:17,558 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) RAM STATS after allocation: for host: 1, old used:
4026531840, old reserved: 0, total: 409839501312; new used: 4563402752,
reserved: 0; requested mem: 536870912,alloc_from_last:false
2018-06-25 03:08:17,564 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Lock is acquired for network id 216 as a part of network
implement
2018-06-25 03:08:17,564 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Asking ExternalGuestNetworkGuru to implement
Ntwk[216|Guest|11]
2018-06-25 03:08:17,571 DEBUG [c.c.u.d.T.Transaction]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Rolling back the transaction: Time = 0 Name =
 Work-Job-Executor-82; called by
-TransactionLegacy.rollback:889-TransactionLegacy.removeUpTo:832-TransactionLegacy.close:656-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy84.take:-1-DataCenterDaoImpl.allocateVnet:212-GeneratedMethodAccessor457.invoke:-1-DelegatingMethodAccessorImpl.invoke:43
2018-06-25 03:08:17,571 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Cleaning up because we're unable to implement the network
Ntwk[216|Guest|11]
2018-06-25 03:08:17,578 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Lock is acquired for network Ntwk[216|Guest|11] as a part
of network shutdown
2018-06-25 03:08:17,581 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing 0 port forwarding rules for network id=216 as a
part of shutdownNetworkRules
2018-06-25 03:08:17,581 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:17,582 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing 0 static nat rules for network id=216 as a part
of shutdownNetworkRules
2018-06-25 03:08:17,582 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:17,582 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Revoking 0 Public load balancing rules for network id=216
2018-06-25 03:08:17,582 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no Load Balancing Rules to forward to the
network elements
2018-06-25 03:08:17,583 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Revoking 0 Internal load balancing rules for network id=216
2018-06-25 03:08:17,583 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no Load Balancing Rules to forward to the
network elements
2018-06-25 03:08:17,583 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing 0 firewall ingress rules for network id=216 as a
part of shutdownNetworkRules
2018-06-25 03:08:17,583 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:17,584 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing 0 firewall egress rules for network id=216 as a
part of shutdownNetworkRules
2018-06-25 03:08:17,584 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:17,584 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing Network ACL Items for network id=216 as a part
of shutdownNetworkRules
2018-06-25 03:08:17,586 DEBUG [c.c.n.v.NetworkACLManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Releasing 2 Network ACL Items for network id=216
2018-06-25 03:08:17,587 DEBUG [c.c.n.v.NetworkACLManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Applying NetworkACL for network: 216 with Network ACL
service provider
2018-06-25 03:08:17,589 DEBUG [c.c.n.e.VpcVirtualRouterElement]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Virtual router elemnt doesn't need to apply firewall rules
on the backend; virtual router doesn't exist in the network 216
2018-06-25 03:08:17,590 DEBUG [c.c.n.v.NetworkACLManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Successfully released Network ACLs for network id=216 and
# of rules now = 2
2018-06-25 03:08:17,590 DEBUG [c.c.n.r.RulesManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Found 0 static nat rules to apply for network id 216
2018-06-25 03:08:17,592 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Sending network shutdown to VpcVirtualRouter
2018-06-25 03:08:17,593 DEBUG [c.c.n.e.VpcVirtualRouterElement]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Router VM[DomainRouter|r-22-VM] is not a part the network
Ntwk[216|Guest|11]
2018-06-25 03:08:17,593 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Network id=216 is shutdown successfully, cleaning up
corresponding resources now.
2018-06-25 03:08:17,600 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Lock is released for network Ntwk[216|Guest|11] as a part
of network shutdown
2018-06-25 03:08:17,602 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Lock is released for network id 216 as a part of network
implement
2018-06-25 03:08:17,602 INFO  [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-82:ctx-*6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Insufficient capacity*
*com.cloud.exception.InsufficientVirtualNetworkCapacityException: Unable to
allocate vnet as a part of network Ntwk[216|Guest|11] implement
Scope=interface com.cloud.dc.DataCenter; id=1*
* at
com.cloud.network.guru.GuestNetworkGuru.allocateVnet(GuestNetworkGuru.java:291)*
* at
com.cloud.network.guru.GuestNetworkGuru.implement(GuestNetworkGuru.java:320)*
* at
com.cloud.network.guru.ExternalGuestNetworkGuru.implement(ExternalGuestNetworkGuru.java:132)*
* at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1059)*
* at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:998)*
* at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1566)*
* at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1108)*
* at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4927)*
* at sun.reflect.GeneratedMethodAccessor419.invoke(Unknown Source)*
* at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)*
* at java.lang.reflect.Method.invoke(Method.java:498)*
* at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)*
* at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5090)*
* at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)*
* at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)*
* 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:529)*
* at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)*
* at java.util.concurrent.FutureTask.run(FutureTask.java:266)*
* at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)*
* at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)*
* at java.lang.Thread.run(Thread.java:748)*
2018-06-25 03:08:17,605 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Cleaning up resources for the vm VM[User|i-2-24-VM] in
Starting state
2018-06-25 03:08:17,607 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Seq 1-736338539075076916: Sending  { Cmd , MgmtId:
88422863436420, via: 1(acskvm1-cc), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-24-VM","executeInSequence":false,"wait":0}}]
}
2018-06-25 03:08:17,725 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-4a3611d1) (logid:f12ae9af) ===START===  10.192.160.145
-- GET
 command=queryAsyncJobResult&jobId=6bb94f13-3283-4995-b7c4-45818204f55b&response=json&_=1529896097703
2018-06-25 03:08:17,727 DEBUG [c.c.a.ApiServer]
(qtp788117692-12:ctx-4a3611d1 ctx-68fb1a44) (logid:f12ae9af) CIDRs from
which account 'Acct[70491db9-7801-11e8-af03-506b8d5d7a84-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2018-06-25 03:08:17,733 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-4a3611d1 ctx-68fb1a44) (logid:f12ae9af) ===END===
 10.192.160.145 -- GET
 command=queryAsyncJobResult&jobId=6bb94f13-3283-4995-b7c4-45818204f55b&response=json&_=1529896097703
2018-06-25 03:08:17,803 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-13:null) (logid:) Seq 1-736338539075076916:
Processing:  { Ans: , MgmtId: 88422863436420, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2018-06-25 03:08:17,803 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Seq 1-736338539075076916: Received:  { Ans: , MgmtId:
88422863436420, via: 1(acskvm1-cc), Ver: v1, Flags: 10, { StopAnswer } }
2018-06-25 03:08:17,810 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Successfully released network resources for the vm
VM[User|i-2-24-VM]
2018-06-25 03:08:17,810 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Successfully cleanued up resources for the vm
VM[User|i-2-24-VM] in Starting state
2018-06-25 03:08:17,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) DeploymentPlanner allocation algorithm: null
2018-06-25 03:08:17,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2018-06-25 03:08:17,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Is ROOT volume READY (pool already allocated)?: No
2018-06-25 03:08:17,815 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) DeploymentPlan has host_id specified, choosing this host
and making no checks on this host: 1
2018-06-25 03:08:17,815 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) The specified host is in avoid set
2018-06-25 03:08:17,815 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Cannot deploy to specified host, returning.
2018-06-25 03:08:17,823 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) VM state transitted from :Starting to Stopped with event:
OperationFailedvm's original host id: null new host id: null host id before
state transition: 1
2018-06-25 03:08:17,826 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Hosts's actual total CPU: 123200 and CPU after applying
overprovisioning: 123200
2018-06-25 03:08:17,826 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Hosts's actual total RAM: 409839501312 and RAM after
applying overprovisioning: 409839501312
2018-06-25 03:08:17,826 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) release cpu from host: 1, old used: 4500,reserved: 0,
actual total: 123200, total with overprovisioning: 123200; new used:
4000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2018-06-25 03:08:17,826 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) release mem from host: 1, old used: 4563402752,reserved:
0, total: 409839501312; new used: 4026531840,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-06-25 03:08:17,833 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-24-VM]Scope=interface com.cloud.dc.DataCenter;
id=1
2018-06-25 03:08:17,833 INFO  [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174 ctx-60e9ada3)
(logid:00fe5d3e) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-24-VM]Scope=interface com.cloud.dc.DataCenter;
id=1
2018-06-25 03:08:17,833 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 24, job origin: 173
2018-06-25 03:08:17,833 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Unable
to complete AsyncJobVO {id:174, userId: 2, accountId: 2, instanceType:
null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAGHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 88422863436420, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Jun 25 03:08:15 GMT 2018}, job
origin:173
*com.cloud.exception.InsufficientServerCapacityException: Unable to create
a deployment for VM[User|i-2-24-VM]Scope=interface com.cloud.dc.DataCenter;
id=1*
* at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1072)*
* at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4927)*
* at sun.reflect.GeneratedMethodAccessor419.invoke(Unknown Source)*
* at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)*
* at java.lang.reflect.Method.invoke(Method.java:498)*
* at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)*
* at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5090)*
* at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)*
* at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:581)*
* 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:529)*
* at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)*
* at java.util.concurrent.FutureTask.run(FutureTask.java:266)*
* at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)*
* at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)*
* at java.lang.Thread.run(Thread.java:748)*
2018-06-25 03:08:17,833 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e)
Complete async job-174, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA0VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNW1VzZXJ8aS0yLTI0LVZNXXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIABEkACmxpbmVOdW1iZXJMAA5kZWNsYXJpbmdDbGFzc3EAfgAKTAAIZmlsZU5hbWVxAH4ACkwACm1ldGhvZE5hbWVxAH4ACnhwAAAEMHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHNxAH4AEQAAEz9xAH4AE3EAfgAUcQB-ABVzcQB-ABH_____dAAmc3VuLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I0MTlwdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AGXNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAZc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQAAE-JxAH4AE3EAfgAUcQB-ACNzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAJFdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADN0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQB-ADZxAH4AM3QADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAvcQB-ADBzcQB-ABEAAAIRcQB-ACpxAH4AK3EAfgAwc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA0c3EAfgARAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AMHNxAH4AEQAABH10ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAnB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEVxAH4AMHNxAH4AEQAAAux0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AMHNyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFF4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFAAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFMAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcmNB93O_lXyzAgAAeHAA
2018-06-25 03:08:17,834 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e)
Publish async job-174 complete on message bus
2018-06-25 03:08:17,834 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Wake
up jobs related to job-174
2018-06-25 03:08:17,834 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Update
db status for job-174
2018-06-25 03:08:17,835 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Wake
up jobs joined with job-174 and disjoin all subjobs created from job- 174
2018-06-25 03:08:17,838 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Done
executing com.cloud.vm.VmWorkStart for job-174
2018-06-25 03:08:17,839 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-82:ctx-6bdbfdde job-173/job-174) (logid:00fe5d3e) Remove
job-174 from job monitoring
2018-06-25 03:08:17,850 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-88:ctx-eb3449a8 job-173 ctx-35b0cc91) (logid:00fe5d3e)
Sync job-175 execution on object VmWorkJobQueue.24
2018-06-25 03:08:18,546 DEBUG [c.c.a.ApiServlet]
(qtp788117692-14:ctx-c5b7465f) (logid:f63aae82) ===START===  10.192.160.145
-- GET
 command=queryAsyncJobResult&jobId=00fe5d3e-68b6-46fd-bae2-57292a3925f1&response=json&_=1529896098522
2018-06-25 03:08:18,548 DEBUG [c.c.a.ApiServer]
(qtp788117692-14:ctx-c5b7465f ctx-bf80f34d) (logid:f63aae82) CIDRs from
which account 'Acct[70491db9-7801-11e8-af03-506b8d5d7a84-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2018-06-25 03:08:18,556 DEBUG [c.c.a.ApiServlet]
(qtp788117692-14:ctx-c5b7465f ctx-bf80f34d) (logid:f63aae82) ===END===
 10.192.160.145 -- GET
 command=queryAsyncJobResult&jobId=00fe5d3e-68b6-46fd-bae2-57292a3925f1&response=json&_=1529896098522
2018-06-25 03:08:19,393 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-4b4f8b69) (logid:bf56148a) ===START===  10.192.160.145
-- GET
 command=queryAsyncJobResult&jobId=b399aad4-d703-423a-b958-eb787898e652&response=json&_=1529896099371
2018-06-25 03:08:19,395 DEBUG [c.c.a.ApiServer]
(qtp788117692-12:ctx-4b4f8b69 ctx-4022ea7f) (logid:bf56148a) CIDRs from
which account 'Acct[70491db9-7801-11e8-af03-506b8d5d7a84-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2018-06-25 03:08:19,403 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-4b4f8b69 ctx-4022ea7f) (logid:bf56148a) ===END===
 10.192.160.145 -- GET
 command=queryAsyncJobResult&jobId=b399aad4-d703-423a-b958-eb787898e652&response=json&_=1529896099371
2018-06-25 03:08:19,511 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-52a1f8fe) (logid:c8c20d5a) Execute sync-queue
item: SyncQueueItemVO {id:83, queueId: 82, contentType: AsyncJob,
contentId: 175, lastProcessMsid: 88422863436420, lastprocessNumber: 2,
lastProcessTime: Mon Jun 25 03:08:19 GMT 2018, created: Mon Jun 25 03:08:17
GMT 2018}
2018-06-25 03:08:19,512 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-52a1f8fe) (logid:c8c20d5a) Schedule queued
job-175
2018-06-25 03:08:19,516 INFO  [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175) (logid:5d6f7d95) Add
job-175 into job monitoring
2018-06-25 03:08:19,521 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175) (logid:00fe5d3e)
Executing AsyncJobVO {id:175, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAGHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 88422863436420, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Jun 25 03:08:17 GMT 2018}
2018-06-25 03:08:19,521 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175) (logid:00fe5d3e) Run VM
work job: com.cloud.vm.VmWorkStart for VM 24, job origin: 173
2018-06-25 03:08:19,522 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":24,"handlerName":"VirtualMachineManagerImpl"}
2018-06-25 03:08:19,526 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) VM state transitted from :Stopped to Starting with event:
StartRequestedvm's original host id: null new host id: null host id before
state transition: null
2018-06-25 03:08:19,526 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Successfully transitioned to start state for
VM[User|i-2-24-VM] reservation id = 51000aca-8ad8-40c3-9370-a8f1cffda88c
2018-06-25 03:08:19,528 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Deploy avoids pods: null, clusters: null, hosts: null
2018-06-25 03:08:19,533 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) DeploymentPlanner allocation algorithm: null
2018-06-25 03:08:19,533 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2018-06-25 03:08:19,533 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Is ROOT volume READY (pool already allocated)?: No
2018-06-25 03:08:19,537 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Deploy avoids pods: [], clusters: [], hosts: []
2018-06-25 03:08:19,538 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Searching resources only under specified Pod: 1
2018-06-25 03:08:19,538 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this Pod: 1
2018-06-25 03:08:19,540 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Removing from the clusterId list these clusters from avoid
set: []
2018-06-25 03:08:19,544 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking resources in Cluster: 1 under Pod: 1
2018-06-25 03:08:19,544 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Looking for hosts in dc: 1
 pod:1  cluster:1
2018-06-25 03:08:19,546 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) FirstFitAllocator has 1 hosts to
check for allocation: [Host[-1-Routing]]
2018-06-25 03:08:19,548 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Found 1 hosts for allocation
after prioritization: [Host[-1-Routing]]
2018-06-25 03:08:19,548 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Looking for speed=500Mhz, Ram=512
2018-06-25 03:08:19,552 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Host: 1 has cpu capability
(cpu:56, speed:2200) to support requested CPU: 1 and requested speed: 500
2018-06-25 03:08:19,552 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Checking if host: 1 has enough
capacity for requested CPU: 500 and requested RAM: 536870912 ,
cpuOverprovisioningFactor: 1.0
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Hosts's actual total CPU: 123200
and CPU after applying overprovisioning: 123200
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Free CPU: 119200 , Requested
CPU: 500
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Free RAM: 405812969472 ,
Requested RAM: 536870912
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Host has enough CPU and RAM
available
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) STATS: Can alloc CPU from host:
1, used: 4000, reserved: 0, actual total: 123200, total with
overprovisioning: 123200; requested cpu:500,alloc_from_last_host?:false
,considerReservedCapacity?: true
2018-06-25 03:08:19,553 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) STATS: Can alloc MEM from host:
1, used: 4026531840, reserved: 0, total: 409839501312; requested mem:
536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2018-06-25 03:08:19,553 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Found a suitable host, adding to
list: 1
2018-06-25 03:08:19,553 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819
FirstFitRoutingAllocator) (logid:00fe5d3e) Host Allocator returning 1
suitable hosts
2018-06-25 03:08:19,555 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking suitable pools for volume (Id, Type): (36,ROOT)
2018-06-25 03:08:19,555 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) We need to allocate new storagepool for this volume
2018-06-25 03:08:19,555 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Calling StoragePoolAllocators to find suitable pools
2018-06-25 03:08:19,555 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) LocalStoragePoolAllocator trying to find storage pool to
fit the vm
2018-06-25 03:08:19,555 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) ClusterScopeStoragePoolAllocator looking for storage pool
2018-06-25 03:08:19,555 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Looking for pools in dc: 1  pod:1  cluster:1. Disabled
pools will be ignored.
2018-06-25 03:08:19,556 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2018-06-25 03:08:19,557 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking if storage pool is suitable, name: null ,poolId: 1
2018-06-25 03:08:19,558 INFO  [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Storage pool null (1) does not supply IOPS capacity,
assuming enough capacity
2018-06-25 03:08:19,559 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking pool 1 for storage, totalSize: 2147483648000,
usedBytes: 3618635776, usedPct: 0.00168505859375, disable threshold: 0.85
2018-06-25 03:08:19,559 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Destination pool id: 1
2018-06-25 03:08:19,567 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) pool id for the volume with id: 36 is null
2018-06-25 03:08:19,568 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Found storage pool Primary of type NetworkFilesystem with
overprovisioning factor 2
2018-06-25 03:08:19,568 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Total over provisioned capacity calculated is 2 *
2147483648000
2018-06-25 03:08:19,568 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Total capacity of the pool Primary id: 1 is 4294967296000
2018-06-25 03:08:19,568 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking pool: 1 for volume allocation
[Vol[36|vm=24|ROOT]], maxSize : 4294967296000, totalAllocatedSize :
61078866432, askingSize : 0, allocated disable threshold: 0.85
2018-06-25 03:08:19,568 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) ClusterScopeStoragePoolAllocator returning 1 suitable
storage pools
2018-06-25 03:08:19,568 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2018-06-25 03:08:19,568 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Checking if host: 1 can access any suitable storage pool
for volume: ROOT
2018-06-25 03:08:19,569 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Host: 1 can access pool: 1
2018-06-25 03:08:19,569 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Found a potential host id: 1 name: acskvm1-cc and
associated storage pools for this VM
2018-06-25 03:08:19,569 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(36|ROOT-->Pool(1))]
2018-06-25 03:08:19,569 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Deployment found  - P0=VM[User|i-2-24-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(36|ROOT-->Pool(1))]
2018-06-25 03:08:19,576 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 1 host id before
state transition: null
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Hosts's actual total CPU: 123200 and CPU after applying
overprovisioning: 123200
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) We are allocating VM, increasing the used capacity of this
host:1
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Current Used CPU: 4000 , Free CPU:119200 ,Requested CPU:
500
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Current Used RAM: 4026531840 , Free RAM:405812969472
,Requested RAM: 536870912
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) CPU STATS after allocation: for host: 1, old used: 4000,
old reserved: 0, actual total: 123200, total with overprovisioning: 123200;
new used:4500, reserved:0; requested cpu:500,alloc_from_last:false
2018-06-25 03:08:19,579 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) RAM STATS after allocation: for host: 1, old used:
4026531840, old reserved: 0, total: 409839501312; new used: 4563402752,
reserved: 0; requested mem: 536870912,alloc_from_last:false
2018-06-25 03:08:19,585 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Lock is acquired for network id 216 as a part of network
implement
2018-06-25 03:08:19,585 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Asking ExternalGuestNetworkGuru to implement
Ntwk[216|Guest|11]
2018-06-25 03:08:19,591 DEBUG [c.c.u.d.T.Transaction]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Rolling back the transaction: Time = 1 Name =
 Work-Job-Executor-83; called by
-TransactionLegacy.rollback:889-TransactionLegacy.removeUpTo:832-TransactionLegacy.close:656-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy84.take:-1-DataCenterDaoImpl.allocateVnet:212-GeneratedMethodAccessor457.invoke:-1-DelegatingMethodAccessorImpl.invoke:43
2018-06-25 03:08:19,591 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Cleaning up because we're unable to implement the network
Ntwk[216|Guest|11]
2018-06-25 03:08:19,597 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Lock is acquired for network Ntwk[216|Guest|11] as a part
of network shutdown
2018-06-25 03:08:19,601 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Releasing 0 port forwarding rules for network id=216 as a
part of shutdownNetworkRules
2018-06-25 03:08:19,601 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:19,601 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Releasing 0 static nat rules for network id=216 as a part
of shutdownNetworkRules
2018-06-25 03:08:19,601 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) There are no rules to forward to the network elements
2018-06-25 03:08:19,602 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Revoking 0 Public load balancing rules for network id=216
2018-06-25 03:08:19,602 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) There are no Load Balancing Rules to forward to the
network elements
2018-06-25 03:08:19,602 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Revoking 0 Internal load balancing rules for network id=216
2018-06-25 03:08:19,602 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) There are no Load Balancing Rules to forward to the
network elements
2018-06-25 03:08:19,603 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-83:ctx-136ac8fc job-173/job-175 ctx-e2d74819)
(logid:00fe5d3e) Releasing 0 firewall ingress rules for network id=216 as a
part of shutdownNetworkRules