Hi, It looks like the systemvm template is not ready. please check
-Wei On Tue, 30 Jan 2024 at 13:38, Kapil Bhuskute <[email protected]> wrote: > 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 > >
