cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Andrija Panic <andrija.pa...@shapeblue.com>
Subject RE: AW: CS 4.9.2: System VMs not starting
Date Fri, 10 May 2019 10:06:43 GMT
Udo,

Nothing new in logs... Perhaps you can try pushing verbosity level to TRACE, so we can see what happens, what SQL statements are executed, etc. - based on current log lines, this seems to be a failure on mgmt. server side, without any interaction with external infra (KVM hosts, storage, etc.) - so might be some DB inconsistency as well.

Andrija


Regards,
Andrija Panic

andrija.panic@shapeblue.com 
www.shapeblue.com
Amadeus House, Floral Street, London  WC2E 9DPUK
@shapeblue
  
 


-----Original Message-----
From: Mueller, Udo <Udo.Mueller@plath.de> 
Sent: 08 May 2019 16:53
To: users@cloudstack.apache.org
Subject: AW: AW: CS 4.9.2: System VMs not starting

Hi Andrija!

I changed the permissions of the id_rsa.pub.cloud. Thanks

After upgrading all hosts to the same version 4.9.3.0 I can say that I have 20 hosts up and running:

# grep -r StatsCollector /var/log/cloudstack/management/management* | grep intsys | sed -e 's/^.*intsys/intsys/' | sort | uniq | grep GetHostStatsAnswer | wc -l
20
# grep -r StatsCollector /var/log/cloudstack/management/management* | grep intsys | sed -e 's/^.*intsys/intsys/' | sort | uniq | grep GetStorageStatsAnswer | wc -l
20

# grep -r "Found a suitable host" /var/log/cloudstack/management/management* | cut -d" " -f10- | sort | uniq | wc -l
17

3 hosts are full of vms so there are no free resources.

I disabled the zone, checked all hosts for running VM, enabled the zone again. No changes.
I restarted CS manager. No changes.

Here is the log after restarting CS Management:

https://www.file-upload.net/download-13597809/management-server.log.html


Thanks!

Regards Udo

-----Ursprüngliche Nachricht-----
Von: Andrija Panic [mailto:andrija.panic@shapeblue.com]
Gesendet: Dienstag, 7. Mai 2019 22:35
An: users@cloudstack.apache.org
Betreff: RE: AW: CS 4.9.2: System VMs not starting

Hi Udo,

Perhaps not relevant, but check host 65, error message being:
2019-05-07 07:09:19,718 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) (logid:) Seq 65-6444932541743890440: Processing:  { Ans: , MgmtId: 101543520292, via: 65, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":false,"details":"File/root/.ssh/id_rsa.pub.cloudis not found:java.io.FileNotFoundException: /root/.ssh/id_rsa.pub.cloud (Permission denied)","wait":0}}] }

In your logs, you get "18 hosts found..." but you have 20 hosts in UP/Enabled state. Further more I see that deployment never started examining storage pools and checking if these hosts can access storage, so I assume an issue with KVM nodes in general.

Of your 20 hosts, some seems to report version 4.9.0 (most of them), one host is 4.9.2 and one host is 4.11.2 ???
I would work out on fixing that and making sure proper CloudStack-agent is present on all nodes, or at least disable those hosts, that are not of proper version.

Also, you could disable the zone (disables provisioning of any new resources), than make sure to remove SSVM and CPVM fully - confirm no SSVM and CPVM are running on any KVM node as well, since you had a crash), then enable the Zone, which will trigger creation of fresh SSVM and CPVM.

If that still fails after above things done, then please check and share logs again (again, pastebin or such).

Best,
Andrija


andrija.panic@shapeblue.com
www.shapeblue.com
Amadeus House, Floral Street, London  WC2E 9DPUK @shapeblue
  
 


-----Original Message-----
From: Mueller, Udo <Udo.Mueller@plath.de>
Sent: 07 May 2019 13:47
To: users@cloudstack.apache.org
Subject: AW: AW: CS 4.9.2: System VMs not starting

Hi Adrian,

yes it was. I think below message results from minimizing the CS Cluster to have a better overview over the agent log files.
I apologize for that.

See 

https://www.file-upload.net/download-13596521/management-server.log.html

where the cluster is fully populated again with  20 hosts and enough resources.

-----Ursprüngliche Nachricht-----
Von: asender@testlabs.com.au [mailto:asender@testlabs.com.au]
Gesendet: Dienstag, 7. Mai 2019 02:16
An: users@cloudstack.apache.org
Cc: Mueller, Udo
Betreff: Re: AW: CS 4.9.2: System VMs not starting

Was it ever working, looks like a resource issue. I used to run KVM + CLVM with gfs successfully.

Adrian Sender


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.


