Hi Udo, As per the log in the email, the System VM deployment failed immediately after finding suitable hosts by the Deployment Planner (FirstFitPlanner). Once suitable hosts are found in the cluster, CS should check for suitable storage pools for finalizing the complete deployment destination (Zone, Pod, Cluster, Host, Storage). It seems there is some unlogged error after finding suitable hosts and the deployment failed immediately with Event OperationFailed. Check the pools accessibilty. and also try with a different Deployment Planner (change the global config parameter "vm.deployment.planner")
- Suresh On Mon, May 6, 2019 at 1:59 PM Mueller, Udo <udo.muel...@plath.de> wrote: > Hi all, > > recently we had a crash in our cloudstack. > > Cloudstack runs inside a pcs cluster which share a direct attached > storage. Cluster is running fine, storage is mounted, CS agents are > running. Virtualization is run in KVM, project VMs can be started fine. > Our installed version is 4.9.2 and we currently cant update to current. > > But: > > The system VM cannot be started. Neither console proxy nor secondary > storage VM. > > Log output on CS management when trying to start console proxy vm manually: > > 2019-05-06 08:22:58,865 DEBUG [c.c.a.ApiServlet] > (catalina-exec-5:ctx-26cf8ba3) (logid:d5797b2d) ===START=== 172.16.192.180 > -- GET > command=startSystemVm&id=4803e585-78d3-45b8-8d8a-49944f05e5fa&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557130978863 > 2019-05-06 08:22:58,878 WARN [c.c.a.d.ParamGenericValidationWorker] > (catalina-exec-5:ctx-26cf8ba3 ctx-31d5912e) (logid:d5797b2d) Received > unknown parameters for command startSystemVm. Unknown parameters : projectid > 2019-05-06 08:22:58,928 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099) (logid:97ae8562) Add > job-122099 into job monitoring > 2019-05-06 08:22:58,944 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (catalina-exec-5:ctx-26cf8ba3 ctx-31d5912e) (logid:d5797b2d) submit async > job-122099, details: AsyncJobVO {id:122099, userId: 16, accountId: 2, > instanceType: SystemVm, instanceId: 4448, cmd: > org.apache.cloudstack.api.command.admin.systemvm.StartSystemVMCmd, cmdInfo: > {"response":"json","id":"4803e585-78d3-45b8-8d8a-49944f05e5fa","ctxDetails":"{\"interface > com.cloud.vm.VirtualMachine\":\"4803e585-78d3-45b8-8d8a-49944f05e5fa\"}","cmdEventType":"PROXY.START","ctxUserId":"16","httpmethod":"GET","_":"1557130978863","projectid":"53824f26-bf1d-4f3d-8f5c-d25a045e4abe","uuid":"4803e585-78d3-45b8-8d8a-49944f05e5fa","ctxAccountId":"2","ctxStartEventId":"108673"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 101543520292, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2019-05-06 08:22:58,945 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099) (logid:4706bea3) Executing > AsyncJobVO {id:122099, userId: 16, accountId: 2, instanceType: SystemVm, > instanceId: 4448, cmd: > org.apache.cloudstack.api.command.admin.systemvm.StartSystemVMCmd, cmdInfo: > {"response":"json","id":"4803e585-78d3-45b8-8d8a-49944f05e5fa","ctxDetails":"{\"interface > com.cloud.vm.VirtualMachine\":\"4803e585-78d3-45b8-8d8a-49944f05e5fa\"}","cmdEventType":"PROXY.START","ctxUserId":"16","httpmethod":"GET","_":"1557130978863","projectid":"53824f26-bf1d-4f3d-8f5c-d25a045e4abe","uuid":"4803e585-78d3-45b8-8d8a-49944f05e5fa","ctxAccountId":"2","ctxStartEventId":"108673"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 101543520292, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2019-05-06 08:22:58,945 DEBUG [c.c.a.ApiServlet] > (catalina-exec-5:ctx-26cf8ba3 ctx-31d5912e) (logid:d5797b2d) ===END=== > 172.16.192.180 -- GET > command=startSystemVm&id=4803e585-78d3-45b8-8d8a-49944f05e5fa&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557130978863 > 2019-05-06 08:22:58,952 WARN [c.c.a.d.ParamGenericValidationWorker] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Received unknown parameters for command startSystemVm. Unknown parameters : > projectid > 2019-05-06 08:22:59,011 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Sync job-122100 execution on object VmWorkJobQueue.4448 > 2019-05-06 08:23:00,135 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-7a6dfcef) (logid:6c3cd4ad) Execute sync-queue > item: SyncQueueItemVO {id:33420, queueId: 49000, contentType: AsyncJob, > contentId: 122100, lastProcessMsid: 101543520292, lastprocessNumber: 16673, > lastProcessTime: Mon May 06 08:23:00 UTC 2019, created: Mon May 06 08:22:59 > UTC 2019} > 2019-05-06 08:23:00,136 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (AsyncJobMgr-Heartbeat-1:ctx-7a6dfcef) (logid:6c3cd4ad) Schedule queued > job-122100 > 2019-05-06 08:23:00,156 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:b2ab9409) > Add job-122100 into job monitoring > 2019-05-06 08:23:00,170 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:4706bea3) > Executing AsyncJobVO {id:122100, userId: 16, accountId: 2, instanceType: > null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: > rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAABAAAAAAAAARYHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 101543520292, completeMsid: null, lastUpdated: > null, lastPolled: null, created: Mon May 06 08:22:59 UTC 2019} > 2019-05-06 08:23:00,170 DEBUG [c.c.v.VmWorkJobDispatcher] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:4706bea3) > Run VM work job: com.cloud.vm.VmWorkStart for VM 4448, job origin: 122099 > 2019-05-06 08:23:00,171 DEBUG [c.c.v.VmWorkJobHandlerProxy] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Execute VM work job: > com.cloud.vm.VmWorkStart{"dcId":0,"userId":16,"accountId":2,"vmId":4448,"handlerName":"VirtualMachineManagerImpl"} > 2019-05-06 08:23:00,181 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) VM state transitted from :Stopped to Starting with event: > StartRequestedvm's original host id: null new host id: null host id before > state transition: null > 2019-05-06 08:23:00,181 DEBUG [c.c.v.VirtualMachineManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Successfully transitioned to start state for > VM[ConsoleProxy|v-4448-VM] reservation id = > d5d5581b-c7f6-47a0-88c4-cfe16d06b1fd > 2019-05-06 08:23:00,195 DEBUG [c.c.v.VirtualMachineManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Trying to deploy VM, vm has dcId: 2 and podId: null > 2019-05-06 08:23:00,195 DEBUG [c.c.v.VirtualMachineManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Deploy avoids pods: null, clusters: null, hosts: null > 2019-05-06 08:23:00,198 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Deploy avoids pods: null, clusters: null, hosts: null > 2019-05-06 08:23:00,199 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) DeploymentPlanner allocation algorithm: > com.cloud.deploy.FirstFitPlanner@4d829b98 > 2019-05-06 08:23:00,199 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Trying to allocate a host and storage pools from dc:2, > pod:null,cluster:null, requested cpu: 500, requested ram: 1073741824 > 2019-05-06 08:23:00,199 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Is ROOT volume READY (pool already allocated)?: No > 2019-05-06 08:23:00,199 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Searching all possible resources under this Zone: 2 > 2019-05-06 08:23:00,200 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Listing clusters in order of aggregate capacity, that have > (atleast one host with) enough CPU and RAM capacity under this Zone: 2 > 2019-05-06 08:23:00,204 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Checking resources in Cluster: 2 under Pod: 2 > 2019-05-06 08:23:00,205 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Looking for hosts in dc: 2 > pod:2 cluster:2 > 2019-05-06 08:23:00,207 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) FirstFitAllocator has 8 hosts to > check for allocation: [Host[-62-Routing], Host[-61-Routing], > Host[-60-Routing], Host[-59-Routing], Host[-57-Routing], Host[-56-Routing], > Host[-58-Routing], Host[-54-Routing]] > 2019-05-06 08:23:00,216 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found 8 hosts for allocation > after prioritization: [Host[-62-Routing], Host[-61-Routing], > Host[-60-Routing], Host[-59-Routing], Host[-57-Routing], Host[-56-Routing], > Host[-58-Routing], Host[-54-Routing]] > 2019-05-06 08:23:00,216 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Looking for speed=500Mhz, > Ram=1024 > 2019-05-06 08:23:00,221 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 62 has cpu capability > (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,221 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 62 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,222 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 19200 > and CPU after applying overprovisioning: 48000 > 2019-05-06 08:23:00,222 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 28000 , Requested CPU: > 500 > 2019-05-06 08:23:00,222 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 284000190464 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,223 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,223 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 62, used: 20000, reserved: 0, actual total: 19200, total with > overprovisioning: 48000; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,223 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 62, used: 51539607552, reserved: 0, total: 335539798016; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,223 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 62 > 2019-05-06 08:23:00,227 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 61 has cpu capability > (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,227 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 61 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,229 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 19200 > and CPU after applying overprovisioning: 48000 > 2019-05-06 08:23:00,229 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 0 , Requested CPU: 500 > 2019-05-06 08:23:00,229 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 571339177984 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,229 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Failed to alloc resource > from host: 61 reservedCpu: 0, used cpu: 48000, requested cpu: 500, actual > total cpu: 19200, total cpu with overprovisioning: 48000, reservedMem: 0, > used Mem: 103079215104, requested mem: 1073741824, total Mem:674418393088 > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,229 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host does not have enough CPU > available, cannot allocate to this host. > 2019-05-06 08:23:00,229 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Not using host 61; host has cpu > capability? true, host has capacity?false > 2019-05-06 08:23:00,234 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 60 has cpu capability > (cpu:80, speed:2394) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,234 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 60 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 191520 > and CPU after applying overprovisioning: 478800 > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 438704 , Requested > CPU: 500 > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 519020019712 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 60, used: 40096, reserved: 0, actual total: 191520, total with > overprovisioning: 478800; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,236 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 60, used: 154618822656, reserved: 0, total: 673638842368; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,236 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 60 > 2019-05-06 08:23:00,240 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 59 has cpu capability > (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,241 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 59 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 19200 > and CPU after applying overprovisioning: 48000 > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 24000 , Requested CPU: > 500 > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 622878785536 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 59, used: 24000, reserved: 0, actual total: 19200, total with > overprovisioning: 48000; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,242 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 59, used: 51539607552, reserved: 0, total: 674418393088; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,242 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 59 > 2019-05-06 08:23:00,248 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 57 has cpu capability > (cpu:32, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,248 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 57 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 76800 > and CPU after applying overprovisioning: 192000 > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 144000 , Requested > CPU: 500 > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 62793105408 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 57, used: 48000, reserved: 0, actual total: 76800, total with > overprovisioning: 192000; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,250 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 57, used: 103079215104, reserved: 0, total: 165872320512; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,250 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 57 > 2019-05-06 08:23:00,255 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 56 has cpu capability > (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,255 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 56 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 19200 > and CPU after applying overprovisioning: 48000 > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 20000 , Requested CPU: > 500 > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 351539953664 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 56, used: 28000, reserved: 0, actual total: 19200, total with > overprovisioning: 48000; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,257 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 56, used: 68719476736, reserved: 0, total: 420259430400; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,257 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 56 > 2019-05-06 08:23:00,262 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 58 has cpu capability > (cpu:32, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,262 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 58 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,263 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 76800 > and CPU after applying overprovisioning: 192000 > 2019-05-06 08:23:00,263 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 144000 , Requested > CPU: 500 > 2019-05-06 08:23:00,263 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 41614508032 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,264 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host has enough CPU and RAM > available > 2019-05-06 08:23:00,264 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc CPU from host: > 58, used: 48000, reserved: 0, actual total: 76800, total with > overprovisioning: 192000; requested cpu:500,alloc_from_last_host?:false > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,264 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Can alloc MEM from host: > 58, used: 103079215104, reserved: 0, total: 144693723136; requested mem: > 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2019-05-06 08:23:00,264 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Found a suitable host, adding to > list: 58 > 2019-05-06 08:23:00,268 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host: 54 has cpu capability > (cpu:8, speed:2400) to support requested CPU: 1 and requested speed: 500 > 2019-05-06 08:23:00,269 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Checking if host: 54 has enough > capacity for requested CPU: 500 and requested RAM: 1073741824 , > cpuOverprovisioningFactor: 2.5 > 2019-05-06 08:23:00,270 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Hosts's actual total CPU: 19200 > and CPU after applying overprovisioning: 48000 > 2019-05-06 08:23:00,270 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free CPU: 0 , Requested CPU: 500 > 2019-05-06 08:23:00,270 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Free RAM: 147740983296 , > Requested RAM: 1073741824 > 2019-05-06 08:23:00,270 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) STATS: Failed to alloc resource > from host: 54 reservedCpu: 0, used cpu: 48000, requested cpu: 500, actual > total cpu: 19200, total cpu with overprovisioning: 48000, reservedMem: 0, > used Mem: 103079215104, requested mem: 1073741824, total Mem:250820198400 > ,considerReservedCapacity?: true > 2019-05-06 08:23:00,270 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host does not have enough CPU > available, cannot allocate to this host. > 2019-05-06 08:23:00,270 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Not using host 54; host has cpu > capability? true, host has capacity?false > 2019-05-06 08:23:00,270 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f > FirstFitRoutingAllocator) (logid:4706bea3) Host Allocator returning 6 > suitable hosts > 2019-05-06 08:23:00,313 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) VM state transitted from :Starting to Stopped with event: > OperationFailedvm's original host id: null new host id: null host id before > state transition: null > 2019-05-06 08:23:00,313 INFO [c.c.v.VirtualMachineManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Caught CloudRuntimeException, returning job failed > 2019-05-06 08:23:00,313 DEBUG [c.c.v.VmWorkJobHandlerProxy] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Done executing VM work job: > com.cloud.vm.VmWorkStart{"dcId":0,"userId":16,"accountId":2,"vmId":4448,"handlerName":"VirtualMachineManagerImpl"} > 2019-05-06 08:23:00,313 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Complete async job-122100, jobStatus: FAILED, resultCode: > 0, result: null > 2019-05-06 08:23:00,314 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Publish async job-122100 complete on message bus > 2019-05-06 08:23:00,314 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Wake up jobs related to job-122100 > 2019-05-06 08:23:00,314 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Update db status for job-122100 > 2019-05-06 08:23:00,315 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100 ctx-49eae88f) > (logid:4706bea3) Wake up jobs joined with job-122100 and disjoin all > subjobs created from job- 122100 > 2019-05-06 08:23:00,339 DEBUG [c.c.v.VmWorkJobDispatcher] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:4706bea3) > Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 4448, job > origin: 122099 > 2019-05-06 08:23:00,339 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:4706bea3) > Done executing com.cloud.vm.VmWorkStart for job-122100 > 2019-05-06 08:23:00,341 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (Work-Job-Executor-56:ctx-8bc110ba job-122099/job-122100) (logid:4706bea3) > Remove job-122100 from job monitoring > 2019-05-06 08:23:00,394 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Complete async job-122099, jobStatus: SUCCEEDED, resultCode: 0, result: > org.apache.cloudstack.api.response.SystemVmResponse/systemvm/{"id":"4803e585-78d3-45b8-8d8a-49944f05e5fa","systemvmtype":"consoleproxy","zoneid":"978f1e08-8650-424f-b527-a1afd74305e9","zonename":"Intsys","dns1":"10.252.34.10","name":"v-4448-VM","templateid":"367b6a82-1471-4fa3-a3b9-c194213c27d6","created":"2019-04-30T13:26:56+0000","state":"Stopped","activeviewersessions":0} > 2019-05-06 08:23:00,395 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Publish async job-122099 complete on message bus > 2019-05-06 08:23:00,395 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Wake up jobs related to job-122099 > 2019-05-06 08:23:00,395 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Update db status for job-122099 > 2019-05-06 08:23:00,396 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099 ctx-fb498807) (logid:4706bea3) > Wake up jobs joined with job-122099 and disjoin all subjobs created from > job- 122099 > 2019-05-06 08:23:00,418 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099) (logid:4706bea3) Done > executing org.apache.cloudstack.api.command.admin.systemvm.StartSystemVMCmd > for job-122099 > 2019-05-06 08:23:00,418 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-63:ctx-c57ad4d3 job-122099) (logid:4706bea3) Remove > job-122099 from job monitoring > 2019-05-06 08:23:01,951 DEBUG [c.c.a.ApiServlet] > (catalina-exec-18:ctx-ec250e8c) (logid:862cd473) ===START=== > 172.16.192.180 -- GET > command=queryAsyncJobResult&jobId=4706bea3-a1fc-4f2b-8521-c296c2c46c4b&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557130981948 > 2019-05-06 08:23:01,958 WARN [c.c.a.d.ParamGenericValidationWorker] > (catalina-exec-18:ctx-ec250e8c ctx-05f46862) (logid:862cd473) Received > unknown parameters for command queryAsyncJobResult. Unknown parameters : > projectid > 2019-05-06 08:23:01,983 DEBUG [c.c.a.ApiServlet] > (catalina-exec-18:ctx-ec250e8c ctx-05f46862) (logid:862cd473) ===END=== > 172.16.192.180 -- GET > command=queryAsyncJobResult&jobId=4706bea3-a1fc-4f2b-8521-c296c2c46c4b&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557130981948 > > CS management reports that start system VM was successful. > > But I cant see any connect/instruction in the agent logfile of the > connected servers. The agents alos log in DEBUG mode. > > Is there anyone out there who can give help or guidance? > > Regards Udo > Mit freundlichen Gr??en > Best regards > > Udo Mueller > Senior System Engineer > > PLATH GmbH > Gotenstrasse 18 > 20097 Hamburg > Germany > > Tel: +49 40 237 34-235 > Fax: +49 40 237 34-222 > Email: udo.muel...@plath.de > > > [http://www.plathgroup.com/banner/aeo-logo.jpg] > Directorate General Customs and > Taxation (c) European Union, 2007-2017 > > > > ---------------------------- > www.plath.de | www.plathgroup.com > District Court Hamburg HRB 7401 > Authorised representatives: > Nico Scharfe (CEO), Hinrich Brueggmann (CEO) > > The information transmitted and any documents, files or previous email > messages attached to it contains strictly confidential information that is > legally privileged and intended only for the person or entity to which it > is addressed. Any review, retransmission, dissemination or other use of, or > taking of any action in reliance upon, this information by persons or > entities other than the intended recipient is prohibited. > If you have received this message in error, please advise the sender > immediately by reply e-mail and delete the original message and any copies > from your computer system. This notice also applies to future messages. > >