andrijapanicsb opened a new issue #4517:
URL: https://github.com/apache/cloudstack/issues/4517
ACS 4.14.0.0 (VMware, but irrelevant)
Trying to deploy VPC (VR), the userdispersing heuristic is choosing one of
the clusters that have at least one host with available capacities - the chosen
cluster has 2 hosts host. After it fails to deploy VR on the first chosen host
due to lack of capacities, it completely fails the job, instead of retrying on
the other host in that cluster that DOES have capacity.
Assuming I don't have any special special, this is very, very bad - have not
tested on user VMs.
Logs below (on this mgmt server, we were experimenting with splitting INFO
vs rest of the logs/DEBUG - so I'm pasting 2 separate sections just for
completenes - otherwise DEBUG logs alone should be enough
Weird thing is that I don't see the usual "requested XXX CPU, does it have
it, yes; requesting YYY RAM, does it have it..." etc
> 2020-12-03 18:21:53,912 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:9fcabb69) Add job-1568832
into job monitoring
2020-12-03 18:21:54,660 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:5187e69e)
Add job-1568833 into job monitoring
2020-12-03 18:21:54,696 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Uefi params UefiFlag: null Boot Type: null Boot Mode: null
2020-12-03 18:21:54,747 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Storage pool null (2) does not supply IOPS capacity, assuming
enough capacity
2020-12-03 18:21:54,916 ERROR [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Exception allocating VM capacity
2020-12-03 18:21:54,963 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Caught CloudRuntimeException, returning job failed
com.cloud.utils.exception.CloudRuntimeException: Host does not have enough
capacity for vm 50516
2020-12-03 18:21:54,999 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Remove job-1568833 from job monitoring
2020-12-03 18:21:55,014 WARN [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Failed to start vpc [VPC [13-andrija-swisstxt-VPC2] due to
2020-12-03 18:21:56,657 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:8efcf05c)
Add job-1568834 into job monitoring
2020-12-03 18:21:56,701 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Remove job-1568834 from job monitoring
2020-12-03 18:21:56,826 INFO [o.a.c.s.v.VolumeServiceImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Expunge volume with no data store specified
2020-12-03 18:21:56,829 INFO [o.a.c.s.v.VolumeServiceImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Volume 51108 is not referred anywhere, remove it from volumes table
2020-12-03 18:21:56,980 WARN [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Successfully destroyed vpc [VPC [13-andrija-swisstxt-VPC2] that failed to start
2020-12-03 18:21:56,992 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Remove
job-1568832 from job monitoring
> 2020-12-03 18:21:53,912 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:9fcabb69) Add job-1568832
into job monitoring
2020-12-03 18:21:53,916 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp869601985-807140:ctx-cd05fc2a ctx-ae03f83a) (logid:27c180ae) submit async
job-1568832, details: AsyncJobVO {id:1568832, userId: 2, accountId: 2,
instanceType: None, instanceId: 13, cmd:
org.apache.cloudstack.api.command.admin.vpc.CreateVPCCmdByAdmin, cmdInfo:
{"httpmethod":"GET","ctxAccountId":"2","uuid":"2e99aade-472a-4aa6-9e54-28baf4df847c","cmdEventType":"VPC.CREATE","vpcofferingid":"9b3f121d-2f44-4414-bd64-8fc8be9a1a51","displaytext":"andrija-swisstxt-VPC2","response":"json","ctxUserId":"2","name":"andrija-swisstxt-VPC2","zoneid":"c852110c-e1b5-4c8c-9e3d-f2a6e76b8fc0","cidr":"10.0.0.0/8","ctxStartEventId":"1849529","id":"13","ctxDetails":"{\"interface
com.cloud.network.vpc.Vpc\":\"2e99aade-472a-4aa6-9e54-28baf4df847c\",\"interface
com.cloud.dc.DataCenter\":\"c852110c-e1b5-4c8c-9e3d-f2a6e76b8fc0\",\"interface
com.cloud.network.vpc.VpcOffering\":\"9b3f121d-2f44-4414-bd64-8fc8be9a1a51\"}","_":"1607019296306"},
cm
dVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 52237721781, completeMsid: null, lastUpdated: null, lastPolled:
null, created: null, removed: null}
2020-12-03 18:21:53,916 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Executing
AsyncJobVO {id:1568832, userId: 2, accountId: 2, instanceType: None,
instanceId: 13, cmd:
org.apache.cloudstack.api.command.admin.vpc.CreateVPCCmdByAdmin, cmdInfo:
{"httpmethod":"GET","ctxAccountId":"2","uuid":"2e99aade-472a-4aa6-9e54-28baf4df847c","cmdEventType":"VPC.CREATE","vpcofferingid":"9b3f121d-2f44-4414-bd64-8fc8be9a1a51","displaytext":"andrija-swisstxt-VPC2","response":"json","ctxUserId":"2","name":"andrija-swisstxt-VPC2","zoneid":"c852110c-e1b5-4c8c-9e3d-f2a6e76b8fc0","cidr":"10.0.0.0/8","ctxStartEventId":"1849529","id":"13","ctxDetails":"{\"interface
com.cloud.network.vpc.Vpc\":\"2e99aade-472a-4aa6-9e54-28baf4df847c\",\"interface
com.cloud.dc.DataCenter\":\"c852110c-e1b5-4c8c-9e3d-f2a6e76b8fc0\",\"interface
com.cloud.network.vpc.VpcOffering\":\"9b3f121d-2f44-4414-bd64-8fc8be9a1a51\"}","_":"1607019296306"},
cmdVersion: 0, status: IN_PR
OGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52237721781,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null,
removed: null}
2020-12-03 18:21:53,968 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
lock account 2 is acquired
2020-12-03 18:21:53,990 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Updating resource Type = public_ip count for Account = 2 Operation = increasing
Amount = 1
2020-12-03 18:21:54,004 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing lock account 2
2020-12-03 18:21:54,028 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating the VR with id=50516 in datacenter
com.cloud.dc.DataCenterVO$$EnhancerByCGLIB$$5ead9b9f@1 with the hypervisor type
VMware
2020-12-03 18:21:54,043 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Adding nic for Virtual Router in Control network
2020-12-03 18:21:54,052 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Found existing network configuration for offering [Network Offering
[3-Control-System-Control-Network]: Ntwk[202|Control|3]
2020-12-03 18:21:54,052 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing lock for Acct[17f520c4-6a9d-11e6-8ec0-0050568ef122-system]
2020-12-03 18:21:54,061 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Adding nic for Virtual Router in Public network
2020-12-03 18:21:54,070 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Found existing network configuration for offering [Network Offering
[1-Public-System-Public-Network]: Ntwk[200|Public|1]
2020-12-03 18:21:54,070 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing lock for Acct[17f520c4-6a9d-11e6-8ec0-0050568ef122-system]
2020-12-03 18:21:54,093 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating entries for VM: VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:54,099 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating nics for VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:54,100 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating nic for vm VM[DomainRouter|r-50516-VM] in network
Ntwk[202|Control|3] with requested profile null
2020-12-03 18:21:54,118 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating nic for vm VM[DomainRouter|r-50516-VM] in network Ntwk[200|Public|1]
with requested profile NicProfile[0-0-null-10.1.4.172-vlan://4
2020-12-03 18:21:54,137 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocating disks for VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:54,148 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Allocation completed for VM: VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:54,158 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Starting router VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:54,170 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Sync job-1568833 execution on object VmWorkJobQueue.50516
2020-12-03 18:21:54,660 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:5187e69e)
Add job-1568833 into job monitoring
2020-12-03 18:21:54,668 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Executing AsyncJobVO {id:1568833, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAADFVHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0A
A5SZXN0YXJ0TmV0d29ya3QAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 52237721781, completeMsid: null, lastUpdated: null, lastPolled:
null, created: Thu Dec 03 18:21:54 GMT 2020, removed: null}
2020-12-03 18:21:54,668 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Run VM work job: com.cloud.vm.VmWorkStart for VM 50516, job origin: 1568832
2020-12-03 18:21:54,671 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":50516,"handlerName":"VirtualMachineManagerImpl"}
2020-12-03 18:21:54,683 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Successfully transitioned to start state for
VM[DomainRouter|r-50516-VM] reservation id =
6ba23963-f4c3-4e05-bbd7-34739b1b7167
2020-12-03 18:21:54,693 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Deploy avoids pods: null, clusters: null, hosts: null
2020-12-03 18:21:54,696 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Uefi params UefiFlag: null Boot Type: null Boot Mode: null
2020-12-03 18:21:54,711 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) DeploymentPlanner allocation algorithm: null
2020-12-03 18:21:54,711 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
2020-12-03 18:21:54,711 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Is ROOT volume READY (pool already allocated)?: No
2020-12-03 18:21:54,712 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Deploy avoids pods: [], clusters: [], hosts: []
2020-12-03 18:21:54,715 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Searching all possible resources under this Zone: 1
2020-12-03 18:21:54,717 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this Zone: 1
2020-12-03 18:21:54,721 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Removing from the clusterId list these clusters from avoid
set: []
2020-12-03 18:21:54,728 DEBUG [c.c.d.UserDispersingPlanner]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Applying Userdispersion heuristic to clusters for account: 2
2020-12-03 18:21:54,734 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking resources in Cluster: 4 under Pod: 1
2020-12-03 18:21:54,735 DEBUG [c.c.a.m.a.i.RandomAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Looking for hosts in dc: 1 pod:1 cluster:4
2020-12-03 18:21:54,737 DEBUG [c.c.a.m.a.i.RandomAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Random Allocator found 2 hosts
2020-12-03 18:21:54,737 DEBUG [c.c.a.m.a.i.RandomAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Random Host Allocator returning 2 suitable hosts
2020-12-03 18:21:54,739 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking suitable pools for volume (Id, Type): (51108,ROOT)
2020-12-03 18:21:54,739 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) We need to allocate new storagepool for this volume
2020-12-03 18:21:54,740 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Calling StoragePoolAllocators to find suitable pools
2020-12-03 18:21:54,742 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) System VMs will use shared storage for zone id=1
2020-12-03 18:21:54,742 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2020-12-03 18:21:54,742 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) ClusterScopeStoragePoolAllocator looking for storage pool
2020-12-03 18:21:54,742 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Looking for pools in dc: 1 pod:1 cluster:4 having tags:[SF].
Disabled pools will be ignored.
2020-12-03 18:21:54,743 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Found pools matching tags: [Pool[2|VMFS]]
2020-12-03 18:21:54,744 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Adding pool Pool[1|VMFS] to avoid set since it did not match
tags
2020-12-03 18:21:54,745 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking if storage pool is suitable, name: null ,poolId: 2
2020-12-03 18:21:54,747 INFO [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Storage pool null (2) does not supply IOPS capacity, assuming
enough capacity
2020-12-03 18:21:54,748 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking pool 2 for storage, totalSize: 7999913459712,
usedBytes: 5236109344768, usedPct: 0.6545207483977585, disable threshold: 0.86
2020-12-03 18:21:54,748 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Destination pool id: 2
2020-12-03 18:21:54,850 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Pool ID for the volume with ID 51108 is null
2020-12-03 18:21:54,857 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Found storage pool SBLAB-SF-P1C1-1 of type VMFS with
over-provisioning factor 4
2020-12-03 18:21:54,857 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Total over-provisioned capacity calculated is 4 * 7999913459712
2020-12-03 18:21:54,857 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Total capacity of the pool SBLAB-SF-P1C1-1 with ID 2 is
31999653838848
2020-12-03 18:21:54,858 DEBUG [c.c.s.StorageManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking pool: 2 for storage allocation , maxSize :
31999653838848, totalAllocatedSize : 8936772949160, askingSize : 2097152000,
allocated disable threshold: 0.86
2020-12-03 18:21:54,858 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) ClusterScopeStoragePoolAllocator returning 1 suitable storage
pools
2020-12-03 18:21:54,858 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Trying to find a potenial host and associated storage pools
from the suitable host/pool lists for this VM
2020-12-03 18:21:54,858 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Checking if host: 96 can access any suitable storage
pool for volume: ROOT
2020-12-03 18:21:54,859 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Host: 96 can access pool: 2
2020-12-03 18:21:54,860 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Found a potential host id: 96 name: 10.2.0.25 and associated
storage pools for this VM
2020-12-03 18:21:54,861 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(4)-Host(96)-Storage(Volume(51108|ROOT-->Pool(2))]
2020-12-03 18:21:54,861 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Deployment found - P0=VM[DomainRouter|r-50516-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(4)-Host(96)-Storage(Volume(51108|ROOT-->Pool(2))]
2020-12-03 18:21:54,914 DEBUG [c.c.u.d.T.Transaction]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Rolling back the transaction: Time = 9 Name =
Work-Job-Executor-93; called by
-TransactionLegacy.rollback:890-TransactionLegacy.removeUpTo:833-TransactionLegacy.close:657-Transaction.execute:38-Transaction.execute:47-CapacityManagerImpl.allocateVmCapacity:308-CapacityManagerImpl.postStateTransitionEvent:953-CapacityManagerImpl.postStateTransitionEvent:98-StateMachine2.transitTo:142-VirtualMachineManagerImpl.stateTransitTo:1885-VirtualMachineManagerImpl.changeState:861-VirtualMachineManagerImpl.orchestrateStart:1117
2020-12-03 18:21:54,916 ERROR [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Exception allocating VM capacity
2020-12-03 18:21:54,963 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Caught CloudRuntimeException, returning job failed
com.cloud.utils.exception.CloudRuntimeException: Host does not have enough
capacity for vm 50516
2020-12-03 18:21:54,968 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"RestartNetwork":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":2,"accountId":2,"vmId":50516,"handlerName":"VirtualMachineManagerImpl"}
2020-12-03 18:21:54,971 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Complete async job-1568833, jobStatus: FAILED, resultCode: 0,
result:
rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ABtVbmFibGUgdG8gc3RhcnQgVk0gaW5zdGFuY2V1cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAABNzcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAAhCAAZmb3JtYXRJAApsaW5lTnVtYmVyTAAPY2xhc3NMb2FkZXJOYW1lcQB-AAVMAA5kZWNsYXJpbmdDbGFzc3EAfgAFTAAIZmlsZU5hbWVxAH4ABUwACm1ldGhvZE5hbWVxAH4ABUw
ACm1vZHVsZU5hbWVxAH4ABUwADW1vZHVsZVZlcnNpb25xAH4ABXhwAQAAFHB0AANhcHB0ACZjb20uY2xvdWQudm0uVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbHQAHlZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwuamF2YXQAEG9yY2hlc3RyYXRlU3RhcnRwcHNxAH4ADAD_____cHQAL2pkay5pbnRlcm5hbC5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yNDkxcHQABmludm9rZXBwc3EAfgAMAgAAACtwdAAxamRrLmludGVybmFsLnJlZmxlY3QuRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbHQAIURlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGwuamF2YXEAfgAUdAAJamF2YS5iYXNldAAGMTEuMC43c3EAfgAMAgAAAjZwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AFHEAfgAYcQB-ABlzcQB-AAwBAAAAa3EAfgAOdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-AAwBAAAVDnEAfgAOcQB-AA9xAH4AEHEAfgAgcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJbcQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0
AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAxcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADhxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGdxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AMHQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADVxAH4ADnEAfgAzcQB-ADB0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC5xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAscQB-AC1wcHNxAH4ADAEAAAIncQB-AA5xAH4AJ3EAfgAocQB-AC1wcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAxcQB-ABhxAH4AGXNxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlY
WRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAYcQB-ABlzcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEJxAH4ALXEAfgAYcQB-ABlzcQB-AAwCAAADQnB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ALXEAfgAYcQB-ABlzcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2020-12-03 18:21:54,974 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Publish async job-1568833 complete on message bus
2020-12-03 18:21:54,974 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Wake up jobs related to job-1568833
2020-12-03 18:21:54,974 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Update db status for job-1568833
2020-12-03 18:21:54,977 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833 ctx-d0af57d6)
(logid:eb5292ac) Wake up jobs joined with job-1568833 and disjoin all subjobs
created from job- 1568833
2020-12-03 18:21:54,996 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 50516, job
origin: 1568832
2020-12-03 18:21:54,996 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Done executing com.cloud.vm.VmWorkStart for job-1568833
2020-12-03 18:21:54,999 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-93:ctx-e64e3b1d job-1568832/job-1568833) (logid:eb5292ac)
Remove job-1568833 from job monitoring
2020-12-03 18:21:55,014 WARN [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Failed to start vpc [VPC [13-andrija-swisstxt-VPC2] due to
2020-12-03 18:21:55,015 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Destroying vpc [VPC [13-andrija-swisstxt-VPC2] that failed to start
2020-12-03 18:21:55,015 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Destroying vpc [VPC [13-andrija-swisstxt-VPC2]
2020-12-03 18:21:55,017 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Updating VPC [VPC [13-andrija-swisstxt-VPC2] with state Inactive as a part of
vpc delete
2020-12-03 18:21:55,031 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Updating resource Type = vpc count for Account = 2 Operation = decreasing
Amount = 1
2020-12-03 18:21:55,051 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Shutting down vpc [VPC [13-andrija-swisstxt-VPC2]
2020-12-03 18:21:55,070 DEBUG [c.c.n.r.NetworkHelperImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Attempting to destroy router 50516
2020-12-03 18:21:55,101 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Sync job-1568834 execution on object VmWorkJobQueue.50516
2020-12-03 18:21:56,657 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:8efcf05c)
Add job-1568834 into job monitoring
2020-12-03 18:21:56,664 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Executing AsyncJobVO {id:1568834, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo:
rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAADFVHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 52237721781, completeMsid: null, lastUpdated: null, lastPolled:
null, created: Thu Dec 03 18:21:55 GMT 2020, removed: null}
2020-12-03 18:21:56,664 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Run VM work job: com.cloud.vm.VmWorkStop for VM 50516, job origin: 1568832
2020-12-03 18:21:56,667 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Execute VM work job:
com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":50516,"handlerName":"VirtualMachineManagerImpl"}
2020-12-03 18:21:56,671 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) VM is already stopped: VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:56,671 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Done executing VM work job:
com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":50516,"handlerName":"VirtualMachineManagerImpl"}
2020-12-03 18:21:56,672 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Complete async job-1568834, jobStatus: SUCCEEDED, resultCode:
0, result: null
2020-12-03 18:21:56,674 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Publish async job-1568834 complete on message bus
2020-12-03 18:21:56,674 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Wake up jobs related to job-1568834
2020-12-03 18:21:56,674 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Update db status for job-1568834
2020-12-03 18:21:56,675 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834 ctx-70254bc6)
(logid:eb5292ac) Wake up jobs joined with job-1568834 and disjoin all subjobs
created from job- 1568834
2020-12-03 18:21:56,698 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 50516, job origin:
1568832
2020-12-03 18:21:56,698 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Done executing com.cloud.vm.VmWorkStop for job-1568834
2020-12-03 18:21:56,701 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-89:ctx-551f6d24 job-1568832/job-1568834) (logid:eb5292ac)
Remove job-1568834 from job monitoring
2020-12-03 18:21:56,734 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Destroying vm VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:56,734 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up NICS
2020-12-03 18:21:56,738 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning network for vm: 50516
2020-12-03 18:21:56,760 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Removed nic id=75956
2020-12-03 18:21:56,761 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Revoving nic secondary ip entry ...
2020-12-03 18:21:56,779 DEBUG [c.c.n.g.PublicNetworkGuru]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
public network deallocate network: networkId: 200, ip: 10.1.4.172
2020-12-03 18:21:56,781 DEBUG [c.c.n.g.PublicNetworkGuru]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Deallocated nic: NicProfile[75957-50516-null-null-null
2020-12-03 18:21:56,790 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Removed nic id=75957
2020-12-03 18:21:56,791 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Revoving nic secondary ip entry ...
2020-12-03 18:21:56,792 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed
storage
2020-12-03 18:21:56,796 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning storage for vm: 50516
2020-12-03 18:21:56,826 INFO [o.a.c.s.v.VolumeServiceImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Expunge volume with no data store specified
2020-12-03 18:21:56,829 INFO [o.a.c.s.v.VolumeServiceImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Volume 51108 is not referred anywhere, remove it from volumes table
2020-12-03 18:21:56,841 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Expunged VM[DomainRouter|r-50516-VM]
2020-12-03 18:21:56,849 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Vpc [VPC [13-andrija-swisstxt-VPC2] has been shutdown succesfully
2020-12-03 18:21:56,849 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up resources for vpc id=13
2020-12-03 18:21:56,849 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up existed site to site VPN connections
2020-12-03 18:21:56,855 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up existed site to site VPN gateways
2020-12-03 18:21:56,860 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing ips for vpc id=13 as a part of vpc cleanup
2020-12-03 18:21:56,860 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Revoking all Firewallrules as a part of public IP id=76697 release...
2020-12-03 18:21:56,871 DEBUG [c.c.n.f.FirewallManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing 0 firewall rules for ip id=76697
2020-12-03 18:21:56,872 DEBUG [c.c.n.f.FirewallManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
There are no firewall rules to apply
2020-12-03 18:21:56,873 DEBUG [c.c.n.f.FirewallManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Successfully released firewall rules for ip id=76697 and # of rules now =
0
2020-12-03 18:21:56,883 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Revoking all PortForwarding/StaticNat rules as a part of public IP id=76697
release...
2020-12-03 18:21:56,885 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing 0 port forwarding rules for ip id=76697
2020-12-03 18:21:56,886 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing 0 static nat rules for ip id=76697
2020-12-03 18:21:56,890 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
There are no port forwarding rules to apply for ip id=76697
2020-12-03 18:21:56,892 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
There are no static nat rules to apply for ip id=76697
2020-12-03 18:21:56,894 DEBUG [c.c.n.r.RulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Successfully released rules for ip id=76697 and # of rules now = 0
2020-12-03 18:21:56,894 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Revoking all LoadBalancing rules as a part of public IP id=76697 release...
2020-12-03 18:21:56,895 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Found 0 lb rules to cleanup
2020-12-03 18:21:56,917 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Cleaning up remote access vpns as a part of public IP id=76697 release...
2020-12-03 18:21:56,929 DEBUG [c.c.n.v.RemoteAccessVpnManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
there are no Remote access vpns for public ip address id=76697
2020-12-03 18:21:56,941 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Updating resource Type = public_ip count for Account = 2 Operation = decreasing
Amount = 1
2020-12-03 18:21:56,954 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Releasing ip id=76697; sourceNat = true
2020-12-03 18:21:56,961 DEBUG [c.c.n.IpAddressManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Released a public ip id=76697
2020-12-03 18:21:56,962 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Released ip addresses for vpc id=13 as a part of cleanup vpc process
2020-12-03 18:21:56,969 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Found 0 to revoke for the vpc 13
2020-12-03 18:21:56,979 DEBUG [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Vpc [VPC [13-andrija-swisstxt-VPC2] is destroyed succesfully
2020-12-03 18:21:56,980 WARN [c.c.n.v.VpcManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832 ctx-6928a5c8) (logid:eb5292ac)
Successfully destroyed vpc [VPC [13-andrija-swisstxt-VPC2] that failed to start
2020-12-03 18:21:56,982 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Complete async
job-1568832, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed
to create VPC"}
2020-12-03 18:21:56,984 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Publish async
job-1568832 complete on message bus
2020-12-03 18:21:56,984 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Wake up jobs
related to job-1568832
2020-12-03 18:21:56,984 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Update db
status for job-1568832
2020-12-03 18:21:56,985 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Wake up jobs
joined with job-1568832 and disjoin all subjobs created from job- 1568832
2020-12-03 18:21:56,992 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Done executing
org.apache.cloudstack.api.command.admin.vpc.CreateVPCCmdByAdmin for
job-1568832
2020-12-03 18:21:56,992 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-94:ctx-d7e162ba job-1568832) (logid:eb5292ac) Remove
job-1568832 from job monitoring
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
