yuanbosoft commented on issue #6761:
URL: https://github.com/apache/cloudstack/issues/6761#issuecomment-1257814638
>
2022-09-26 18:18:01,809 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Unable
to complete AsyncJobVO {id:2167, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAArHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAA
AH3BwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229335791363470, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Mon Sep 26 18:18:00 CST 2022}, job origin:2166
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-172-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
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:5100)
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)
2022-09-26 18:18:01,811 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Complete
async job-2167, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lb
nQgZm9yIFZNW1VzZXJ8aS0yLTE3Mi1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABVzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAABDN0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABNJcQB-ABNxAH4AFHEAfgAVc3EAfgAR_____nQAJHN1bi5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHNxAH4AEQAAAD5xAH4AGHEAfgAZdAAGaW52b2tlc3EAfgARAAAAK3QAKHN1bi5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHHNxAH4AEQAAAfJ0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAcc3EAfgARAAAAa3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnNxAH4AEQAAE-xxAH4AE3EAfgAUcQB-ACZzcQB-ABEAAABmdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0AB
hWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-ABEAAAJFdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgARAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgARAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4AEQAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADZ0AA9jYWxsV2l0aENvbnRleHRzcQB-ABEAAAA1cQB-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0c3EAfgARAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNzcQB-ABEAAAIRcQB-AC1xAH4ALnEAfgAzc3EAfgARAAAB_3QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3c3EAfgARAAABCnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t
0AA9GdXR1cmVUYXNrLmphdmFxAH4AM3NxAH4AEQAABH10ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4AEQAAAnB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3NxAH4AEQAAAux0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAMeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-AFR4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcQB-AFMAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFYAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlcmNB93O_lXyzAgAAeHAA
2022-09-26 18:18:01,812 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Publish
async job-2167 complete on message bus
2022-09-26 18:18:01,812 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Wake up
jobs related to job-2167
2022-09-26 18:18:01,812 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Update
db status for job-2167
2022-09-26 18:18:01,813 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Wake up
jobs joined with job-2167 and disjoin all subjobs created from job- 2167
2022-09-26 18:18:01,817 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Done
executing com.cloud.vm.VmWorkStart for job-2167
2022-09-26 18:18:01,818 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-22:ctx-b0e1978d job-2166/job-2167) (logid:8b427d52) Remove
job-2167 from job monitoring
2022-09-26 18:18:01,830 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52) Sync
job-2168 execution on object VmWorkJobQueue.172
2022-09-26 18:18:02,969 DEBUG [c.c.a.ApiServlet]
(qtp895947612-354:ctx-cd19f97e) (logid:5896197d) ===START=== 192.168.23.201 --
GET
command=queryAsyncJobResult&jobId=8b427d52-e83c-4428-825d-819bea29dfde&response=json&_=1664187140609
2022-09-26 18:18:02,972 DEBUG [c.c.a.ApiServer]
(qtp895947612-354:ctx-cd19f97e ctx-00c708ec) (logid:5896197d) CIDRs from which
account 'Acct[d5ac213c-c4cf-11ea-a36e-d0946660e58e-admin]' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-09-26 18:18:02,983 DEBUG [c.c.a.ApiServlet]
(qtp895947612-354:ctx-cd19f97e ctx-00c708ec) (logid:5896197d) ===END===
192.168.23.201 -- GET
command=queryAsyncJobResult&jobId=8b427d52-e83c-4428-825d-819bea29dfde&response=json&_=1664187140609
2022-09-26 18:18:03,388 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-352a38c5) (logid:6d9a8309) Execute sync-queue
item: SyncQueueItemVO {id:45, queueId: 1077, contentType: AsyncJob, contentId:
2168, lastProcessMsid: 229335791363470, lastprocessNumber: 2, lastProcessTime:
Mon Sep 26 18:18:03 CST 2022, created: Mon Sep 26 18:18:01 CST 2022}
2022-09-26 18:18:03,389 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-352a38c5) (logid:6d9a8309) Schedule queued job-2168
2022-09-26 18:18:03,392 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:9ad0c2fb) Add
job-2168 into job monitoring
2022-09-26 18:18:03,393 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-526a5f34) (logid:a70ab1b6) Begin cleanup expired
async-jobs
2022-09-26 18:18:03,397 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-526a5f34) (logid:a70ab1b6) End cleanup expired
async-jobs
2022-09-26 18:18:03,403 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52)
Executing AsyncJobVO {id:2168, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAArHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3
N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
229335791363470, completeMsid: null, lastUpdated: null, lastPolled: null,
created: Mon Sep 26 18:18:01 CST 2022}
2022-09-26 18:18:03,404 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Run VM
work job: com.cloud.vm.VmWorkStart for VM 172, job origin: 2166
2022-09-26 18:18:03,405 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":172,"handlerName":"VirtualMachineManagerImpl"}
2022-09-26 18:18:03,411 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) 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
2022-09-26 18:18:03,411 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Successfully transitioned to start state for
VM[User|i-2-172-VM] reservation id = 58abf1dd-68e6-4091-a72a-69fd85b32135
2022-09-26 18:18:03,412 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Deploy avoids pods: null, clusters: null, hosts: null
2022-09-26 18:18:03,417 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) DeploymentPlanner allocation algorithm: null
2022-09-26 18:18:03,417 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:null, requested cpu: 8000, requested ram: 4294967296
2022-09-26 18:18:03,417 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Is ROOT volume READY (pool already allocated)?: No
2022-09-26 18:18:03,421 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Deploy avoids pods: [], clusters: [], hosts: []
2022-09-26 18:18:03,421 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Searching resources only under specified Pod: 1
2022-09-26 18:18:03,421 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this Pod: 1
2022-09-26 18:18:03,424 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Removing from the clusterId list these clusters from avoid
set: []
2022-09-26 18:18:03,429 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking resources in Cluster: 1 under Pod: 1
2022-09-26 18:18:03,429 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Looking for hosts in dc: 1 pod:1
cluster:1
2022-09-26 18:18:03,431 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) FirstFitAllocator has 5 hosts to
check for allocation: [Host[-28-Routing], Host[-30-Routing], Host[-34-Routing],
Host[-31-Routing], Host[-29-Routing]]
2022-09-26 18:18:03,435 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found 5 hosts for allocation after
prioritization: [Host[-28-Routing], Host[-30-Routing], Host[-34-Routing],
Host[-31-Routing], Host[-29-Routing]]
2022-09-26 18:18:03,435 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Looking for speed=8000Mhz, Ram=4096
2022-09-26 18:18:03,437 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host: 28 has cpu capability (cpu:32,
speed:2100) to support requested CPU: 4 and requested speed: 2000
2022-09-26 18:18:03,437 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Checking if host: 28 has enough
capacity for requested CPU: 8000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Hosts's actual total CPU: 67200 and
CPU after applying overprovisioning: 67200
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free CPU: 66200 , Requested CPU: 8000
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free RAM: 64200208384 , Requested
RAM: 4294967296
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host has enough CPU and RAM available
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc CPU from host: 28,
used: 1000, reserved: 0, actual total: 67200, total with overprovisioning:
67200; requested cpu:8000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2022-09-26 18:18:03,438 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc MEM from host: 28,
used: 1610612736, reserved: 0, total: 65810821120; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,438 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found a suitable host, adding to
list: 28
2022-09-26 18:18:03,440 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host: 30 has cpu capability (cpu:32,
speed:2100) to support requested CPU: 4 and requested speed: 2000
2022-09-26 18:18:03,440 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Checking if host: 30 has enough
capacity for requested CPU: 8000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Hosts's actual total CPU: 67200 and
CPU after applying overprovisioning: 67200
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free CPU: 67200 , Requested CPU: 8000
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free RAM: 67178491904 , Requested
RAM: 4294967296
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host has enough CPU and RAM available
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc CPU from host: 30,
used: 0, reserved: 0, actual total: 67200, total with overprovisioning: 67200;
requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,441 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc MEM from host: 30,
used: 0, reserved: 0, total: 67178491904; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,441 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found a suitable host, adding to
list: 30
2022-09-26 18:18:03,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host: 34 has cpu capability (cpu:32,
speed:2100) to support requested CPU: 4 and requested speed: 2000
2022-09-26 18:18:03,443 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Checking if host: 34 has enough
capacity for requested CPU: 8000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Hosts's actual total CPU: 67200 and
CPU after applying overprovisioning: 67200
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free CPU: 67200 , Requested CPU: 8000
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free RAM: 67178491904 , Requested
RAM: 4294967296
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host has enough CPU and RAM available
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc CPU from host: 34,
used: 0, reserved: 0, actual total: 67200, total with overprovisioning: 67200;
requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,444 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc MEM from host: 34,
used: 0, reserved: 0, total: 67178491904; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,444 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found a suitable host, adding to
list: 34
2022-09-26 18:18:03,446 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host: 31 has cpu capability (cpu:32,
speed:2100) to support requested CPU: 4 and requested speed: 2000
2022-09-26 18:18:03,446 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Checking if host: 31 has enough
capacity for requested CPU: 8000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Hosts's actual total CPU: 67200 and
CPU after applying overprovisioning: 67200
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free CPU: 67200 , Requested CPU: 8000
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free RAM: 67089707008 , Requested
RAM: 4294967296
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host has enough CPU and RAM available
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc CPU from host: 31,
used: 0, reserved: 0, actual total: 67200, total with overprovisioning: 67200;
requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,447 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc MEM from host: 31,
used: 0, reserved: 0, total: 67089707008; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,447 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found a suitable host, adding to
list: 31
2022-09-26 18:18:03,449 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host: 29 has cpu capability (cpu:32,
speed:2100) to support requested CPU: 4 and requested speed: 2000
2022-09-26 18:18:03,449 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Checking if host: 29 has enough
capacity for requested CPU: 8000 and requested RAM: 4294967296 ,
cpuOverprovisioningFactor: 1.0
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Hosts's actual total CPU: 67200 and
CPU after applying overprovisioning: 67200
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free CPU: 67200 , Requested CPU: 8000
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Free RAM: 67178491904 , Requested
RAM: 4294967296
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host has enough CPU and RAM available
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc CPU from host: 29,
used: 0, reserved: 0, actual total: 67200, total with overprovisioning: 67200;
requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,450 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) STATS: Can alloc MEM from host: 29,
used: 0, reserved: 0, total: 67178491904; requested mem:
4294967296,alloc_from_last_host?:false ,considerReservedCapacity?: true
2022-09-26 18:18:03,450 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Found a suitable host, adding to
list: 29
2022-09-26 18:18:03,450 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068
FirstFitRoutingAllocator) (logid:8b427d52) Host Allocator returning 5 suitable
hosts
2022-09-26 18:18:03,451 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking suitable pools for volume (Id, Type): (263,ROOT)
2022-09-26 18:18:03,451 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) We need to allocate new storagepool for this volume
2022-09-26 18:18:03,451 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Calling StoragePoolAllocators to find suitable pools
2022-09-26 18:18:03,451 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2022-09-26 18:18:03,451 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) ClusterScopeStoragePoolAllocator looking for storage pool
2022-09-26 18:18:03,451 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Looking for pools in dc: 1 pod:1 cluster:1. Disabled pools
will be ignored.
2022-09-26 18:18:03,451 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found pools matching tags: [Pool[2|NetworkFilesystem],
Pool[3|NetworkFilesystem], Pool[4|NetworkFilesystem],
Pool[5|NetworkFilesystem], Pool[7|NetworkFilesystem]]
2022-09-26 18:18:03,452 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if storage pool is suitable, name: null ,poolId: 2
2022-09-26 18:18:03,453 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Storage pool null (2) does not supply IOPS capacity, assuming
enough capacity
2022-09-26 18:18:03,453 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool 2 for storage, totalSize: 1415965573120,
usedBytes: 263653949440, usedPct: 0.18620081903478305, disable threshold: 0.85
2022-09-26 18:18:03,453 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Destination pool id: 2
2022-09-26 18:18:03,457 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Pool ID for the volume with ID 263 is null
2022-09-26 18:18:03,459 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found storage pool ps2 of type NetworkFilesystem with
overprovisioning factor 2
2022-09-26 18:18:03,459 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total over provisioned capacity calculated is 2 * 1415965573120
2022-09-26 18:18:03,459 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total capacity of the pool ps2 with ID 2 is 2831931146240
2022-09-26 18:18:03,459 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool: 2 for storage allocation , maxSize :
2831931146240, totalAllocatedSize : 2459254611968, askingSize : 64424509440,
allocated disable threshold: 0.85
2022-09-26 18:18:03,459 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Insufficient un-allocated capacity on: 2 for storage
allocation since its allocated percentage: 0.8911512996206595 has crossed the
allocated pool.storage.allocated.capacity.disablethreshold: 0.85, skipping this
pool
2022-09-26 18:18:03,459 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if storage pool is suitable, name: null ,poolId: 3
2022-09-26 18:18:03,460 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Storage pool null (3) does not supply IOPS capacity, assuming
enough capacity
2022-09-26 18:18:03,460 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool 3 for storage, totalSize: 1415965573120,
usedBytes: 242251464704, usedPct: 0.17108570243710983, disable threshold: 0.85
2022-09-26 18:18:03,460 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Destination pool id: 3
2022-09-26 18:18:03,467 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Pool ID for the volume with ID 263 is null
2022-09-26 18:18:03,469 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found storage pool ps3 of type NetworkFilesystem with
overprovisioning factor 2
2022-09-26 18:18:03,469 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total over provisioned capacity calculated is 2 * 1415965573120
2022-09-26 18:18:03,469 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total capacity of the pool ps3 with ID 3 is 2831931146240
2022-09-26 18:18:03,470 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool: 3 for storage allocation , maxSize :
2831931146240, totalAllocatedSize : 2373355068416, askingSize : 64424509440,
allocated disable threshold: 0.85
2022-09-26 18:18:03,470 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Insufficient un-allocated capacity on: 3 for storage
allocation since its allocated percentage: 0.8608188024248679 has crossed the
allocated pool.storage.allocated.capacity.disablethreshold: 0.85, skipping this
pool
2022-09-26 18:18:03,470 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if storage pool is suitable, name: null ,poolId: 4
2022-09-26 18:18:03,471 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Storage pool null (4) does not supply IOPS capacity, assuming
enough capacity
2022-09-26 18:18:03,472 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool 4 for storage, totalSize: 1415965573120,
usedBytes: 240695377920, usedPct: 0.16998674437376424, disable threshold: 0.85
2022-09-26 18:18:03,472 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Destination pool id: 4
2022-09-26 18:18:03,480 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Pool ID for the volume with ID 263 is null
2022-09-26 18:18:03,483 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found storage pool ps4 of type NetworkFilesystem with
overprovisioning factor 2
2022-09-26 18:18:03,483 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total over provisioned capacity calculated is 2 * 1415965573120
2022-09-26 18:18:03,483 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total capacity of the pool ps4 with ID 4 is 2831931146240
2022-09-26 18:18:03,484 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool: 4 for storage allocation , maxSize :
2831931146240, totalAllocatedSize : 2362232407552, askingSize : 64424509440,
allocated disable threshold: 0.85
2022-09-26 18:18:03,484 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Insufficient un-allocated capacity on: 4 for storage
allocation since its allocated percentage: 0.8568912136913749 has crossed the
allocated pool.storage.allocated.capacity.disablethreshold: 0.85, skipping this
pool
2022-09-26 18:18:03,484 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if storage pool is suitable, name: null ,poolId: 5
2022-09-26 18:18:03,485 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Storage pool null (5) does not supply IOPS capacity, assuming
enough capacity
2022-09-26 18:18:03,486 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool 5 for storage, totalSize: 1415965573120,
usedBytes: 204421988352, usedPct: 0.14436932100091085, disable threshold: 0.85
2022-09-26 18:18:03,486 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Destination pool id: 5
2022-09-26 18:18:03,495 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Pool ID for the volume with ID 263 is null
2022-09-26 18:18:03,497 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found storage pool ps5 of type NetworkFilesystem with
overprovisioning factor 2
2022-09-26 18:18:03,498 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total over provisioned capacity calculated is 2 * 1415965573120
2022-09-26 18:18:03,498 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total capacity of the pool ps5 with ID 5 is 2831931146240
2022-09-26 18:18:03,498 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool: 5 for storage allocation , maxSize :
2831931146240, totalAllocatedSize : 2426656719360, askingSize : 64424509440,
allocated disable threshold: 0.85
2022-09-26 18:18:03,498 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Insufficient un-allocated capacity on: 5 for storage
allocation since its allocated percentage: 0.8796404644609556 has crossed the
allocated pool.storage.allocated.capacity.disablethreshold: 0.85, skipping this
pool
2022-09-26 18:18:03,499 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if storage pool is suitable, name: null ,poolId: 7
2022-09-26 18:18:03,499 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Storage pool null (7) does not supply IOPS capacity, assuming
enough capacity
2022-09-26 18:18:03,500 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool 7 for storage, totalSize: 1415965573120,
usedBytes: 44663046144, usedPct: 0.031542466138910076, disable threshold: 0.85
2022-09-26 18:18:03,500 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Destination pool id: 7
2022-09-26 18:18:03,509 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Pool ID for the volume with ID 263 is null
2022-09-26 18:18:03,512 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found storage pool ps6 of type NetworkFilesystem with
overprovisioning factor 2
2022-09-26 18:18:03,512 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total over provisioned capacity calculated is 2 * 1415965573120
2022-09-26 18:18:03,512 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Total capacity of the pool ps6 with ID 7 is 2831931146240
2022-09-26 18:18:03,512 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking pool: 7 for storage allocation , maxSize :
2831931146240, totalAllocatedSize : 751619671552, askingSize : 64424509440,
allocated disable threshold: 0.85
2022-09-26 18:18:03,512 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) ClusterScopeStoragePoolAllocator returning 1 suitable storage
pools
2022-09-26 18:18:03,512 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2022-09-26 18:18:03,512 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Checking if host: 28 can access any suitable storage pool for
volume: ROOT
2022-09-26 18:18:03,513 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Host: 28 can access pool: 7
2022-09-26 18:18:03,513 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Found a potential host id: 28 name: cloud006.sinodata.net.cn
and associated storage pools for this VM
2022-09-26 18:18:03,514 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) 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(28)-Storage(Volume(263|ROOT-->Pool(7))]
2022-09-26 18:18:03,514 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Deployment found - P0=VM[User|i-2-172-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(28)-Storage(Volume(263|ROOT-->Pool(7))]
2022-09-26 18:18:03,520 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: null new host id: 28 host id before state
transition: null
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) We are allocating VM, increasing the used capacity of this
host:28
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Current Used CPU: 1000 , Free CPU:66200 ,Requested CPU: 8000
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Current Used RAM: 1610612736 , Free RAM:64200208384 ,Requested
RAM: 4294967296
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) CPU STATS after allocation: for host: 28, old used: 1000, old
reserved: 0, actual total: 67200, total with overprovisioning: 67200; new
used:9000, reserved:0; requested cpu:8000,alloc_from_last:false
2022-09-26 18:18:03,524 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) RAM STATS after allocation: for host: 28, old used:
1610612736, old reserved: 0, total: 65810821120; new used: 5905580032,
reserved: 0; requested mem: 4294967296,alloc_from_last:false
2022-09-26 18:18:03,531 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Network id=204 is already implemented
2022-09-26 18:18:03,538 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Service SecurityGroup is not supported in the network id=204
2022-09-26 18:18:03,543 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Changing active number of nics for network id=204 on 1
2022-09-26 18:18:03,546 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Asking VirtualRouter to prepare for
Nic[241-172-58abf1dd-68e6-4091-a72a-69fd85b32135-192.168.30.152]
2022-09-26 18:18:03,554 ERROR [o.c.n.r.d.RouterDeploymentDefinition]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Didn't support redundant virtual router without public network!
2022-09-26 18:18:03,554 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
unreachable: Can't find at least one running router!
at
com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:280)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1296)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1631)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1565)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1111)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
at sun.reflect.GeneratedMethodAccessor342.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:5100)
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)
2022-09-26 18:18:03,556 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Cleaning up resources for the vm VM[User|i-2-172-VM] in
Starting state
2022-09-26 18:18:03,559 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Seq 28-7942942367798009077: Sending { Cmd , MgmtId:
229335791363470, via: 28(cloud006.sinodata.net.cn), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-2-172-VM","executeInSequence":false,"wait":0}}]
}
2022-09-26 18:18:03,831 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 28-7942942367798009077: Processing:
{ Ans: , MgmtId: 229335791363470, via: 28, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2022-09-26 18:18:03,831 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Seq 28-7942942367798009077: Received: { Ans: , MgmtId:
229335791363470, via: 28(cloud006.sinodata.net.cn), Ver: v1, Flags: 10, {
StopAnswer } }
2022-09-26 18:18:03,837 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Service SecurityGroup is not supported in the network id=204
2022-09-26 18:18:03,839 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Changing active number of nics for network id=204 on -1
2022-09-26 18:18:03,844 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Asking VirtualRouter to release
NicProfile[241-172-58abf1dd-68e6-4091-a72a-69fd85b32135-192.168.30.152-vlan://untagged
2022-09-26 18:18:03,844 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Successfully released network resources for the vm
VM[User|i-2-172-VM]
2022-09-26 18:18:03,844 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Successfully cleanued up resources for the vm
VM[User|i-2-172-VM] in Starting state
2022-09-26 18:18:03,850 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) DeploymentPlanner allocation algorithm: null
2022-09-26 18:18:03,850 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:null, requested cpu: 8000, requested ram: 4294967296
2022-09-26 18:18:03,850 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Is ROOT volume READY (pool already allocated)?: No
2022-09-26 18:18:03,855 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Deploy avoids pods: [], clusters: [], hosts: [28]
2022-09-26 18:18:03,855 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) DataCenter id = '1' provided is in avoid set,
DeploymentPlanner cannot allocate the VM, returning.
2022-09-26 18:18:03,861 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) VM state transitted from :Starting to Stopped with event:
OperationFailedvm's original host id: null new host id: null host id before
state transition: 28
2022-09-26 18:18:03,864 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Hosts's actual total CPU: 67200 and CPU after applying
overprovisioning: 67200
2022-09-26 18:18:03,864 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Hosts's actual total RAM: 65810821120 and RAM after applying
overprovisioning: 65810821120
2022-09-26 18:18:03,864 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) release cpu from host: 28, old used: 9000,reserved: 0, actual
total: 67200, total with overprovisioning: 67200; new used: 1000,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2022-09-26 18:18:03,864 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) release mem from host: 28, old used: 5905580032,reserved: 0,
total: 65810821120; new used: 1610612736,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2022-09-26 18:18:03,873 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-172-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2022-09-26 18:18:03,873 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168 ctx-4dd9a068)
(logid:8b427d52) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-172-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2022-09-26 18:18:03,873 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 172, job origin: 2166
2022-09-26 18:18:03,873 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Unable
to complete AsyncJobVO {id:2168, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAArHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVB
hc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
229335791363470, completeMsid: null, lastUpdated: null, lastPolled: null,
created: Mon Sep 26 18:18:01 CST 2022}, job origin:2166
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-172-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
at sun.reflect.GeneratedMethodAccessor342.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:5100)
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)
2022-09-26 18:18:03,875 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Complete
async job-2168, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdAA1VW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lb
nQgZm9yIFZNW1VzZXJ8aS0yLTE3Mi1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABRzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AAp4cAAABDN0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRzcQB-ABEAABNJcQB-ABNxAH4AFHEAfgAVc3EAfgAR_____3QAJnN1bi5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yMzQycHQABmludm9rZXNxAH4AEQAAACt0AChzdW4ucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABlzcQB-ABEAAAHydAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGXNxAH4AEQAAAGt0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JzcQB-ABEAABPscQB-ABNxAH4AFHEAfgAjc3EAfgARAAAAZnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9ic3EAfgARAAACRXQAP29yZy5hcGFjaGUuY2
xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHNxAH4AEQAAADF0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnNxAH4AEQAAADh0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxzcQB-ABEAAABndABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgAzdAAPY2FsbFdpdGhDb250ZXh0c3EAfgARAAAANXEAfgA2cQB-ADN0AA5ydW5XaXRoQ29udGV4dHNxAH4AEQAAAC50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AL3EAfgAwc3EAfgARAAACEXEAfgAqcQB-ACtxAH4AMHNxAH4AEQAAAf90AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4ANHNxAH4AEQAAAQp0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADBzcQB-ABEAAAR9dAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGh
yZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJzcQB-ABEAAAJwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBFcQB-ADBzcQB-ABEAAALsdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADBzcgAmamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUxpc3T8DyUxteyOEAIAAUwABGxpc3RxAH4ADHhyACxqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlQ29sbGVjdGlvbhlCAIDLXvceAgABTAABY3QAFkxqYXZhL3V0aWwvQ29sbGVjdGlvbjt4cHNyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHEAfgBReHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3EAfgBQAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBTAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXJjQfdzv5V8swIAAHhwAA
2022-09-26 18:18:03,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Publish
async job-2168 complete on message bus
2022-09-26 18:18:03,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Wake up
jobs related to job-2168
2022-09-26 18:18:03,876 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Update
db status for job-2168
2022-09-26 18:18:03,877 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Wake up
jobs joined with job-2168 and disjoin all subjobs created from job- 2168
2022-09-26 18:18:03,882 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Done
executing com.cloud.vm.VmWorkStart for job-2168
2022-09-26 18:18:03,883 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-23:ctx-1f7ad0dc job-2166/job-2168) (logid:8b427d52) Remove
job-2168 from job monitoring
2022-09-26 18:18:03,891 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Destroying vm VM[User|i-2-172-VM] as it failed to create on Host with Id:null
2022-09-26 18:18:03,895 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52) 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
2022-09-26 18:18:03,910 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Updating resource Type = volume count for Account = 2 Operation = decreasing
Amount = 1
2022-09-26 18:18:03,914 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Updating resource Type = primary_storage count for Account = 2 Operation =
decreasing Amount = 64424509440
2022-09-26 18:18:03,918 WARN [o.a.c.alerts]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message::
Failed to deploy Vm with Id: 172, on Host with Id: null
2022-09-26 18:18:03,922 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Updating resource Type = user_vm count for Account = 2 Operation = decreasing
Amount = 1
2022-09-26 18:18:03,926 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Updating resource Type = cpu count for Account = 2 Operation = decreasing
Amount = 4
2022-09-26 18:18:03,930 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166 ctx-522245c2) (logid:8b427d52)
Updating resource Type = memory count for Account = 2 Operation = decreasing
Amount = 4096
2022-09-26 18:18:03,937 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to
insufficient capacity
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:722)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:245)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:212)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4493)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4057)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4044)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at
org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
at com.sun.proxy.$Proxy164.startVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:50)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:150)
at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
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)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable
to create a deployment for VM[User|i-2-172-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1075)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4937)
at sun.reflect.GeneratedMethodAccessor342.invoke(Unknown Source)
... 17 more
2022-09-26 18:18:03,938 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Complete async
job-2166, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable
to start a VM due to insufficient capacity"}
2022-09-26 18:18:03,939 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Publish async
job-2166 complete on message bus
2022-09-26 18:18:03,939 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Wake up jobs
related to job-2166
2022-09-26 18:18:03,939 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Update db status
for job-2166
2022-09-26 18:18:03,940 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Wake up jobs
joined with job-2166 and disjoin all subjobs created from job- 2166
2022-09-26 18:18:03,942 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-2166
2022-09-26 18:18:03,942 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-18:ctx-0ed3784a job-2166) (logid:8b427d52) Remove job-2166
from job monitoring
2022-09-26 18:18:05,358 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) HostStatsCollector is
running...
2022-09-26 18:18:05,368 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) Seq 28-7942942367798009078:
Received: { Ans: , MgmtId: 229335791363470, via: 28(cloud006.sinodata.net.cn),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-09-26 18:18:05,415 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) Seq 29-270778927595657214:
Received: { Ans: , MgmtId: 229335791363470, via: 29(cloud003.sinodata.net.cn),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-09-26 18:18:05,461 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) Seq 30-5901122886738909115:
Received: { Ans: , MgmtId: 229335791363470, via: 30(cloud002.sinodata.net.cn),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-09-26 18:18:05,469 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) Seq 31-9023806278366926842:
Received: { Ans: , MgmtId: 229335791363470, via: 31(cloud004.sinodata.net.cn),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-09-26 18:18:05,516 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-db8f3ac9) (logid:5497f4ac) Seq 34-4726527808925341667:
Received: { Ans: , MgmtId: 229335791363470, via: 34(cloud005.sinodata.net.cn),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
^C
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
