Hello,
Unable to deploy vm instance,
My server is alam 8.
1. MGMT+NFS
2. KVM
+++++++++++++++++
Unable to start a VM [55d71859-ae54-4e12-8de3-8f84fe9627bf] due to
[Unable to create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}].
+++++++++++++
MGMT server log
++++++++++++++++++
2023-09-04 14:53:15,711 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-d4b80649) (logid:550584ab) ===START=== 10.66.10.22
-- GET
zoneid=cd6b9366-3982-42be-b3b2-8c4361239e4f&podid=97b8385b-baf9-4818-97b1-4ca141dcddce&clusterid=94385c60-5970-447c-926b-11653ac04a5a&hostid=7cad36ca-ddb9-404f-99ae-4f9f446138d8&boottype=BIOS&bootmode=LEGACY&templateid=0b13fe5d-af8a-4247-b473-20fb19723a9a&hypervisor=KVM&startvm=true&serviceofferingid=d13efba9-4f06-429c-a697-7a46a7c0f9b4&diskofferingid=961fd360-ca5e-4d2a-9813-cbd9eb392412&affinitygroupids=&securitygroupids=3388fc57-4a57-11ee-acdf-08002737abca&keypairs=&command=deployVirtualMachine&response=json
2023-09-04 14:53:15,711 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-d4b80649) (logid:550584ab) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:15,729 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:15,736 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:15,738 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [deployVirtualMachine] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:15,742 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:15,744 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:15,815 DEBUG [c.c.u.AccountManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Access
granted to Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]
to
org.apache.cloudstack.quota.vo.ServiceOfferingVO$$EnhancerByCGLIB$$24a01240@4ca3d6c4
by AffinityGroupAccessChecker
2023-09-04 14:53:15,820 DEBUG [c.c.u.AccountManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Access
granted to Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]
to com.cloud.storage.DiskOfferingVO$$EnhancerByCGLIB$$cd698f33@64fe404
by AffinityGroupAccessChecker
2023-09-04 14:53:16,073 INFO [c.c.v.UserVmManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) VM cannot
be configured to be dynamically scalable if any of the service
offering's dynamic scaling property, template's dynamic scaling property
or global setting is false
2023-09-04 14:53:16,078 DEBUG [c.c.v.UserVmManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab)
Rootdisksize override validation successful. Template root disk size
(1.13 GB) 1215168512 Root disk size specified 20 GB
2023-09-04 14:53:16,084 DEBUG [c.c.v.UserVmManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocating
in the DB for vm
2023-09-04 14:53:16,104 INFO [c.c.v.VirtualMachineManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) allocating
virtual machine from template:0b13fe5d-af8a-4247-b473-20fb19723a9a with
hostname:i-2-15-VM and 1 networks
2023-09-04 14:53:16,110 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocating
entries for VM: VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
2023-09-04 14:53:16,113 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocating
nics for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
2023-09-04 14:53:16,118 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocating
nic for vm VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
in network Network {"id": 213, "name": "defaultGuestNetwork", "uuid":
"1d3be879-f75b-4ba9-83e8-aa1bb32c858c", "networkofferingid": 7} with
requested profile NicProfile
{"broadcastUri":null,"iPv4Address":null,"id":0,"reservationId":null,"vmId":0}
2023-09-04 14:53:16,201 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocating
disks for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
2023-09-04 14:53:16,212 DEBUG [c.c.r.ResourceLimitManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78 ctx-d4ed4fa3)
(logid:550584ab) Updating resource Type = volume count for Account = 2
Operation = increasing Amount = 1
2023-09-04 14:53:16,218 DEBUG [c.c.r.ResourceLimitManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78 ctx-d4ed4fa3)
(logid:550584ab) Updating resource Type = primary_storage count for
Account = 2 Operation = increasing Amount = (20.00 GB) 21474836480
2023-09-04 14:53:16,232 DEBUG [c.c.v.VirtualMachineManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Allocation
completed for VM: VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
2023-09-04 14:53:16,232 DEBUG [c.c.v.UserVmManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab)
Successfully allocated DB entry for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
2023-09-04 14:53:16,236 DEBUG [c.c.r.ResourceLimitManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Updating
resource Type = user_vm count for Account = 2 Operation = increasing
Amount = 1
2023-09-04 14:53:16,244 DEBUG [c.c.r.ResourceLimitManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Updating
resource Type = cpu count for Account = 2 Operation = increasing Amount = 1
2023-09-04 14:53:16,250 DEBUG [c.c.r.ResourceLimitManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) Updating
resource Type = memory count for Account = 2 Operation = increasing
Amount = 1024
2023-09-04 14:53:16,529 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:99848ca6) Add job-121
into job monitoring
2023-09-04 14:53:16,532 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) submit
async job-121, details: AsyncJobVO: {id:121, userId: 2, accountId: 2,
instanceType: VirtualMachine, instanceId: 15, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"boottype":"BIOS","hostid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8","httpmethod":"GET","clusterid":"94385c60-5970-447c-926b-11653ac04a5a","templateid":"0b13fe5d-af8a-4247-b473-20fb19723a9a","securitygroupids":"3388fc57-4a57-11ee-acdf-08002737abca","ctxAccountId":"2","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf","cmdEventType":"VM.CREATE","diskofferingid":"961fd360-ca5e-4d2a-9813-cbd9eb392412","startvm":"true","bootmode":"LEGACY","serviceofferingid":"d13efba9-4f06-429c-a697-7a46a7c0f9b4","response":"json","ctxUserId":"2","hypervisor":"KVM","zoneid":"cd6b9366-3982-42be-b3b2-8c4361239e4f","ctxStartEventId":"299","id":"15","ctxDetails":"{\"interface
com.cloud.template.VirtualMachineTemplate\":\"0b13fe5d-af8a-4247-b473-20fb19723a9a\",\"interface
com.cloud.offering.DiskOffering\":\"961fd360-ca5e-4d2a-9813-cbd9eb392412\",\"interface
com.cloud.org.Cluster\":\"94385c60-5970-447c-926b-11653ac04a5a\",\"interface
com.cloud.dc.DataCenter\":\"cd6b9366-3982-42be-b3b2-8c4361239e4f\",\"interface
com.cloud.network.security.SecurityGroup\":\"3388fc57-4a57-11ee-acdf-08002737abca\",\"interface
com.cloud.host.Host\":\"7cad36ca-ddb9-404f-99ae-4f9f446138d8\",\"interface
com.cloud.dc.Pod\":\"97b8385b-baf9-4818-97b1-4ca141dcddce\",\"interface
com.cloud.offering.ServiceOffering\":\"d13efba9-4f06-429c-a697-7a46a7c0f9b4\",\"interface
com.cloud.vm.VirtualMachine\":\"55d71859-ae54-4e12-8de3-8f84fe9627bf\"}","podid":"97b8385b-baf9-4818-97b1-4ca141dcddce","affinitygroupids":"","keypairs":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 8796750982090, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2023-09-04 14:53:16,550 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Executing
AsyncJobVO: {id:121, userId: 2, accountId: 2, instanceType:
VirtualMachine, instanceId: 15, cmd:
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo:
{"boottype":"BIOS","hostid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8","httpmethod":"GET","clusterid":"94385c60-5970-447c-926b-11653ac04a5a","templateid":"0b13fe5d-af8a-4247-b473-20fb19723a9a","securitygroupids":"3388fc57-4a57-11ee-acdf-08002737abca","ctxAccountId":"2","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf","cmdEventType":"VM.CREATE","diskofferingid":"961fd360-ca5e-4d2a-9813-cbd9eb392412","startvm":"true","bootmode":"LEGACY","serviceofferingid":"d13efba9-4f06-429c-a697-7a46a7c0f9b4","response":"json","ctxUserId":"2","hypervisor":"KVM","zoneid":"cd6b9366-3982-42be-b3b2-8c4361239e4f","ctxStartEventId":"299","id":"15","ctxDetails":"{\"interface
com.cloud.template.VirtualMachineTemplate\":\"0b13fe5d-af8a-4247-b473-20fb19723a9a\",\"interface
com.cloud.offering.DiskOffering\":\"961fd360-ca5e-4d2a-9813-cbd9eb392412\",\"interface
com.cloud.org.Cluster\":\"94385c60-5970-447c-926b-11653ac04a5a\",\"interface
com.cloud.dc.DataCenter\":\"cd6b9366-3982-42be-b3b2-8c4361239e4f\",\"interface
com.cloud.network.security.SecurityGroup\":\"3388fc57-4a57-11ee-acdf-08002737abca\",\"interface
com.cloud.host.Host\":\"7cad36ca-ddb9-404f-99ae-4f9f446138d8\",\"interface
com.cloud.dc.Pod\":\"97b8385b-baf9-4818-97b1-4ca141dcddce\",\"interface
com.cloud.offering.ServiceOffering\":\"d13efba9-4f06-429c-a697-7a46a7c0f9b4\",\"interface
com.cloud.vm.VirtualMachine\":\"55d71859-ae54-4e12-8de3-8f84fe9627bf\"}","podid":"97b8385b-baf9-4818-97b1-4ca141dcddce","affinitygroupids":"","keypairs":""},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 8796750982090, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2023-09-04 14:53:16,551 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-d4b80649 ctx-698d5d78) (logid:550584ab) ===END===
10.66.10.22 -- GET
zoneid=cd6b9366-3982-42be-b3b2-8c4361239e4f&podid=97b8385b-baf9-4818-97b1-4ca141dcddce&clusterid=94385c60-5970-447c-926b-11653ac04a5a&hostid=7cad36ca-ddb9-404f-99ae-4f9f446138d8&boottype=BIOS&bootmode=LEGACY&templateid=0b13fe5d-af8a-4247-b473-20fb19723a9a&hypervisor=KVM&startvm=true&serviceofferingid=d13efba9-4f06-429c-a697-7a46a7c0f9b4&diskofferingid=961fd360-ca5e-4d2a-9813-cbd9eb392412&affinitygroupids=&securitygroupids=3388fc57-4a57-11ee-acdf-08002737abca&keypairs=&command=deployVirtualMachine&response=json
2023-09-04 14:53:16,587 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-48e107ba) (logid:d4b2ae71) ===START=== 10.66.10.22
-- GET
jobId=f67a3ec7-7399-4d25-9b4e-498867eb42a4&command=queryAsyncJobResult&response=json
2023-09-04 14:53:16,587 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-48e107ba) (logid:d4b2ae71) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:16,603 DEBUG [c.c.a.ApiServer]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:16,611 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:16,625 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [queryAsyncJobResult] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:16,628 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:16,634 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:16,795 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Destination Host to deploy the VM is specified, specifying a deployment
plan to deploy the VM
2023-09-04 14:53:16,803 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Host: 5 has cpu capability (cpu:4, speed:2400) to support requested CPU:
1 and requested speed: 1000
2023-09-04 14:53:16,803 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking if host: 5 has enough capacity for requested CPU: 1000 and
requested RAM: (1.00 GB) 1073741824 , cpuOverprovisioningFactor: 1.0
2023-09-04 14:53:16,808 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Hosts's actual total CPU: 9600 and CPU after applying overprovisioning: 9600
2023-09-04 14:53:16,808 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
considerReservedCapacity isfalse , not considering reserved capacity for
calculating free capacity
2023-09-04 14:53:16,808 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Free CPU: 8600 , Requested CPU: 1000
2023-09-04 14:53:16,809 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Free RAM: (1.07 GB) 1146843136 , Requested RAM: (1.00 GB) 1073741824
2023-09-04 14:53:16,809 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Host has enough CPU and RAM available
2023-09-04 14:53:16,809 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
STATS: Can alloc CPU from host: 5, used: 1000, reserved: 0, actual
total: 9600, total with overprovisioning: 9600; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: false
2023-09-04 14:53:16,809 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
STATS: Can alloc MEM from host: 5, used: (1.50 GB) 1610612736, reserved:
(0 bytes) 0, total: (2.57 GB) 2757455872; requested mem: (1.00 GB)
1073741824, alloc_from_last_host?: false , considerReservedCapacity?: false
2023-09-04 14:53:16,849 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-48e107ba ctx-2391aec5) (logid:d4b2ae71) ===END===
10.66.10.22 -- GET
jobId=f67a3ec7-7399-4d25-9b4e-498867eb42a4&command=queryAsyncJobResult&response=json
2023-09-04 14:53:16,862 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Adding pods to avoid lists for non-explicit VM deployment: []
2023-09-04 14:53:16,863 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Adding clusters to avoid lists for non-explicit VM deployment: []
2023-09-04 14:53:16,863 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Adding hosts to avoid lists for non-explicit VM deployment: []
2023-09-04 14:53:16,863 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
DeploymentPlanner allocation algorithm: null
2023-09-04 14:53:16,864 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Trying to allocate a host and storage pools from dc:3, pod:3,cluster:3,
requested cpu: 1000, requested ram: (1.00 GB) 1073741824
2023-09-04 14:53:16,864 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Is ROOT volume READY (pool already allocated)?: No
2023-09-04 14:53:16,883 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
DeploymentPlan has host_id specified, choosing this host: 5
2023-09-04 14:53:16,885 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Looking for suitable pools for this host under zone: 3, pod: 3, cluster: 3
2023-09-04 14:53:16,894 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking suitable pools for volume (Id, Type): (15,ROOT)
2023-09-04 14:53:16,894 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
We need to allocate new storagepool for this volume
2023-09-04 14:53:16,908 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Calling StoragePoolAllocators to find suitable pools
2023-09-04 14:53:16,911 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
LocalStoragePoolAllocator is returning null since the disk profile does
not use local storage and bypassStorageTypeCheck is false.
2023-09-04 14:53:16,911 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Looking for pools in dc [3], pod [3] and cluster [3]. Disabled pools
will be ignored.
2023-09-04 14:53:16,913 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Found pools [[]] that match with tags [[]].
2023-09-04 14:53:16,915 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
No storage pools available for [shared] volume allocation.
2023-09-04 14:53:16,923 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking if storage pool is suitable, name: primary ,poolId: 3
2023-09-04 14:53:16,926 INFO [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Storage pool primary (3) does not supply IOPS capacity, assuming enough
capacity
2023-09-04 14:53:16,928 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking pool 3 for storage, totalSize: 49917460480, usedBytes:
22645571584, usedPct: 0.4536603297972902, disable threshold: 0.85
2023-09-04 14:53:16,928 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Destination pool id: 3
2023-09-04 14:53:16,952 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Pool ID for the volume with ID 15 is null
2023-09-04 14:53:16,966 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Found storage pool primary of type NetworkFilesystem with
overprovisioning factor 2
2023-09-04 14:53:16,967 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Total over provisioned capacity calculated is 2 * (46.49 GB) 49917460480
2023-09-04 14:53:16,967 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Total capacity of the pool primary with ID 3 is (92.98 GB) 99834920960
2023-09-04 14:53:16,968 DEBUG [c.c.s.StorageManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking pool: 3 for storage allocation , maxSize : (92.98 GB)
99834920960, totalAllocatedSize : (192.08 KB) 196688, askingSize :
(20.00 GB) 21474836480, allocated disable threshold: 0.85
2023-09-04 14:53:16,968 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
ZoneWideStoragePoolAllocator is returning [1] suitable storage pools
[[{"name":"primary","uuid":"0079a325-0619-3307-95d6-fc8bc0493ff5"}]].
2023-09-04 14:53:16,975 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Volume encryption requirements are met by provided host Host
{"id":5,"name":"kvm","type":"Routing","uuid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8"}
2023-09-04 14:53:16,975 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Trying to find a potenial host and associated storage pools from the
suitable host/pool lists for this VM
2023-09-04 14:53:16,977 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Checking if host: 5 can access any suitable storage pool for volume: ROOT
2023-09-04 14:53:16,979 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Host: 5 can access pool: 3
2023-09-04 14:53:16,984 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Found a potential host id: 5 name: kvm and associated storage pools for
this VM
2023-09-04 14:53:16,986 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(3)-Pod(3)-Cluster(3)-Host(5)-Storage(Volume(15|ROOT-->Pool(3))]
2023-09-04 14:53:17,003 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
start parameter value of enterHardwareSetup == null during processing of
queued job
2023-09-04 14:53:17,023 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Sync job-122 execution on object VmWorkJobQueue.15
2023-09-04 14:53:17,301 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-6a9eef62) (logid:e37fa014) ===START=== 10.66.10.22
-- GET
resourceids=0b13fe5d-af8a-4247-b473-20fb19723a9a&resourcetype=template&command=listResourceIcon&response=json
2023-09-04 14:53:17,301 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-6a9eef62) (logid:e37fa014) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:17,302 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-81ded62c) (logid:f4f5887d) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:17,302 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-81ded62c) (logid:f4f5887d) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:17,312 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-2:ctx-8f9fd05a) (logid:5a99f4b3) HA health
check task is running...
2023-09-04 14:53:17,319 DEBUG [c.c.a.ApiServer]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:17,323 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:17,326 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:17,328 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:17,330 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:17,330 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:17,332 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:17,333 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listResourceIcon] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:17,335 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:17,336 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:17,338 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-6a9eef62 ctx-c463d569) (logid:e37fa014) ===END===
10.66.10.22 -- GET
resourceids=0b13fe5d-af8a-4247-b473-20fb19723a9a&resourcetype=template&command=listResourceIcon&response=json
2023-09-04 14:53:17,387 DEBUG [c.c.a.ApiServlet]
(qtp649329985-15:ctx-81ded62c ctx-f652ebb4) (logid:f4f5887d) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:17,685 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-6cc01119) (logid:c7182fe9) ===START=== 10.66.10.22
-- GET
resourceids=0b13fe5d-af8a-4247-b473-20fb19723a9a&resourcetype=iso&command=listResourceIcon&response=json
2023-09-04 14:53:17,686 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-6cc01119) (logid:c7182fe9) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:17,699 DEBUG [c.c.a.ApiServer]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:17,702 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:17,705 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listResourceIcon] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:17,706 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:17,708 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:17,710 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-6cc01119 ctx-3025aa30) (logid:c7182fe9) ===END===
10.66.10.22 -- GET
resourceids=0b13fe5d-af8a-4247-b473-20fb19723a9a&resourcetype=iso&command=listResourceIcon&response=json
2023-09-04 14:53:17,756 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-3cb2a03a) (logid:5498088a) ===START=== 10.66.10.22
-- GET
resourceids=cd6b9366-3982-42be-b3b2-8c4361239e4f&resourcetype=zone&command=listResourceIcon&response=json
2023-09-04 14:53:17,756 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-3cb2a03a) (logid:5498088a) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:17,769 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:17,773 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:17,778 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listResourceIcon] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:17,780 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:17,781 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:17,785 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-3cb2a03a ctx-eb13701c) (logid:5498088a) ===END===
10.66.10.22 -- GET
resourceids=cd6b9366-3982-42be-b3b2-8c4361239e4f&resourcetype=zone&command=listResourceIcon&response=json
2023-09-04 14:53:18,339 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-979662ea) (logid:f124e938) Execute
sync-queue item: SyncQueueItemVO {id:49, queueId: 49, contentType:
AsyncJob, contentId: 122, lastProcessMsid: 8796750982090,
lastprocessNumber: 1, lastProcessTime: Mon Sep 04 14:53:18 BDT 2023,
created: Mon Sep 04 14:53:17 BDT 2023}
2023-09-04 14:53:18,342 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-979662ea) (logid:f124e938) Schedule queued
job-122
2023-09-04 14:53:18,361 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:0f0db085) Add
job-122 into job monitoring
2023-09-04 14:53:18,377 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Executing AsyncJobVO: {id:122, userId: 2, accountId: 2, instanceType:
null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAD3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAA3BzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAANzcQB-AAgAAAAAAAAABXBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 8796750982090, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Sep 04 14:53:17 BDT 2023, removed:
null}
2023-09-04 14:53:18,378 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7) Run
VM work job: com.cloud.vm.VmWorkStart for VM 15, job origin: 121
2023-09-04 14:53:18,384 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":3,"podId":3,"clusterId":3,"hostId":5,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":15,"handlerName":"VirtualMachineManagerImpl"}
2023-09-04 14:53:18,386 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) orchestrating VM start for 'i-2-15-VM'
com.cloud.vm.VirtualMachineProfile$Param@b66cdd7d set to null
2023-09-04 14:53:18,405 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
state transited from [Stopped] to [Starting] with event
[StartRequested]. VM's original host: null, new host: null, host before
state transition: null
2023-09-04 14:53:18,406 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Successfully transitioned to start state for VM
instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
reservation id = 260f06c2-cd9e-4cc4-bd43-4bf0f1747e8d
2023-09-04 14:53:18,432 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) advanceStart: DeploymentPlan is provided, using dcId:3,
podId: 3, clusterId: 3, hostId: 5, poolId: null
2023-09-04 14:53:18,436 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Deploy avoids pods: null, clusters: null, hosts: null
2023-09-04 14:53:18,439 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM start attempt #1
2023-09-04 14:53:18,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding pods to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:18,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding clusters to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:18,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding hosts to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:18,459 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) DeploymentPlanner allocation algorithm: null
2023-09-04 14:53:18,460 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Trying to allocate a host and storage pools from dc:3,
pod:3,cluster:3, requested cpu: 1000, requested ram: (1.00 GB) 1073741824
2023-09-04 14:53:18,460 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Is ROOT volume READY (pool already allocated)?: No
2023-09-04 14:53:18,472 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) DeploymentPlan has host_id specified, choosing this host: 5
2023-09-04 14:53:18,477 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Looking for suitable pools for this host under zone: 3,
pod: 3, cluster: 3
2023-09-04 14:53:18,483 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking suitable pools for volume (Id, Type): (15,ROOT)
2023-09-04 14:53:18,483 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) We need to allocate new storagepool for this volume
2023-09-04 14:53:18,484 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Calling StoragePoolAllocators to find suitable pools
2023-09-04 14:53:18,486 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) LocalStoragePoolAllocator is returning null since the
disk profile does not use local storage and bypassStorageTypeCheck is false.
2023-09-04 14:53:18,487 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Looking for pools in dc [3], pod [3] and cluster [3].
Disabled pools will be ignored.
2023-09-04 14:53:18,489 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Found pools [[]] that match with tags [[]].
2023-09-04 14:53:18,491 DEBUG
[o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) No storage pools available for [shared] volume allocation.
2023-09-04 14:53:18,498 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking if storage pool is suitable, name: primary
,poolId: 3
2023-09-04 14:53:18,500 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Storage pool primary (3) does not supply IOPS capacity,
assuming enough capacity
2023-09-04 14:53:18,504 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking pool 3 for storage, totalSize: 49917460480,
usedBytes: 22645571584, usedPct: 0.4536603297972902, disable threshold: 0.85
2023-09-04 14:53:18,504 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Destination pool id: 3
2023-09-04 14:53:18,520 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Pool ID for the volume with ID 15 is null
2023-09-04 14:53:18,528 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Found storage pool primary of type NetworkFilesystem
with overprovisioning factor 2
2023-09-04 14:53:18,528 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Total over provisioned capacity calculated is 2 *
(46.49 GB) 49917460480
2023-09-04 14:53:18,528 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Total capacity of the pool primary with ID 3 is (92.98
GB) 99834920960
2023-09-04 14:53:18,529 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking pool: 3 for storage allocation , maxSize :
(92.98 GB) 99834920960, totalAllocatedSize : (192.08 KB) 196688,
askingSize : (20.00 GB) 21474836480, allocated disable threshold: 0.85
2023-09-04 14:53:18,529 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) ZoneWideStoragePoolAllocator is returning [1] suitable
storage pools
[[{"name":"primary","uuid":"0079a325-0619-3307-95d6-fc8bc0493ff5"}]].
2023-09-04 14:53:18,534 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Volume encryption requirements are met by provided host
Host
{"id":5,"name":"kvm","type":"Routing","uuid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8"}
2023-09-04 14:53:18,534 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2023-09-04 14:53:18,536 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking if host: 5 can access any suitable storage
pool for volume: ROOT
2023-09-04 14:53:18,537 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Host: 5 can access pool: 3
2023-09-04 14:53:18,541 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Found a potential host id: 5 name: kvm and associated
storage pools for this VM
2023-09-04 14:53:18,543 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(3)-Pod(3)-Cluster(3)-Host(5)-Storage(Volume(15|ROOT-->Pool(3))]
2023-09-04 14:53:18,545 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Deployment found - Attempt #1 - P0=VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"},
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(3)-Pod(3)-Cluster(3)-Host(5)-Storage(Volume(15|ROOT-->Pool(3))]
2023-09-04 14:53:18,569 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
state transited from [Starting] to [Starting] with event
[OperationRetry]. VM's original host: null, new host: Host
{"id":5,"name":"kvm","type":"Routing","uuid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8"},
host before state transition: null
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Hosts's actual total CPU: 9600 and CPU after applying
overprovisioning: 9600
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) We are allocating VM, increasing the used capacity of
this host:5
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Current Used CPU: 1000 , Free CPU:8600 ,Requested CPU: 1000
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Current Used RAM: (1.50 GB) 1610612736 , Free RAM:(1.07
GB) 1146843136 ,Requested RAM: (1.00 GB) 1073741824
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) CPU STATS after allocation: for host: 5, old used:
1000, old reserved: 0, actual total: 9600, total with overprovisioning:
9600; new used:2000, reserved:0; requested cpu:1000,alloc_from_last:false
2023-09-04 14:53:18,584 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) RAM STATS after allocation: for host: 5, old used:
(1.50 GB) 1610612736, old reserved: (0 bytes) 0, total: (2.57 GB)
2757455872; new used: (2.50 GB) 2684354560, reserved: (0 bytes) 0;
requested mem: (1.00 GB) 1073741824,alloc_from_last:false
2023-09-04 14:53:18,588 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Host: 5 has cpu capability (cpu:4, speed:2400) to
support requested CPU: 1 and requested speed: 1000
2023-09-04 14:53:18,588 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking if host: 5 has enough capacity for requested
CPU: 1000 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Hosts's actual total CPU: 9600 and CPU after applying
overprovisioning: 9600
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) We need to allocate to the last host again, so checking
if there is enough reserved capacity
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Reserved CPU: 0 , Requested CPU: 1000
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Reserved RAM: (0 bytes) 0 , Requested RAM: (1.00 GB)
1073741824
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) STATS: Failed to alloc resource from host: 5
reservedCpu: 0, requested cpu: 1000, reservedMem: (0 bytes) 0, requested
mem: (1.00 GB) 1073741824
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Host does not have enough reserved CPU available,
cannot allocate to this host.
2023-09-04 14:53:18,590 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Checking if host: 5 has enough capacity for requested
CPU: 1000 and requested RAM: (1.00 GB) 1073741824 ,
cpuOverprovisioningFactor: 1.0
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Hosts's actual total CPU: 9600 and CPU after applying
overprovisioning: 9600
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Free CPU: 8600 , Requested CPU: 1000
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Free RAM: (1.07 GB) 1146843136 , Requested RAM: (1.00
GB) 1073741824
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Host has enough CPU and RAM available
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) STATS: Can alloc CPU from host: 5, used: 1000,
reserved: 0, actual total: 9600, total with overprovisioning: 9600;
requested cpu:1000,alloc_from_last_host?:false
,considerReservedCapacity?: true
2023-09-04 14:53:18,595 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) STATS: Can alloc MEM from host: 5, used: (1.50 GB)
1610612736, reserved: (0 bytes) 0, total: (2.57 GB) 2757455872;
requested mem: (1.00 GB) 1073741824, alloc_from_last_host?: false ,
considerReservedCapacity?: true
2023-09-04 14:53:18,623 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Network id=213 is already implemented
2023-09-04 14:53:18,688 DEBUG [c.c.n.g.DirectPodBasedNetworkGuru]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) No IPv6 CIDR configured for VLAN 2
2023-09-04 14:53:18,705 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Changing active number of nics for network id=213 on 1
2023-09-04 14:53:18,728 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Asking SecurityGroupProvider to prepare for
Nic[25-15-260f06c2-cd9e-4cc4-bd43-4bf0f1747e8d-10.66.10.77]
2023-09-04 14:53:18,743 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Asking VirtualRouter to prepare for
Nic[25-15-260f06c2-cd9e-4cc4-bd43-4bf0f1747e8d-10.66.10.77]
2023-09-04 14:53:18,761 DEBUG [c.c.n.r.NetworkHelperImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Starting router VM instance
{"id":12,"instanceName":"r-12-VM","type":"DomainRouter","uuid":"6cb1a13f-c23e-4ba3-90dd-9dcafb186b01"}
2023-09-04 14:53:18,761 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) start parameter value of enterHardwareSetup == null
during dispatching
2023-09-04 14:53:18,793 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":12,"instanceName":"r-12-VM","type":"DomainRouter","uuid":"6cb1a13f-c23e-4ba3-90dd-9dcafb186b01"}
state transited from [Stopped] to [Starting] with event
[StartRequested]. VM's original host: null, new host: null, host before
state transition: null
2023-09-04 14:53:18,793 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Successfully transitioned to start state for VM
instance
{"id":12,"instanceName":"r-12-VM","type":"DomainRouter","uuid":"6cb1a13f-c23e-4ba3-90dd-9dcafb186b01"}
reservation id = f47c490c-b704-4019-93c7-36dd64bae751
2023-09-04 14:53:18,834 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Deploy avoids pods: null, clusters: null, hosts: null
2023-09-04 14:53:18,838 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM start attempt #1
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding pods to avoid lists: []
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding clusters to avoid lists: []
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding hosts to avoid lists: []
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) DeploymentPlanner allocation algorithm: null
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Trying to allocate a host and storage pools from dc:3,
pod:3,cluster:null, requested cpu: 500, requested ram: (256.00 MB) 268435456
2023-09-04 14:53:18,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Is ROOT volume READY (pool already allocated)?: No
2023-09-04 14:53:18,871 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Deploy avoids pods: [], clusters: [], hosts: []
2023-09-04 14:53:18,871 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Deploy hosts with priorities {} , hosts have NORMAL
priority by default
2023-09-04 14:53:18,873 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Searching resources only under specified Pod: 3
2023-09-04 14:53:18,878 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Listing clusters in order of aggregate capacity, that
have (at least one host with) enough CPU and RAM capacity under this Pod: 3
2023-09-04 14:53:18,883 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) No clusters found having a host with enough capacity,
returning.
2023-09-04 14:53:18,927 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":12,"instanceName":"r-12-VM","type":"DomainRouter","uuid":"6cb1a13f-c23e-4ba3-90dd-9dcafb186b01"}
state transited from [Starting] to [Stopped] with event
[OperationFailed]. VM's original host: null, new host: null, host before
state transition: null
2023-09-04 14:53:18,941 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Insufficient capacity
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance
{"id":12,"instanceName":"r-12-VM","type":"DomainRouter","uuid":"6cb1a13f-c23e-4ba3-90dd-9dcafb186b01"}Scope=interface
com.cloud.dc.DataCenter; id=3
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1166)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:991)
at
com.cloud.network.router.NetworkHelperImpl.start(NetworkHelperImpl.java:315)
at
com.cloud.network.router.NetworkHelperImpl.startVirtualRouter(NetworkHelperImpl.java:394)
at
com.cloud.network.router.NetworkHelperImpl.startRouters(NetworkHelperImpl.java:379)
at
org.apache.cloudstack.network.router.deployment.RouterDeploymentDefinition.deployVirtualRouter(RouterDeploymentDefinition.java:209)
at
com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:283)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1703)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:2064)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1991)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1203)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5351)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5475)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2023-09-04 14:53:18,952 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Cleaning up resources for the vm VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
in Starting state
2023-09-04 14:53:18,966 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
is a [User], returning null for control Nic IP.
2023-09-04 14:53:18,973 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Seq 5-7256706374577422557: Sending { Cmd , MgmtId:
8796750982090, via: 5(kvm), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":"false","checkBeforeCleanup":"false","forceStop":"false","vlanToPersistenceMap":{"untagged":"true"},"volumesToDisconnect":[],"vmName":"i-2-15-VM","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}]
}
2023-09-04 14:53:19,243 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-15:null) (logid:) Seq 5-7256706374577422557:
Processing: { Ans: , MgmtId: 8796750982090, via: 5, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2023-09-04 14:53:19,243 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Seq 5-7256706374577422557: Received: { Ans: , MgmtId:
8796750982090, via: 5(kvm), Ver: v1, Flags: 10, { StopAnswer } }
2023-09-04 14:53:19,271 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Changing active number of nics for network id=213 on -1
2023-09-04 14:53:19,310 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Asking SecurityGroupProvider to release NicProfile
{"broadcastUri":"vlan:\/\/untagged","iPv4Address":"10.66.10.77","id":25,"reservationId":"260f06c2-cd9e-4cc4-bd43-4bf0f1747e8d","vmId":15}
2023-09-04 14:53:19,311 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Asking VirtualRouter to release NicProfile
{"broadcastUri":"vlan:\/\/untagged","iPv4Address":"10.66.10.77","id":25,"reservationId":"260f06c2-cd9e-4cc4-bd43-4bf0f1747e8d","vmId":15}
2023-09-04 14:53:19,311 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Successfully released network resources for the VM VM
instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
in Starting state
2023-09-04 14:53:19,317 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Successfully released storage resources for the VM VM
instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
in Starting state
2023-09-04 14:53:19,317 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Successfully cleaned up resources for the VM VM
instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
in Starting state
2023-09-04 14:53:19,319 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM start attempt #2
2023-09-04 14:53:19,337 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding pods to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:19,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding clusters to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:19,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Adding hosts to avoid lists for non-explicit VM
deployment: []
2023-09-04 14:53:19,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) DeploymentPlanner allocation algorithm: null
2023-09-04 14:53:19,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Trying to allocate a host and storage pools from dc:3,
pod:3,cluster:3, requested cpu: 1000, requested ram: (1.00 GB) 1073741824
2023-09-04 14:53:19,338 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Is ROOT volume READY (pool already allocated)?: No
2023-09-04 14:53:19,350 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) DeploymentPlan has host_id specified, choosing this host: 5
2023-09-04 14:53:19,352 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) The specified host is in avoid set
2023-09-04 14:53:19,352 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Cannot deploy to specified host, returning.
2023-09-04 14:53:19,399 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
state transited from [Starting] to [Stopped] with event
[OperationFailed]. VM's original host: null, new host: null, host before
state transition: Host
{"id":5,"name":"kvm","type":"Routing","uuid":"7cad36ca-ddb9-404f-99ae-4f9f446138d8"}
2023-09-04 14:53:19,412 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Hosts's actual total CPU: 9600 and CPU after applying
overprovisioning: 9600
2023-09-04 14:53:19,412 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Hosts's actual total RAM: (2.57 GB) 2757455872 and RAM
after applying overprovisioning: (2.57 GB) 2757455872
2023-09-04 14:53:19,412 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) release cpu from host: 5, old used: 2000,reserved: 0,
actual total: 9600, total with overprovisioning: 9600; new used:
1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2023-09-04 14:53:19,412 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) release mem from host: 5, old used: (2.50 GB)
2684354560,reserved: (0 bytes) 0, total: (2.57 GB) 2757455872; new used:
(1.50 GB) 1610612736,reserved:(0 bytes) 0; movedfromreserved:
false,moveToReserveredfalse
2023-09-04 14:53:19,448 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Invocation exception, caused by:
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}Scope=interface
com.cloud.dc.DataCenter; id=3
2023-09-04 14:53:19,448 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122 ctx-7d522cd7)
(logid:f67a3ec7) Rethrow exception
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}Scope=interface
com.cloud.dc.DataCenter; id=3
2023-09-04 14:53:19,448 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 15, job
origin: 121
2023-09-04 14:53:19,448 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Unable to complete AsyncJobVO: {id:122, userId: 2, accountId: 2,
instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart,
cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAD3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAA3BzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAANzcQB-AAgAAAAAAAAABXBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 8796750982090, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Sep 04 14:53:17 BDT 2023, removed:
null}, job origin:121
com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}Scope=interface
com.cloud.dc.DataCenter; id=3
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1166)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5351)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5475)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2023-09-04 14:53:19,460 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Complete async job-122, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uAAAAAFZNT3ACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvbgAAAABWTU91AgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACOVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjE1LCJpbnN0YW5jZU5hbWUiOiJpLTItMTUtVk0iLCJ0eXBlIjoiVXNlciIsInV1aWQiOiI1NWQ3MTg1OS1hZTU0LTRlMTItOGRlMy04Zjg0ZmU5NjI3YmYifXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFXNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACkwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKTAAKbW9kdWxlTmFtZXEAfgAKTAANbW9kdWxlVmVyc2lvbnEAfgAKeHABAAAEjnQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgARAQAAFOdxAH4AE3EAfgAUcQB-ABVxAH4AFnBwc3EAfgARAv____5wdAAtamRrLmludGVybmFsLnJlZmxlY3QuTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsdAAdTmF0aXZlTWV0aG9kQWNjZXNzb3JJbXBsLmphdmF0AAdpbnZva2UwdAAJamF2YS5iYXNldAAHMTEuMC4yMHNxAH4AEQIAAAA-cHEAfgAZcQB-ABp0AAZpbnZva2VxAH4AHHEAfgAdc3EAfgARAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAfcQB-ABxxAH4AHXNxAH4AEQIAAAI2cHQAGGphdmEubGFuZy5yZWZsZWN0Lk1ldGhvZHQAC01ldGhvZC5qYXZhcQB-AB9xAH4AHHEAfgAdc3EAfgARAQAAAGtxAH4AE3QAImNvbS5jbG91ZC52bS5WbVdvcmtKb2JIYW5kbGVyUHJveHl0ABpWbVdvcmtKb2JIYW5kbGVyUHJveHkuamF2YXQAD2hhbmRsZVZtV29ya0pvYnBwc3EAfgARAQAAFWNxAH4AE3EAfgAUcQB-ABVxAH4AKXBwc3EAfgARAQAAAGZxAH4AE3QAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-ABEBAAACbHEAfgATdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-ABEBAAAAMHEAfgATdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4AEQEAAAA3cQB-ABN0AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4AEQEAAABmcQB-ABN0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ADl0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4AEQEAAAA0cQB-ABNxAH4APHEAfgA5dAAOcnVuV2l0aENvbnRleHRwcHNxAH4AEQEAAAAtcQB-ABN0ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4ANXEAfgA2cHBzcQB-ABEBAAACOHEAfgATcQB-ADBxAH4AMXEAfgA2cHBzcQB-ABECAAACA3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AOnEAfgAccQB-AB1zcQB-ABECAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAABGhwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AHHEAfgAdc3EAfgARAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBLcQB-ADZxAH4AHHEAfgAdc3EAfgARAgAAAz1wdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-ADZxAH4AHHEAfgAdc3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweHNyABFqYXZhLmxhbmcuSW50ZWdlchLioKT3gYc4AgABSQAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAABDvc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4c3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhxAH4AVQAAAAAAAAADdnIAF2NvbS5jbG91ZC5kYy5EYXRhQ2VudGVyEFBUbQNFHgACAAB4cAA
2023-09-04 14:53:19,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Publish async job-122 complete on message bus
2023-09-04 14:53:19,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Wake up jobs related to job-122
2023-09-04 14:53:19,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Update db status for job-122
2023-09-04 14:53:19,472 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Wake up jobs joined with job-122 and disjoin all subjobs created from
job- 122
2023-09-04 14:53:19,492 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Done executing com.cloud.vm.VmWorkStart for job-122
2023-09-04 14:53:19,496 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-49:ctx-c8a359da job-121/job-122) (logid:f67a3ec7)
Remove job-122 from job monitoring
2023-09-04 14:53:19,526 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Destroying vm VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
as it failed to create on Host with Id:5
2023-09-04 14:53:19,567 DEBUG [c.c.c.CapacityManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}
state transited from [Stopped] to [Error] with event
[OperationFailedToError]. VM's original host: null, new host: null, host
before state transition: null
2023-09-04 14:53:19,570 DEBUG [c.c.s.d.VolumeDaoImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Removing volume 15 from DB
2023-09-04 14:53:19,596 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Updating resource Type = volume count for Account = 2 Operation =
decreasing Amount = 1
2023-09-04 14:53:19,609 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Updating resource Type = primary_storage count for Account = 2 Operation
= decreasing Amount = (20.00 GB) 21474836480
2023-09-04 14:53:19,637 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
alertType=[8] dataCenterId=[3] podId=[3] clusterId=[null]
message=[Failed to deploy Vm with Id: 15, on Host with Id: 5].
2023-09-04 14:53:19,648 WARN [c.c.a.AlertManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
No recipients set in global setting 'alert.email.addresses', skipping
sending alert with subject [Failed to deploy Vm with Id: 15, on Host
with Id: 5] and content [Failed to deploy Vm with Id: 15, on Host with
Id: 5].
2023-09-04 14:53:19,652 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Updating resource Type = user_vm count for Account = 2 Operation =
decreasing Amount = 1
2023-09-04 14:53:19,665 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-cc75ea40) (logid:b1357e22) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,665 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-cc75ea40) (logid:b1357e22) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:19,676 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Updating resource Type = cpu count for Account = 2 Operation =
decreasing Amount = 1
2023-09-04 14:53:19,681 DEBUG [c.c.a.ApiServer]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:19,702 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:19,707 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:19,712 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:19,713 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:19,717 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121 ctx-20a6ca68) (logid:f67a3ec7)
Updating resource Type = memory count for Account = 2 Operation =
decreasing Amount = 1024
2023-09-04 14:53:19,756 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM
[55d71859-ae54-4e12-8de3-8f84fe9627bf] due to [Unable to create a
deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}].
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:822)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:246)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5370)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5220)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4845)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4834)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at
org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at
com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:52)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at com.sun.proxy.$Proxy185.startVirtualMachine(Unknown Source)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:772)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:163)
at
com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:106)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at
java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}Scope=interface
com.cloud.dc.DataCenter; id=3
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1166)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5351)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
... 18 more
2023-09-04 14:53:19,760 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-cc75ea40 ctx-30495d59) (logid:b1357e22) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,766 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-b60b8768) (logid:a0b6ca8c) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,766 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-b60b8768) (logid:a0b6ca8c) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:19,770 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Complete
async job-121, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable
to start a VM [55d71859-ae54-4e12-8de3-8f84fe9627bf] due to [Unable to
create a deployment for VM instance
{"id":15,"instanceName":"i-2-15-VM","type":"User","uuid":"55d71859-ae54-4e12-8de3-8f84fe9627bf"}]."}
2023-09-04 14:53:19,774 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Publish
async job-121 complete on message bus
2023-09-04 14:53:19,777 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Wake up jobs
related to job-121
2023-09-04 14:53:19,778 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Update db
status for job-121
2023-09-04 14:53:19,780 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Wake up jobs
joined with job-121 and disjoin all subjobs created from job- 121
2023-09-04 14:53:19,786 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:19,794 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:19,797 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:19,799 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:19,800 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:19,801 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Done
executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin
for job-121
2023-09-04 14:53:19,801 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-50:ctx-b4026366 job-121) (logid:f67a3ec7) Remove
job-121 from job monitoring
2023-09-04 14:53:19,840 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-b60b8768 ctx-ca2428f1) (logid:a0b6ca8c) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,848 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-b3fd5643) (logid:81605c11) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,848 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-b3fd5643) (logid:81605c11) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:19,865 DEBUG [c.c.a.ApiServer]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:19,870 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:19,873 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:19,878 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:19,879 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:19,929 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-b3fd5643 ctx-817ae892) (logid:81605c11) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,932 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-eccb2e5c) (logid:b43caa4b) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:19,932 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-eccb2e5c) (logid:b43caa4b) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:19,944 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:19,948 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:19,950 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:19,952 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:19,953 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:19,996 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-eccb2e5c ctx-e0d1e37c) (logid:b43caa4b) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:20,000 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-62bdee63) (logid:73af78f3) ===START=== 10.66.10.22
-- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:20,000 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-62bdee63) (logid:73af78f3) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:20,017 DEBUG [c.c.a.ApiServer]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:20,021 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:20,023 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [listVirtualMachinesMetrics] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:20,027 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) RoleService
is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:20,028 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:20,063 DEBUG [c.c.a.ApiServlet]
(qtp649329985-21:ctx-62bdee63 ctx-e27c1c1e) (logid:73af78f3) ===END===
10.66.10.22 -- GET
listall=true&page=1&pagesize=20&showIcon=true&command=listVirtualMachinesMetrics&response=json
2023-09-04 14:53:20,378 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-1f7eb993) (logid:6b99905f) ===START=== 10.66.10.22
-- GET
jobId=f67a3ec7-7399-4d25-9b4e-498867eb42a4&command=queryAsyncJobResult&response=json
2023-09-04 14:53:20,378 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-1f7eb993) (logid:6b99905f) Two factor
authentication is already verified for the user 2, so skipping
2023-09-04 14:53:20,388 DEBUG [c.c.a.ApiServer]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f) CIDRs from
which account 'Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]'
is allowed to perform API calls: 0.0.0.0/0,::/0
2023-09-04 14:53:20,393 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f) Account
[Account
[{"accountName":"admin","id":2,"uuid":"33862365-4a57-11ee-acdf-08002737abca"}]]
is Root Admin or Domain Admin, all APIs are allowed.
2023-09-04 14:53:20,396 WARN [o.a.c.a.ProjectRoleBasedApiAccessChecker]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f) Project is
null, ProjectRoleBasedApiAccessChecker only applies to projects,
returning API [queryAsyncJobResult] for user [User
{"username":"admin","uuid":"33884ade-4a57-11ee-acdf-08002737abca"}.] as
allowed.
2023-09-04 14:53:20,399 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f)
RoleService is enabled. We will use it instead of
StaticRoleBasedAPIAccessChecker.
2023-09-04 14:53:20,400 DEBUG [o.a.c.r.ApiRateLimitServiceImpl]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f) API rate
limiting is disabled. We will not use ApiRateLimitService.
2023-09-04 14:53:20,422 DEBUG [c.c.a.ApiServlet]
(qtp649329985-505:ctx-1f7eb993 ctx-6b139c1c) (logid:6b99905f) ===END===
10.66.10.22 -- GET
jobId=f67a3ec7-7399-4d25-9b4e-498867eb42a4&command=queryAsyncJobResult&response=json
2023-09-04 14:53:21,314 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-4:ctx-a531b78c) (logid:101f9878) HA health
check task is running...
2023-09-04 14:53:21,553 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) (logid:) SeqA 6-462: Processing Seq
6-462: { Cmd , MgmtId: -1, via: 6, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"9","_loadInfo":"{
"connections": [],
"removedSessions": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2023-09-04 14:53:21,567 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) (logid:) SeqA 6-462: Sending Seq 6-462:
{ Ans: , MgmtId: 8796750982090, via: 6, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
+++++++++++++++++++++++++++++++
--
*Thanks & Regards.*
*Support Admin*
------------------------------------------------------------------------
*Facebook <https://www.facebook.com/TechnologyRSS> | Twitter
<https://twitter.com/technologyrss1> | YouTube
<https://www.youtube.com/channel/UCBq7qGqFEUe6ObVHMuxudTw> | LinkedIn
<https://www.linkedin.com/company/technologyrss/>*
*Address : *116/1 West Malibagh, D. I. T Road
Dhaka-1217, Bangladesh
*Mob :* +88 01716915504
*Email :* support.ad...@technologyrss.com
*Web :* www.technologyrss.com
