Re: AW: AW: CS 4.9.2: System VMs not starting

Tue, 07 May 2019 18:38:13 -0700 

Hi Udo,

This issue your having aside for a moment;
How many hosts in a cluster sharing the GFS2 file system? I had issues scaling more then 2 nodes because of locking performance problems. I imagine your IO is horrible as well, as in a few MB/s. I used CLVM instead of mounting a GFS2 file system (xenserver style). Performance was as expected using CLVM. 

Adrian Sender

On 2019-05-07 21:46, Mueller, Udo wrote:

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: asen...@testlabs.com.au [mailto:asen...@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.anapa...@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.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.

Reply via email to