On 2019-05-07 00:14, Mueller, Udo wrote:
> Hi Suresh,
> 
> thanks for your reply!
> 
> Zone, Pod, Cluster and hosts are all up and enabled.
> Primary storage is online and enabled.
> 
> I changed  vm.deployment.planner to UserDispersingPlanner
> 
> Nothing changed:
> 
> 2019-05-06 14:04:20,466 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Zone 2 is ready to launch 
> secondary storage VM
> 2019-05-06 14:04:20,469 INFO
> [o.a.c.s.PremiumSecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) No running secondary 
> storage vms found in datacenter id=2, starting one
> 2019-05-06 14:04:20,472 TRACE [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Allocate secondary 
> storage vm standby capacity for data center : 2
> 2019-05-06 14:04:20,474 INFO  [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Found a stopped secondary 
> storage vm, starting it. Vm id : 4464
> 2019-05-06 14:04:20,509 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Sync job-123639 execution 
> on object VmWorkJobQueue.4464
> 2019-05-06 14:04:22,359 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) received secondary 
> storage vm alert
> 2019-05-06 14:04:22,359 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Secondary Storage Vm is 
> up, zone: Intsys, secStorageVm: s-4464-VM, public IP: null, private
> IP: null
> 2019-05-06 14:04:22,360 WARN  [o.a.c.alerts]
> (secstorage-1:ctx-723640c1) (logid:0fb29055)  alertType:: 19 //
> dataCenterId:: 2 // podId:: null // clusterId:: null // message::
> Secondary Storage Vm up in zone: Intsys, secStorageVm: s-4464-VM, 
> public IP: null, private IP: N/A
> 2019-05-06 14:04:22,392 INFO  [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Secondary storage vm 
> s-4464-VM is started
> 2019-05-06 14:04:22,392 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) received secondary 
> storage vm alert
> 2019-05-06 14:04:22,392 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Secondary Storage Vm 
> creation failure, zone: Intsys
> 2019-05-06 14:04:22,393 WARN  [o.a.c.alerts]
> (secstorage-1:ctx-723640c1) (logid:0fb29055)  alertType:: 19 //
> dataCenterId:: 2 // podId:: null // clusterId:: null // message::
> Secondary Storage Vm creation failure. zone: Intsys, error details:
> null
> 2019-05-06 14:04:22,412 INFO
> [o.a.c.s.PremiumSecondaryStorageManagerImpl]
> (secstorage-1:ctx-723640c1) (logid:0fb29055) Primary secondary storage 
> is not even started, wait until next turn
> 
> Manual start of VM results in "System VM started" by web ui.
> 
> I changed  vm.deployment.planner to UserConcentratedPodPlanner
> 
> Nothing changed
> 
> 2019-05-06 14:13:44,824 DEBUG [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Zone 2 is ready to 
> launch console proxy
> 2019-05-06 14:13:44,824 DEBUG [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Expand console proxy 
> standby capacity for zone Intsys
> 2019-05-06 14:13:44,826 INFO  [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Found a stopped console 
> proxy, starting it. Vm id : 4463
> 2019-05-06 14:13:44,860 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Sync job-123671 
> execution on object VmWorkJobQueue.4463
> 2019-05-06 14:13:46,816 INFO  [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Console proxy v-4463-VM 
> is started
> 2019-05-06 14:13:46,817 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) received console proxy 
> alert
> 2019-05-06 14:13:46,817 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Console proxy is up,
> zone: Intsys, proxy: v-4463-VM, public IP: null, private IP: null
> 2019-05-06 14:13:46,818 WARN  [o.a.c.alerts]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac)  alertType:: 10 //
> dataCenterId:: 2 // podId:: null // clusterId:: null // message::
> Console proxy up in zone: Intsys, proxy: v-4463-VM, public IP: null, 
> private IP: N/A
> 2019-05-06 14:13:46,840 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) received console proxy 
> alert
> 2019-05-06 14:13:46,840 DEBUG [c.c.a.ConsoleProxyAlertAdapter]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac) Console proxy creation 
> failure, zone: Intsys
> 2019-05-06 14:13:46,841 WARN  [o.a.c.alerts]
> (consoleproxy-1:ctx-2825c38c) (logid:64c127ac)  alertType:: 10 //
> dataCenterId:: 2 // podId:: null // clusterId:: null // message::
> Console proxy creation failure. zone: Intsys, error details: null
> 
> Regards Udo
> 
> -----Ursprüngliche Nachricht-----
> Von: Suresh Kumar Anaparti [mailto:sureshkumar.anaparti@gmail.com]
> Gesendet: Montag, 6. Mai 2019 11:34
> An: users@cloudstack.apache.org
> Betreff: Re: CS 4.9.2: System VMs not starting
> 
> 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.Mueller@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&respons
>> e=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","ctxDe
>> tails":"{\"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","c
>> txStartEventId":"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","ctxDe
>> tails":"{\"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","c
>> txStartEventId":"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&respons
>> e=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:
>> rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMA
>> AZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdW
>> RlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJ
>> MAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29y
>> a0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMA
>> AlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cg
>> ATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlckl
>> kSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAABAAAAAAAAAR
>> YHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA,
>> 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":44
>> 48,"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":44
>> 48,"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":"4
>> 803e585-78d3-45b8-8d8a-49944f05e5fa","systemvmtype":"consoleproxy","z
>> oneid":"978f1e08-8650-424f-b527-a1afd74305e9","zonename":"Intsys","dn
>> s1":"10.252.34.10","name":"v-4448-VM","templateid":"367b6a82-1471-4fa
>> 3-a3b9-c194213c27d6","created":"2019-04-30T13:26:56+0000","state":"St
>> opped","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-c296c2c46c4
>> b&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557
>> 130981948
>> 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-c296c2c46c4
>> b&response=json&projectid=53824f26-bf1d-4f3d-8f5c-d25a045e4abe&_=1557
>> 130981948
>> 
>> 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.Mueller@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.
>> 
>> 
Mime
View raw message