We have been using the CloudStack version 4.18.1.0 with KVM hosts with a NFS
primary storage pool and a secondary NFS storage pool.
We have created a shared guest network with "DefaultSharedNetworkOffering"
network offering with a fixed IP range to spin VMs using a standard linux image.
However, the VM spin keeps failing with errors and the instance goes to 'Error'
state and the ROOT disk volume for the instance also gets destroyed. And no VR
gets created.
Please find the detailed errors we see while trying to spin the instance using
the Shared network.
Error
Unable to start a VM [cf941e56-f29d-4442-947a-cd18f5b5d733] due to [Unable to
create a deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}].
The /var/log/messages show below logs:
Jan 30 11:54:41 vhs04 java: ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
Jan 30 11:54:41 vhs04 java: INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
Jan 30 11:54:41 vhs04 java: ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Unable
to complete AsyncJobVO: {id:2071, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAABhHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229310345246465, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Jan 30 11:54:40 UTC 2024, removed: null}, job
origin:2070
Jan 30 11:54:41 vhs04 java:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1226)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5412)
Jan 30 11:54:41 vhs04 java: at
jdk.internal.reflect.GeneratedMethodAccessor882.invoke(Unknown Source)
Jan 30 11:54:41 vhs04 java: at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan 30 11:54:41 vhs04 java: at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5536)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jan 30 11:54:41 vhs04 java: at java.base/java.lang.Thread.run(Thread.java:829)
Jan 30 11:54:41 vhs04 java: INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Remove
job-2071 from job monitoring
Jan 30 11:54:41 vhs04 java: WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
alertType=[8] dataCenterId=[1] podId=[1] clusterId=[null] message=[Failed to
deploy Vm with Id: 388, on Host with Id: 1].
Jan 30 11:54:41 vhs04 java: WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) No
recipients set in global setting 'alert.email.addresses', skipping sending
alert with subject [Failed to deploy Vm with Id: 388, on Host with Id: 1] and
content [Failed to deploy Vm with Id: 388, on Host with Id: 1].
Jan 30 11:54:41 vhs04 java: ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
Jan 30 11:54:41 vhs04 java: com.cloud.utils.exception.CloudRuntimeException:
Unable to start a VM [cf941e56-f29d-4442-947a-cd18f5b5d733] due to [Unable to
create a deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}].
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:841)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:246)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5401)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5251)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4876)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4865)
Jan 30 11:54:41 vhs04 java: at
jdk.internal.reflect.GeneratedMethodAccessor1043.invoke(Unknown Source)
Jan 30 11:54:41 vhs04 java: at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jan 30 11:54:41 vhs04 java: at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 30 11:54:41 vhs04 java: at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:52)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
Jan 30 11:54:41 vhs04 java: at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
Jan 30 11:54:41 vhs04 java: at
com.sun.proxy.$Proxy185.startVirtualMachine(Unknown Source)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:754)
Jan 30 11:54:41 vhs04 java: at
com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:163)
Jan 30 11:54:41 vhs04 java: at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:112)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
Jan 30 11:54:41 vhs04 java: at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jan 30 11:54:41 vhs04 java: at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jan 30 11:54:41 vhs04 java: at java.base/java.lang.Thread.run(Thread.java:829)
Jan 30 11:54:41 vhs04 java: Caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1226)
Jan 30 11:54:41 vhs04 java: at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5412)
Jan 30 11:54:41 vhs04 java: at
jdk.internal.reflect.GeneratedMethodAccessor882.invoke(Unknown Source)
Jan 30 11:54:41 vhs04 java: ... 17 more
The cloudstack management log file shows below logs:
[Host04]# egrep "i-2-388-VM|job-2071|job-2070|7b4f2d1b"
/var/log/cloudstack/management/management-server.log
2024-01-30 11:54:40,249 INFO [c.c.v.VirtualMachineManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) allocating
virtual machine from template:62077549-9c1f-442a-ad97-ce42cd7c63fe with
hostname:i-2-388-VM and 1 networks
2024-01-30 11:54:40,250 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Allocating
entries for VM: VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
2024-01-30 11:54:40,251 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Allocating
nics for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
2024-01-30 11:54:40,251 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Allocating nic
for vm VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
in network Network {"id": 247, "name": "10.252.1.x", "uuid":
"f2971bd7-4635-48f2-8b05-75b5d5a4705c", "networkofferingid": 8} with requested
profile NicProfile
{"broadcastUri":null,"iPv4Address":null,"id":0,"reservationId":null,"vmId":0}
2024-01-30 11:54:40,273 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Allocating
disks for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
2024-01-30 11:54:40,274 INFO [o.a.c.e.o.VolumeOrchestrator]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6 ctx-8967dcfd) (logid:de917ec1)
Adding disk object [ROOT-388] to VM [VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}]
2024-01-30 11:54:40,283 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Allocation
completed for VM: VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
2024-01-30 11:54:40,283 DEBUG [c.c.v.UserVmManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) Successfully
allocated DB entry for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
2024-01-30 11:54:40,298 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:36107a8f) Add job-2070 into
job monitoring
2024-01-30 11:54:40,302 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp1789718525-14197:ctx-9096458a ctx-1cadf5a6) (logid:de917ec1) submit async
job-2070, details: AsyncJobVO: {id:2070, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 388, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"f2971bd7-4635-48f2-8b05-75b5d5a4705c","boottype":"BIOS","hostid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810","httpmethod":"GET","clusterid":"35c1a5be-5609-4a39-bcf8-1940c0fc3e64","templateid":"62077549-9c1f-442a-ad97-ce42cd7c63fe","ctxAccountId":"2","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733","cmdEventType":"VM.CREATE","startvm":"true","bootmode":"LEGACY","iothreadsenabled":"false","serviceofferingid":"abb92858-9eb9-45bb-8cce-9778113fe54f","response":"json","ctxUserId":"2","zoneid":"bef7ac55-3bb8-4211-bbc7-1e708bb36083","rootdisksize":"50","ctxStartEventId":"3902","id":"388","ctxDetails":"{\"interface
com.cloud.offering.ServiceOffering\":\"abb92858-9eb9-45bb-8cce-9778113fe54f\",\"interface
com.cloud.host.Host\":\"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810\",\"interface
com.cloud.dc.DataCenter\":\"bef7ac55-3bb8-4211-bbc7-1e708bb36083\",\"interface
com.cloud.org.Cluster\":\"35c1a5be-5609-4a39-bcf8-1940c0fc3e64\",\"interface
com.cloud.dc.Pod\":\"364522fe-d989-4cee-bc1c-7489aa54f113\",\"interface
com.cloud.template.VirtualMachineTemplate\":\"62077549-9c1f-442a-ad97-ce42cd7c63fe\",\"interface
com.cloud.vm.VirtualMachine\":\"cf941e56-f29d-4442-947a-cd18f5b5d733\"}","dynamicscalingenabled":"true","podid":"364522fe-d989-4cee-bc1c-7489aa54f113","affinitygroupids":"","keypairs":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229310345246465, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2024-01-30 11:54:40,302 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Executing
AsyncJobVO: {id:2070, userId: 2, accountId: 2, instanceType: VirtualMachine,
instanceId: 388, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"iptonetworklist[0].networkid":"f2971bd7-4635-48f2-8b05-75b5d5a4705c","boottype":"BIOS","hostid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810","httpmethod":"GET","clusterid":"35c1a5be-5609-4a39-bcf8-1940c0fc3e64","templateid":"62077549-9c1f-442a-ad97-ce42cd7c63fe","ctxAccountId":"2","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733","cmdEventType":"VM.CREATE","startvm":"true","bootmode":"LEGACY","iothreadsenabled":"false","serviceofferingid":"abb92858-9eb9-45bb-8cce-9778113fe54f","response":"json","ctxUserId":"2","zoneid":"bef7ac55-3bb8-4211-bbc7-1e708bb36083","rootdisksize":"50","ctxStartEventId":"3902","id":"388","ctxDetails":"{\"interface
com.cloud.offering.ServiceOffering\":\"abb92858-9eb9-45bb-8cce-9778113fe54f\",\"interface
com.cloud.host.Host\":\"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810\",\"interface
com.cloud.dc.DataCenter\":\"bef7ac55-3bb8-4211-bbc7-1e708bb36083\",\"interface
com.cloud.org.Cluster\":\"35c1a5be-5609-4a39-bcf8-1940c0fc3e64\",\"interface
com.cloud.dc.Pod\":\"364522fe-d989-4cee-bc1c-7489aa54f113\",\"interface
com.cloud.template.VirtualMachineTemplate\":\"62077549-9c1f-442a-ad97-ce42cd7c63fe\",\"interface
com.cloud.vm.VirtualMachine\":\"cf941e56-f29d-4442-947a-cd18f5b5d733\"}","dynamicscalingenabled":"true","podid":"364522fe-d989-4cee-bc1c-7489aa54f113","affinitygroupids":"","keypairs":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229310345246465, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2024-01-30 11:54:40,312 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Service SecurityGroup is not supported in the network id=247
2024-01-30 11:54:40,314 DEBUG [c.c.n.NetworkModelImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Service SecurityGroup is not supported in the network id=247
2024-01-30 11:54:40,315 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Destination Host to deploy the VM is specified, specifying a deployment plan to
deploy the VM
2024-01-30 11:54:40,315 DEBUG [c.c.a.ApiServlet]
(qtp1789718525-14166:ctx-c9a1a86f) (logid:aa592ac2) ===START=== 10.252.10.14
-- GET
jobId=7b4f2d1b-953b-4626-a05f-dced09db9bea&command=queryAsyncJobResult&response=json
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Host:
1 has cpu capability (cpu:96, speed:2200) to support requested CPU: 4 and
requested speed: 1000
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking if host: 1 has enough capacity for requested CPU: 4000 and requested
RAM: (16.00 GB) 17179869184 , cpuOverprovisioningFactor: 1.0
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Hosts's actual total CPU: 211200 and CPU after applying overprovisioning: 211200
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
considerReservedCapacity isfalse , not considering reserved capacity for
calculating free capacity
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Free
CPU: 210700 , Requested CPU: 4000
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Free
RAM: (1004.57 GB) 1078650142720 , Requested RAM: (16.00 GB) 17179869184
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Host
has enough CPU and RAM available
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) STATS:
Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 211200, total
with overprovisioning: 211200; requested cpu:4000,alloc_from_last_host?:false
,considerReservedCapacity?: false
2024-01-30 11:54:40,316 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) STATS:
Can alloc MEM from host: 1, used: (512.00 MB) 536870912, reserved: (0 bytes) 0,
total: (1005.07 GB) 1079187013632; requested mem: (16.00 GB) 17179869184,
alloc_from_last_host?: false , considerReservedCapacity?: false
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Adding
pods to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Adding
clusters to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Adding
hosts to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
DeploymentPlanner allocation algorithm: null
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Trying
to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
4000, requested ram: (16.00 GB) 17179869184
2024-01-30 11:54:40,320 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Is
ROOT volume READY (pool already allocated)?: No
2024-01-30 11:54:40,322 DEBUG [c.c.a.ApiServlet]
(qtp1789718525-14166:ctx-c9a1a86f ctx-5d6bdb4c) (logid:aa592ac2) ===END===
10.252.10.14 -- GET
jobId=7b4f2d1b-953b-4626-a05f-dced09db9bea&command=queryAsyncJobResult&response=json
2024-01-30 11:54:40,323 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
DeploymentPlan has host_id specified, choosing this host: 1
2024-01-30 11:54:40,323 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2024-01-30 11:54:40,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking suitable pools for volume (Id, Type): (260,ROOT)
2024-01-30 11:54:40,324 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) We
need to allocate new storagepool for this volume
2024-01-30 11:54:40,325 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Calling StoragePoolAllocators to find suitable pools
2024-01-30 11:54:40,325 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
LocalStoragePoolAllocator is returning null since the disk profile does not use
local storage and bypassStorageTypeCheck is false.
2024-01-30 11:54:40,325 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Looking for pools in dc [1], pod [1], cluster [1], and having tags [[nfs]].
Disabled pools will be ignored.
2024-01-30 11:54:40,326 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Found
pools [[Pool[2|NetworkFilesystem]]] that match with tags [[nfs]].
2024-01-30 11:54:40,326 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking if storage pool is suitable, name: vhs01-nfs ,poolId: 2
2024-01-30 11:54:40,327 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Storage pool vhs01-nfs (2) does not supply IOPS capacity, assuming enough
capacity
2024-01-30 11:54:40,327 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking pool 2 for storage, totalSize: 799140741120, usedBytes: 142769913856,
usedPct: 0.17865428016585314, disable threshold: 0.85
2024-01-30 11:54:40,327 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Destination pool id: 2
2024-01-30 11:54:40,331 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Pool
ID for the volume with ID 260 is null
2024-01-30 11:54:40,333 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Found
storage pool vhs01-nfs of type NetworkFilesystem with overprovisioning factor 2
2024-01-30 11:54:40,333 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Total
over provisioned capacity calculated is 2 * (744.26 GB) 799140741120
2024-01-30 11:54:40,333 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Total
capacity of the pool vhs01-nfs with ID 2 is (1.4536 TB) 1598281482240
2024-01-30 11:54:40,333 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking pool: 2 for storage allocation , maxSize : (1.4536 TB) 1598281482240,
totalAllocatedSize : (839.77 GB) 901691868672, askingSize : (50.00 GB)
53687091200, allocated disable threshold: 0.85
2024-01-30 11:54:40,333 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
ClusterScopeStoragePoolAllocator is returning [1] suitable storage pools
[[{"name":"vhs01-nfs","uuid":"eb29dd4c-7cc6-3f6f-bc36-470d6a03621e"}]].
2024-01-30 11:54:40,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Volume
encryption requirements are met by provided host Host
{"id":1,"name":"vhs05.lego05.ops.in01.qualys.com","type":"Routing","uuid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810"}
2024-01-30 11:54:40,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Trying
to find a potenial host and associated storage pools from the suitable
host/pool lists for this VM
2024-01-30 11:54:40,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Checking if host: 1 can access any suitable storage pool for volume: ROOT
2024-01-30 11:54:40,334 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Host:
1 can access pool: 2
2024-01-30 11:54:40,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Found
a potential host id: 1 name: vhs05.lego05.ops.in01.qualys.com and associated
storage pools for this VM
2024-01-30 11:54:40,335 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
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(260|ROOT-->Pool(2))]
2024-01-30 11:54:40,337 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) start
parameter value of enterHardwareSetup == null during processing of queued job
2024-01-30 11:54:40,339 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) Sync
job-2071 execution on object VmWorkJobQueue.388
2024-01-30 11:54:41,127 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-0be1faac) (logid:f7b9ebfd) Schedule queued job-2071
2024-01-30 11:54:41,129 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:d346f7d1) Add
job-2071 into job monitoring
2024-01-30 11:54:41,132 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b)
Executing AsyncJobVO: {id:2071, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAABhHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229310345246465, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Jan 30 11:54:40 UTC 2024, removed: null}
2024-01-30 11:54:41,132 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Run VM
work job: com.cloud.vm.VmWorkStart for VM 388, job origin: 2070
2024-01-30 11:54:41,133 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":388,"handlerName":"VirtualMachineManagerImpl"}
2024-01-30 11:54:41,133 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) orchestrating VM start for 'i-2-388-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d<mailto:com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d>
set to null
2024-01-30 11:54:41,135 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
state transited from [Stopped] to [Starting] with event [StartRequested]. VM's
original host: null, new host: null, host before state transition: null
2024-01-30 11:54:41,135 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Successfully transitioned to start state for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
reservation id = b89bb251-7182-4342-83dc-2aba408db832
2024-01-30 11:54:41,136 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) advanceStart: DeploymentPlan is provided, using dcId:1, podId:
1, clusterId: 1, hostId: 1, poolId: null
2024-01-30 11:54:41,137 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Deploy avoids pods: null, clusters: null, hosts: null
2024-01-30 11:54:41,138 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM start attempt #1
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding pods to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding hosts to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) DeploymentPlanner allocation algorithm: null
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:1, requested cpu: 4000, requested ram: (16.00 GB) 17179869184
2024-01-30 11:54:41,140 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Is ROOT volume READY (pool already allocated)?: No
2024-01-30 11:54:41,142 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) DeploymentPlan has host_id specified, choosing this host: 1
2024-01-30 11:54:41,142 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Looking for suitable pools for this host under zone: 1, pod:
1, cluster: 1
2024-01-30 11:54:41,143 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking suitable pools for volume (Id, Type): (260,ROOT)
2024-01-30 11:54:41,143 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) We need to allocate new storagepool for this volume
2024-01-30 11:54:41,143 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Calling StoragePoolAllocators to find suitable pools
2024-01-30 11:54:41,143 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) LocalStoragePoolAllocator is returning null since the disk
profile does not use local storage and bypassStorageTypeCheck is false.
2024-01-30 11:54:41,144 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Looking for pools in dc [1], pod [1], cluster [1], and having
tags [[nfs]]. Disabled pools will be ignored.
2024-01-30 11:54:41,144 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Found pools [[Pool[2|NetworkFilesystem]]] that match with tags
[[nfs]].
2024-01-30 11:54:41,145 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking if storage pool is suitable, name: vhs01-nfs ,poolId:
2
2024-01-30 11:54:41,145 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Storage pool vhs01-nfs (2) does not supply IOPS capacity,
assuming enough capacity
2024-01-30 11:54:41,145 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking pool 2 for storage, totalSize: 799140741120,
usedBytes: 142769913856, usedPct: 0.17865428016585314, disable threshold: 0.85
2024-01-30 11:54:41,145 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Destination pool id: 2
2024-01-30 11:54:41,149 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Pool ID for the volume with ID 260 is null
2024-01-30 11:54:41,151 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Found storage pool vhs01-nfs of type NetworkFilesystem with
overprovisioning factor 2
2024-01-30 11:54:41,151 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Total over provisioned capacity calculated is 2 * (744.26 GB)
799140741120
2024-01-30 11:54:41,151 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Total capacity of the pool vhs01-nfs with ID 2 is (1.4536 TB)
1598281482240
2024-01-30 11:54:41,151 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking pool: 2 for storage allocation , maxSize : (1.4536
TB) 1598281482240, totalAllocatedSize : (839.77 GB) 901691868672, askingSize :
(50.00 GB) 53687091200, allocated disable threshold: 0.85
2024-01-30 11:54:41,151 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) ClusterScopeStoragePoolAllocator is returning [1] suitable
storage pools
[[{"name":"vhs01-nfs","uuid":"eb29dd4c-7cc6-3f6f-bc36-470d6a03621e"}]].
2024-01-30 11:54:41,152 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Volume encryption requirements are met by provided host Host
{"id":1,"name":"vhs05.lego05.ops.in01.qualys.com","type":"Routing","uuid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810"}
2024-01-30 11:54:41,152 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2024-01-30 11:54:41,152 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking if host: 1 can access any suitable storage pool for
volume: ROOT
2024-01-30 11:54:41,152 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host: 1 can access pool: 2
2024-01-30 11:54:41,153 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Found a potential host id: 1 name:
vhs05.lego05.ops.in01.qualys.com and associated storage pools for this VM
2024-01-30 11:54:41,153 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) 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(260|ROOT-->Pool(2))]
2024-01-30 11:54:41,153 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Deployment found - Attempt #1 - P0=VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"},
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(260|ROOT-->Pool(2))]
2024-01-30 11:54:41,156 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
state transited from [Starting] to [Starting] with event [OperationRetry].
VM's original host: null, new host: Host
{"id":1,"name":"vhs05.lego05.ops.in01.qualys.com","type":"Routing","uuid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810"},
host before state transition: null
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total CPU: 211200 and CPU after applying
overprovisioning: 211200
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) We are allocating VM, increasing the used capacity of this
host:1
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Current Used CPU: 500 , Free CPU:210700 ,Requested CPU: 4000
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Current Used RAM: (512.00 MB) 536870912 , Free RAM:(1004.57
GB) 1078650142720 ,Requested RAM: (16.00 GB) 17179869184
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) CPU STATS after allocation: for host: 1, old used: 500, old
reserved: 0, actual total: 211200, total with overprovisioning: 211200; new
used:4500, reserved:0; requested cpu:4000,alloc_from_last:false
2024-01-30 11:54:41,158 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) RAM STATS after allocation: for host: 1, old used: (512.00 MB)
536870912, old reserved: (0 bytes) 0, total: (1005.07 GB) 1079187013632; new
used: (16.50 GB) 17716740096, reserved: (0 bytes) 0; requested mem: (16.00 GB)
17179869184,alloc_from_last:false
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host: 1 has cpu capability (cpu:96, speed:2200) to support
requested CPU: 4 and requested speed: 1000
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking if host: 1 has enough capacity for requested CPU:
4000 and requested RAM: (16.00 GB) 17179869184 , cpuOverprovisioningFactor: 1.0
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total CPU: 211200 and CPU after applying
overprovisioning: 211200
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) We need to allocate to the last host again, so checking if
there is enough reserved capacity
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Reserved CPU: 0 , Requested CPU: 4000
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Reserved RAM: (0 bytes) 0 , Requested RAM: (16.00 GB)
17179869184
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) STATS: Failed to alloc resource from host: 1 reservedCpu: 0,
requested cpu: 4000, reservedMem: (0 bytes) 0, requested mem: (16.00 GB)
17179869184
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host does not have enough reserved CPU available, cannot
allocate to this host.
2024-01-30 11:54:41,159 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking if host: 1 has enough capacity for requested CPU:
4000 and requested RAM: (16.00 GB) 17179869184 , cpuOverprovisioningFactor: 1.0
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total CPU: 211200 and CPU after applying
overprovisioning: 211200
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Free CPU: 210700 , Requested CPU: 4000
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Free RAM: (1004.57 GB) 1078650142720 , Requested RAM: (16.00
GB) 17179869184
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host has enough CPU and RAM available
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0,
actual total: 211200, total with overprovisioning: 211200; requested
cpu:4000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2024-01-30 11:54:41,160 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) STATS: Can alloc MEM from host: 1, used: (512.00 MB)
536870912, reserved: (0 bytes) 0, total: (1005.07 GB) 1079187013632; requested
mem: (16.00 GB) 17179869184, alloc_from_last_host?: false ,
considerReservedCapacity?: true
2024-01-30 11:54:41,163 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Network id=247 is already implemented
2024-01-30 11:54:41,166 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Service SecurityGroup is not supported in the network id=247
2024-01-30 11:54:41,168 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Changing active number of nics for network id=247 on 1
2024-01-30 11:54:41,170 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Asking VirtualRouter to prepare for
Nic[410-388-null-10.252.1.4]
2024-01-30 11:54:41,179 DEBUG [o.a.c.n.r.d.RouterDeploymentDefinition]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Verifying router service offering with uuid :
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host: 1 has cpu capability (cpu:96, speed:2200) to support
requested CPU: 1 and requested speed: 500
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Checking if host: 1 has enough capacity for requested CPU: 500
and requested RAM: (256.00 MB) 268435456 , cpuOverprovisioningFactor: 1.0
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total CPU: 211200 and CPU after applying
overprovisioning: 211200
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) considerReservedCapacity isfalse , not considering reserved
capacity for calculating free capacity
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Free CPU: 206700 , Requested CPU: 500
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Free RAM: (988.57 GB) 1061470273536 , Requested RAM: (256.00
MB) 268435456
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host has enough CPU and RAM available
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) STATS: Can alloc CPU from host: 1, used: 4500, reserved: 0,
actual total: 211200, total with overprovisioning: 211200; requested
cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: false
2024-01-30 11:54:41,182 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) STATS: Can alloc MEM from host: 1, used: (16.50 GB)
17716740096, reserved: (0 bytes) 0, total: (1005.07 GB) 1079187013632;
requested mem: (256.00 MB) 268435456, alloc_from_last_host?: false ,
considerReservedCapacity?: false
2024-01-30 11:54:41,182 DEBUG [c.c.n.r.NetworkHelperImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Host Host
{"id":1,"name":"vhs05.lego05.ops.in01.qualys.com","type":"Routing","uuid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810"}
has enough capacity for the router
2024-01-30 11:54:41,183 DEBUG [c.c.n.r.NetworkHelperImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Allocating the VR with id=389 in datacenter Zone {"id": "1",
"name": "IN01", "uuid": "bef7ac55-3bb8-4211-bbc7-1e708bb36083"} with the
hypervisor type KVM
2024-01-30 11:54:41,184 DEBUG [c.c.n.r.NetworkHelperImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) KVM won't support system vm, skip it
2024-01-30 11:54:41,185 DEBUG [o.a.c.n.r.d.RouterDeploymentDefinition]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Lock is released for network id 247 as a part of router
startup in
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(260|ROOT-->Pool(2))]
2024-01-30 11:54:41,185 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Unable to contact resource.
2024-01-30 11:54:41,186 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Cleaning up resources for the vm VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
in Starting state
2024-01-30 11:54:41,189 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
is a [User], returning null for control Nic IP.
2024-01-30 11:54:41,190 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Seq 1-7704251587547390078: Sending { Cmd , MgmtId:
229310345246465, via: 1(vhs05.lego05.ops.in01.qualys.com), Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"101":"true"},"volumesToDisconnect":[],"vmName":"i-2-388-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}]
}
2024-01-30 11:54:41,308 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Seq 1-7704251587547390078: Received: { Ans: , MgmtId:
229310345246465, via: 1(vhs05.lego05.ops.in01.qualys.com), Ver: v1, Flags: 10,
{ StopAnswer } }
2024-01-30 11:54:41,312 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Changing active number of nics for network id=247 on -1
2024-01-30 11:54:41,314 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Successfully released network resources for the VM VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
in Starting state
2024-01-30 11:54:41,315 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Successfully released storage resources for the VM VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
in Starting state
2024-01-30 11:54:41,315 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Successfully cleaned up resources for the VM VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
in Starting state
2024-01-30 11:54:41,315 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM start attempt #2
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding pods to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding clusters to avoid lists for non-explicit VM deployment:
[]
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Adding hosts to avoid lists for non-explicit VM deployment: []
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) DeploymentPlanner allocation algorithm: null
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:1, requested cpu: 4000, requested ram: (16.00 GB) 17179869184
2024-01-30 11:54:41,318 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Is ROOT volume READY (pool already allocated)?: No
2024-01-30 11:54:41,319 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) DeploymentPlan has host_id specified, choosing this host: 1
2024-01-30 11:54:41,319 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) The specified host is in avoid set
2024-01-30 11:54:41,319 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Cannot deploy to specified host, returning.
2024-01-30 11:54:41,324 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
state transited from [Starting] to [Stopped] with event [OperationFailed].
VM's original host: null, new host: null, host before state transition: Host
{"id":1,"name":"vhs05.lego05.ops.in01.qualys.com","type":"Routing","uuid":"5e6f1b73-5f0a-4ab1-b424-42dc16fc9810"}
2024-01-30 11:54:41,326 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total CPU: 211200 and CPU after applying
overprovisioning: 211200
2024-01-30 11:54:41,326 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Hosts's actual total RAM: (1005.07 GB) 1079186989056 and RAM
after applying overprovisioning: (1005.07 GB) 1079187013632
2024-01-30 11:54:41,326 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) release cpu from host: 1, old used: 4500,reserved: 0, actual
total: 211200, total with overprovisioning: 211200; new used: 500,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2024-01-30 11:54:41,326 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) release mem from host: 1, old used: (16.50 GB)
17716740096,reserved: (0 bytes) 0, total: (1005.07 GB) 1079187013632; new used:
(512.00 MB) 536870912,reserved:(0 bytes) 0; movedfromreserved:
false,moveToReserveredfalse
2024-01-30 11:54:41,328 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
2024-01-30 11:54:41,328 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071 ctx-2570ea30)
(logid:7b4f2d1b) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
2024-01-30 11:54:41,328 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 388, job origin: 2070
2024-01-30 11:54:41,328 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Unable
to complete AsyncJobVO: {id:2071, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAABhHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 229310345246465, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Jan 30 11:54:40 UTC 2024, removed: null}, job
origin:2070
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
2024-01-30 11:54:41,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b)
Complete async job-2071, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACQVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjM4OCwiaW5zdGFuY2VOYW1lIjoiaS0yLTM4OC1WTSIsInR5cGUiOiJVc2VyIiwidXVpZCI6ImNmOTQxZTU2LWYyOWQtNDQ0Mi05NDdhLWNkMThmNWI1ZDczMyJ9dXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAUc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAKTAAOZGVjbGFyaW5nQ2xhc3NxAH4ACkwACGZpbGVOYW1lcQB-AApMAAptZXRob2ROYW1lcQB-AApMAAptb2R1bGVOYW1lcQB-AApMAA1tb2R1bGVWZXJzaW9ucQB-AAp4cAEAAATKdAADYXBwdAAmY29tLmNsb3VkLnZtLlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGx0AB5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsLmphdmF0ABBvcmNoZXN0cmF0ZVN0YXJ0cHBzcQB-ABEBAAAVJHEAfgATcQB-ABRxAH4AFXEAfgAWcHBzcQB-ABEA_____3B0AC9qZGsuaW50ZXJuYWwucmVmbGVjdC5HZW5lcmF0ZWRNZXRob2RBY2Nlc3Nvcjg4MnB0AAZpbnZva2VwcHNxAH4AEQIAAAArcHQAMWpkay5pbnRlcm5hbC5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AGnQACWphdmEuYmFzZXQABzExLjAuMjFzcQB-ABECAAACNnB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAacQB-AB5xAH4AH3NxAH4AEQEAAABrcQB-ABN0ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4AEQEAABWgcQB-ABNxAH4AFHEAfgAVcQB-ACZwcHNxAH4AEQEAAABmcQB-ABN0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnBwc3EAfgARAQAAAmxxAH4AE3QAP29yZy5hcGFjaGUuY2xvdWRzdGFjay5mcmFtZXdvcmsuam9icy5pbXBsLkFzeW5jSm9iTWFuYWdlckltcGwkNXQAGEFzeW5jSm9iTWFuYWdlckltcGwuamF2YXQADHJ1bkluQ29udGV4dHBwc3EAfgARAQAAADBxAH4AE3QAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVucHBzcQB-ABEBAAAAN3EAfgATdABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxscHBzcQB-ABEBAAAAZnEAfgATdABAb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dHEAfgA2dAAPY2FsbFdpdGhDb250ZXh0cHBzcQB-ABEBAAAANHEAfgATcQB-ADlxAH4ANnQADnJ1bldpdGhDb250ZXh0cHBzcQB-ABEBAAAALXEAfgATdAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ADJxAH4AM3Bwc3EAfgARAQAAAjhxAH4AE3EAfgAtcQB-AC5xAH4AM3Bwc3EAfgARAgAAAgNwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ADdxAH4AHnEAfgAfc3EAfgARAgAAAQhwdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAzcQB-AB5xAH4AH3NxAH4AEQIAAARocHQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2VycQB-AB5xAH4AH3NxAH4AEQIAAAJ0cHQALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ASHEAfgAzcQB-AB5xAH4AH3NxAH4AEQIAAAM9cHQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAzcQB-AB5xAH4AH3NyAB9qYXZhLnV0aWwuQ29sbGVjdGlvbnMkRW1wdHlMaXN0ergXtDynnt4CAAB4cHhzcgARamF2YS5sYW5nLkludGVnZXIS4qCk94GHOAIAAUkABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAQ73NyABNqYXZhLnV0aWwuQXJyYXlMaXN0eIHSHZnHYZ0DAAFJAARzaXpleHAAAAAAdwQAAAAAeHNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cQB-AFIAAAAAAAAAAXZyABdjb20uY2xvdWQuZGMuRGF0YUNlbnRlchBQVG0DRR4AAgAAeHAA
2024-01-30 11:54:41,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Publish
async job-2071 complete on message bus
2024-01-30 11:54:41,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Wake up
jobs related to job-2071
2024-01-30 11:54:41,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Update
db status for job-2071
2024-01-30 11:54:41,330 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Wake up
jobs joined with job-2071 and disjoin all subjobs created from job- 2071
2024-01-30 11:54:41,331 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Done
executing com.cloud.vm.VmWorkStart for job-2071
2024-01-30 11:54:41,331 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-154:ctx-612d5ad2 job-2070/job-2071) (logid:7b4f2d1b) Remove
job-2071 from job monitoring
2024-01-30 11:54:41,334 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Destroying vm VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
as it failed to create on Host with Id:1
2024-01-30 11:54:41,336 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) VM
instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}
state transited from [Stopped] to [Error] with event [OperationFailedToError].
VM's original host: null, new host: null, host before state transition: null
2024-01-30 11:54:41,338 DEBUG [c.c.s.d.VolumeDaoImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Removing volume 260 from DB
2024-01-30 11:54:41,340 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Updating resource Type = volume count for Account = 2 Operation = decreasing
Amount = 1
2024-01-30 11:54:41,341 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Updating resource Type = primary_storage count for Account = 2 Operation =
decreasing Amount = (50.00 GB) 53687091200
2024-01-30 11:54:41,344 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
alertType=[8] dataCenterId=[1] podId=[1] clusterId=[null] message=[Failed to
deploy Vm with Id: 388, on Host with Id: 1].
2024-01-30 11:54:41,345 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b) No
recipients set in global setting 'alert.email.addresses', skipping sending
alert with subject [Failed to deploy Vm with Id: 388, on Host with Id: 1] and
content [Failed to deploy Vm with Id: 388, on Host with Id: 1].
2024-01-30 11:54:41,345 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Updating resource Type = user_vm count for Account = 2 Operation = decreasing
Amount = 1
2024-01-30 11:54:41,346 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Updating resource Type = cpu count for Account = 2 Operation = decreasing
Amount = 4
2024-01-30 11:54:41,347 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070 ctx-873335b4) (logid:7b4f2d1b)
Updating resource Type = memory count for Account = 2 Operation = decreasing
Amount = 16384
2024-01-30 11:54:41,350 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM
[cf941e56-f29d-4442-947a-cd18f5b5d733] due to [Unable to create a deployment
for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}].
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}Scope=interface
com.cloud.dc.DataCenter; id=1
2024-01-30 11:54:41,351 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Complete async
job-2070, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable
to start a VM [cf941e56-f29d-4442-947a-cd18f5b5d733] due to [Unable to create
a deployment for VM instance
{"id":388,"instanceName":"i-2-388-VM","type":"User","uuid":"cf941e56-f29d-4442-947a-cd18f5b5d733"}]."}
2024-01-30 11:54:41,351 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Publish async
job-2070 complete on message bus
2024-01-30 11:54:41,351 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Wake up jobs
related to job-2070
2024-01-30 11:54:41,351 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Update db status
for job-2070
2024-01-30 11:54:41,351 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Wake up jobs joined
with job-2070 and disjoin all subjobs created from job- 2070
2024-01-30 11:54:41,352 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Done executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-2070
2024-01-30 11:54:41,352 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-7:ctx-a1e63a1e job-2070) (logid:7b4f2d1b) Remove job-2070
from job monitoring
2024-01-30 11:54:43,631 DEBUG [c.c.a.ApiServlet]
(qtp1789718525-14127:ctx-1dc46815) (logid:6278b8c9) ===START=== 10.252.10.14
-- GET
jobId=7b4f2d1b-953b-4626-a05f-dced09db9bea&command=queryAsyncJobResult&response=json
2024-01-30 11:54:43,638 DEBUG [c.c.a.ApiServlet]
(qtp1789718525-14127:ctx-1dc46815 ctx-b0064f7e) (logid:6278b8c9) ===END===
10.252.10.14 -- GET
jobId=7b4f2d1b-953b-4626-a05f-dced09db9bea&command=queryAsyncJobResult&response=json
[Host04]#
Can someone suggest where exactly is that InsufficientServerCapacityException
error pointing to in this case?
Kapil B
