cloudstack+kvm 创建虚拟机日志报错

2017-12-21 08:38:35,880 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:c65a3e99) Exception: /usr/share/cloudstack-common/scripts/vm/network/security_group.py add_network_rules --vmname i-2-27-VM --vmid 27 --vmip 10.83.32.169 --vmip6 null --sig 1bb8f16bea8fcff2fa927946160a9d0e --seq 1 --vmmac 1e:00:22:00:00:0f --vif vnet5 --brname cloudbr0 --nicsecips 0: --rules I:icmp:-1:-1:0.0.0.0/0,NEXT;I:tcp:1:65535:0.0.0.0/0,NEXT;I:udp:1:65535:0.0.0.0/0,NEXT;
java.lang.NullPointerException
    at java.lang.ProcessBuilder.start(ProcessBuilder.java:1012)
    at com.cloud.utils.script.Script.execute(Script.java:214)
    at com.cloud.utils.script.Script.execute(Script.java:182)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.addNetworkRules(LibvirtComputingResource.java:3429)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:57)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:36)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:75)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1369)
    at com.cloud.agent.Agent.processRequest(Agent.java:525)
    at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:833)
    at com.cloud.utils.nio.Task.call(Task.java:83)
    at com.cloud.utils.nio.Task.call(Task.java:29)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2017-12-21 08:38:35,880 WARN  [resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper] (agentRequest-Handler-4:null) (logid:c65a3e99) Failed to program network rules for vm i-2-27-VM
2017-12-21 08:38:35,964 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null) (logid:85c0f077) Exception: /usr/share/cloudstack-common/scripts/vm/network/security_group.py add_network_rules --vmname i-2-27-VM --vmid 27 --vmip 10.83.32.169 --vmip6 null --sig 1bb8f16bea8fcff2fa927946160a9d0e --seq 1 --vmmac 1e:00:22:00:00:0f --vif vnet5 --brname cloudbr0 --nicsecips 0: --rules I:icmp:-1:-1:0.0.0.0/0,NEXT;I:tcp:1:65535:0.0.0.0/0,NEXT;I:udp:1:65535:0.0.0.0/0,NEXT;
java.lang.NullPointerException
    at java.lang.ProcessBuilder.start(ProcessBuilder.java:1012)
    at com.cloud.utils.script.Script.execute(Script.java:214)
    at com.cloud.utils.script.Script.execute(Script.java:182)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.addNetworkRules(LibvirtComputingResource.java:3429)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:57)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:36)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:75)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1369)
    at com.cloud.agent.Agent.processRequest(Agent.java:525)
    at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:833)
    at com.cloud.utils.nio.Task.call(Task.java:83)
    at com.cloud.utils.nio.Task.call(Task.java:29)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2017-12-21 08:38:35,964 WARN  [resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper] (agentRequest-Handler-5:null) (logid:85c0f077) Failed to program network rules for vm i-2-27-VM
已邀请:

zgui2000 - 80后IT男

赞同来自:

还有我每次通过management管理页面,选择停止虚拟机的时候要很久,所在的kvm宿主机上面的日志为:
2017-12-21 08:49:48,646 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:1d581b89) Timed out waiting for domain i-2-27-VM to shutdown gracefully

启动虚拟机的时候也会报错:
2017-12-21 08:54:08,072 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-5:null) (logid:f8fa1ce3) Exception: /usr/share/cloudstack-common/scripts/vm/network/security_group.py add_network_rules --vmname i-2-27-VM --vmid 27 --vmip 10.83.32.169 --vmip6 null --sig 1bb8f16bea8fcff2fa927946160a9d0e --seq 2 --vmmac 1e:00:22:00:00:0f --vif vnet5 --brname cloudbr0 --nicsecips 0: --rules I:icmp:-1:-1:0.0.0.0/0,NEXT;I:tcp:1:65535:0.0.0.0/0,NEXT;I:udp:1:65535:0.0.0.0/0,NEXT;
java.lang.NullPointerException
    at java.lang.ProcessBuilder.start(ProcessBuilder.java:1012)
    at com.cloud.utils.script.Script.execute(Script.java:214)
    at com.cloud.utils.script.Script.execute(Script.java:182)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.addNetworkRules(LibvirtComputingResource.java:3429)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:57)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper.execute(LibvirtSecurityGroupRulesCommandWrapper.java:36)
    at com.cloud.hypervisor.kvm.resource.wrapper.LibvirtRequestWrapper.execute(LibvirtRequestWrapper.java:75)
    at com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1369)
    at com.cloud.agent.Agent.processRequest(Agent.java:525)
    at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:833)
    at com.cloud.utils.nio.Task.call(Task.java:83)
    at com.cloud.utils.nio.Task.call(Task.java:29)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
2017-12-21 08:54:08,072 WARN  [resource.wrapper.LibvirtSecurityGroupRulesCommandWrapper] (agentRequest-Handler-5:null) (logid:f8fa1ce3) Failed to program network rules for vm i-2-27-VM


停止虚拟机的时候,管理端的日志如下:
2017-12-21 08:54:56,316 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) SeqA 9-8304: Processing Seq 9-8304:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:54:56,335 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) SeqA 9-8304: Sending Seq 9-8304:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:54:56,646 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-4ab8ded7) (logid:de82bf9b) ===START===  10.83.14.11 -- GET  command=stopVirtualMachine&id=b82fab4b-501e-4d75-8e86-dbf878cfd59d&forced=false&response=json&_=1513817694108
2017-12-21 08:54:56,694 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-43:ctx-add568c1 job-256) (logid:3fd8b24c) Add job-256 into job monitoring
2017-12-21 08:54:56,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-18:ctx-4ab8ded7 ctx-022027dd) (logid:de82bf9b) submit async job-256, details: AsyncJobVO {id:256, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 27, cmd: org.apache.cloudstack.api.command.admin.vm.StopVMCmdByAdmin, cmdInfo: {"forced":"false","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"547","id":"b82fab4b-501e-4d75-8e86-dbf878cfd59d","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"b82fab4b-501e-4d75-8e86-dbf878cfd59d\"}","ctxAccountId":"2","uuid":"b82fab4b-501e-4d75-8e86-dbf878cfd59d","cmdEventType":"VM.STOP","_":"1513817694108"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90592323948, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2017-12-21 08:54:56,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-43:ctx-add568c1 job-256) (logid:f1dfa574) Executing AsyncJobVO {id:256, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 27, cmd: org.apache.cloudstack.api.command.admin.vm.StopVMCmdByAdmin, cmdInfo: {"forced":"false","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"547","id":"b82fab4b-501e-4d75-8e86-dbf878cfd59d","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"b82fab4b-501e-4d75-8e86-dbf878cfd59d\"}","ctxAccountId":"2","uuid":"b82fab4b-501e-4d75-8e86-dbf878cfd59d","cmdEventType":"VM.STOP","_":"1513817694108"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90592323948, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2017-12-21 08:54:56,697 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-4ab8ded7 ctx-022027dd) (logid:de82bf9b) ===END===  10.83.14.11 -- GET  command=stopVirtualMachine&id=b82fab4b-501e-4d75-8e86-dbf878cfd59d&forced=false&response=json&_=1513817694108
2017-12-21 08:54:56,736 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-43:ctx-add568c1 job-256 ctx-b4daabc7) (logid:f1dfa574) Sync job-257 execution on object VmWorkJobQueue.27
2017-12-21 08:54:58,010 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0ac8945c) (logid:fd359da7) Execute sync-queue item: SyncQueueItemVO {id:85, queueId: 89, contentType: AsyncJob, contentId: 257, lastProcessMsid: 90592323948, lastprocessNumber: 4, lastProcessTime: Thu Dec 21 08:54:57 CST 2017, created: Thu Dec 21 08:54:56 CST 2017}
2017-12-21 08:54:58,011 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-0ac8945c) (logid:fd359da7) Schedule queued job-257
2017-12-21 08:54:58,045 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-39:ctx-def568da job-256/job-257) (logid:d6929f71) Add job-257 into job monitoring
2017-12-21 08:54:58,049 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-39:ctx-def568da job-256/job-257) (logid:f1dfa574) Executing AsyncJobVO {id:257, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90592323948, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Dec 21 08:54:56 CST 2017}
2017-12-21 08:54:58,049 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-39:ctx-def568da job-256/job-257) (logid:f1dfa574) Run VM work job: com.cloud.vm.VmWorkStop for VM 27, job origin: 256
2017-12-21 08:54:58,050 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":27,"handlerName":"VirtualMachineManagerImpl"}
2017-12-21 08:54:58,069 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) VM state transitted from :Running to Stopping with event: StopRequestedvm's original host id: 4 new host id: 4 host id before state transition: 4
2017-12-21 08:54:58,070 DEBUG [c.c.v.UserVmManagerImpl] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) Collect vm disk statistics from host before stopping Vm
2017-12-21 08:54:58,115 DEBUG [c.c.a.t.Request] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) Seq 4-500462508591547712: Received:  { Ans: , MgmtId: 90592323948, via: 4(c4.bqjr.me), Ver: v1, Flags: 10, { GetVmDiskStatsAnswer } }
2017-12-21 08:54:58,116 DEBUG [c.c.a.m.AgentManagerImpl] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) Details from executing class com.cloud.agent.api.GetVmDiskStatsCommand:
2017-12-21 08:54:58,117 DEBUG [c.c.a.t.Request] (Work-Job-Executor-39:ctx-def568da job-256/job-257 ctx-6874e4da) (logid:f1dfa574) Seq 4-500462508591547713: Sending  { Cmd , MgmtId: 90592323948, via: 4(c4.bqjr.me), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"vmName":"i-2-27-VM","executeInSequence":false,"wait":0}}] }
2017-12-21 08:54:59,720 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-3544eea5) (logid:e795f958) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817697182
2017-12-21 08:54:59,736 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-3544eea5 ctx-4f2d70ad) (logid:e795f958) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817697182
2017-12-21 08:55:02,722 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-f80fd41a) (logid:effeb41d) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817700183
2017-12-21 08:55:02,756 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-f80fd41a ctx-2ebc4df1) (logid:effeb41d) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817700183
2017-12-21 08:55:04,554 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-9432a638) (logid:3f2b20ae) Zone 1 is ready to launch console proxy
2017-12-21 08:55:04,699 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-e5969eba) (logid:7e399b32) Zone 1 is ready to launch secondary storage VM
2017-12-21 08:55:05,722 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-bdb3b4e3) (logid:8b068175) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817703183
2017-12-21 08:55:05,755 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-bdb3b4e3 ctx-bf9ca33f) (logid:8b068175) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817703183
2017-12-21 08:55:05,982 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6eb5c5bf) (logid:51bb529b) Begin cleanup expired async-jobs
2017-12-21 08:55:05,988 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6eb5c5bf) (logid:51bb529b) End cleanup expired async-jobs
2017-12-21 08:55:06,317 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) SeqA 9-8305: Processing Seq 9-8305:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:06,420 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) SeqA 9-8305: Sending Seq 9-8305:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:08,721 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-dac8f270) (logid:bd91df36) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817706183
2017-12-21 08:55:08,738 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-dac8f270 ctx-6b89650b) (logid:bd91df36) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817706183
2017-12-21 08:55:11,724 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-02d86c5a) (logid:9f8a4ec4) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817709183
2017-12-21 08:55:11,757 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-02d86c5a ctx-dbde50bc) (logid:9f8a4ec4) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817709183
2017-12-21 08:55:14,723 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-0ecd8368) (logid:530ca098) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817712185
2017-12-21 08:55:14,757 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-0ecd8368 ctx-ff29ccfc) (logid:530ca098) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817712185
2017-12-21 08:55:15,983 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-564181bb) (logid:7ccb27a8) Begin cleanup expired async-jobs
2017-12-21 08:55:15,988 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-564181bb) (logid:7ccb27a8) End cleanup expired async-jobs
2017-12-21 08:55:16,101 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:ctx-09e20370) (logid:7d694ba2) External devices are not used. Skipping external device usage collection
2017-12-21 08:55:16,111 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:ctx-379b5156) (logid:8c6b06dc) Found 0 running routers.
2017-12-21 08:55:16,111 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-93ec9a1a) (logid:3b7040d8) Found 0 routers to update status.
2017-12-21 08:55:16,113 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-93ec9a1a) (logid:3b7040d8) Found 0 VPC networks to update Redundant State.
2017-12-21 08:55:16,114 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-93ec9a1a) (logid:3b7040d8) Found 0 networks to update RvR status.
2017-12-21 08:55:16,127 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-c17b1f9f) (logid:fd566b11) Snapshot scheduler.poll is being called at 2017-12-21 00:55:16 GMT
2017-12-21 08:55:16,128 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-c17b1f9f) (logid:fd566b11) Got 0 snapshots to be executed at 2017-12-21 00:55:16 GMT
2017-12-21 08:55:16,279 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 9-8306: Processing Seq 9-8306:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:16,296 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) (logid:) SeqA 9-8306: Sending Seq 9-8306:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:17,724 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-ec84966e) (logid:cc6315c6) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817715185
2017-12-21 08:55:17,758 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-ec84966e ctx-687164a5) (logid:cc6315c6) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817715185
2017-12-21 08:55:20,726 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-da003359) (logid:42692b03) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817718186
2017-12-21 08:55:20,757 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-da003359 ctx-49bef87c) (logid:42692b03) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817718186
2017-12-21 08:55:21,245 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Resetting hosts suitable for reconnect
2017-12-21 08:55:21,247 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Completed resetting hosts suitable for reconnect
2017-12-21 08:55:21,247 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Acquiring hosts for clusters already owned by this management server
2017-12-21 08:55:21,247 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Completed acquiring hosts for clusters already owned by this management server
2017-12-21 08:55:21,247 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Acquiring hosts for clusters not owned by any management server
2017-12-21 08:55:21,248 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-ef999862) (logid:cb0eef74) Completed acquiring hosts for clusters not owned by any management server
2017-12-21 08:55:21,320 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 9-8307: Processing Seq 9-8307:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:21,414 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) (logid:) SeqA 9-8307: Sending Seq 9-8307:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:23,726 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-7226b141) (logid:2bf82151) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817721186
2017-12-21 08:55:23,758 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-7226b141 ctx-77e75869) (logid:2bf82151) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817721186
2017-12-21 08:55:25,977 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) Ping from 6(c6.bqjr.me)
2017-12-21 08:55:25,977 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-5:null) (logid:) Process host VM state report from ping process. host: 6
2017-12-21 08:55:25,980 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-5:null) (logid:) Process VM state report. host: 6, number of records in report: 1
2017-12-21 08:55:25,980 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-5:null) (logid:) VM state report. host: 6, vm id: 26, power state: PowerOn
2017-12-21 08:55:25,983 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f2eb5155) (logid:2a5145e9) Begin cleanup expired async-jobs
2017-12-21 08:55:25,983 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-5:null) (logid:) VM power state does not change, skip DB writing. vm id: 26
2017-12-21 08:55:25,986 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-5:null) (logid:) Done with process of VM state report. host: 6
2017-12-21 08:55:25,988 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f2eb5155) (logid:2a5145e9) End cleanup expired async-jobs
2017-12-21 08:55:26,343 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) Ping from 1(c2.bqjr.me)
2017-12-21 08:55:26,343 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Process host VM state report from ping process. host: 1
2017-12-21 08:55:26,346 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Process VM state report. host: 1, number of records in report: 1
2017-12-21 08:55:26,346 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM state report. host: 1, vm id: 16, power state: PowerOn
2017-12-21 08:55:26,348 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) Ping from 5(c5.bqjr.me)
2017-12-21 08:55:26,348 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process host VM state report from ping process. host: 5
2017-12-21 08:55:26,348 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Process VM state report. host: 5, number of records in report: 0
2017-12-21 08:55:26,349 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) VM power state does not change, skip DB writing. vm id: 16
2017-12-21 08:55:26,350 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-7:null) (logid:) Done with process of VM state report. host: 5
2017-12-21 08:55:26,352 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-1:null) (logid:) Done with process of VM state report. host: 1
2017-12-21 08:55:26,501 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) Ping from 4(c4.bqjr.me)
2017-12-21 08:55:26,501 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) Process host VM state report from ping process. host: 4
2017-12-21 08:55:26,510 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) Process VM state report. host: 4, number of records in report: 3
2017-12-21 08:55:26,510 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM state report. host: 4, vm id: 17, power state: PowerOn
2017-12-21 08:55:26,512 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM power state does not change, skip DB writing. vm id: 17
2017-12-21 08:55:26,512 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM state report. host: 4, vm id: 19, power state: PowerOn
2017-12-21 08:55:26,515 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM power state does not change, skip DB writing. vm id: 19
2017-12-21 08:55:26,515 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM state report. host: 4, vm id: 27, power state: PowerOn
2017-12-21 08:55:26,517 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) VM power state does not change, skip DB writing. vm id: 27
2017-12-21 08:55:26,521 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-6:null) (logid:) Done with process of VM state report. host: 4
2017-12-21 08:55:26,726 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-9e59ccd4) (logid:f393600a) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817724187
2017-12-21 08:55:26,748 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-9e59ccd4 ctx-cc0751df) (logid:f393600a) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817724187
2017-12-21 08:55:26,942 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) (logid:) Ping from 10(s-17-VM)
2017-12-21 08:55:26,960 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) Ping from 9(v-16-VM)
2017-12-21 08:55:29,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-2e0083b8) (logid:069f5e0d) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817727187
2017-12-21 08:55:29,749 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-2e0083b8 ctx-e74cc84e) (logid:069f5e0d) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817727187
2017-12-21 08:55:31,321 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 9-8309: Processing Seq 9-8309:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:31,340 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) (logid:) SeqA 9-8309: Sending Seq 9-8309:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:31,475 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-a1718719) (logid:87c9f7f1) HostOutOfBandManagementStatsCollector is running...
2017-12-21 08:55:32,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-73d04ea4) (logid:03f22be2) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817730187
2017-12-21 08:55:32,759 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-73d04ea4 ctx-0e67d9ce) (logid:03f22be2) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817730187
2017-12-21 08:55:32,889 DEBUG [c.c.s.StatsCollector] (StatsCollector-6:ctx-6fd3ec7f) (logid:fc94437e) AutoScaling Monitor is running...
2017-12-21 08:55:33,051 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-bc667caa) (logid:3522282c) HostStatsCollector is running...
2017-12-21 08:55:33,103 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-bc667caa) (logid:3522282c) Seq 1-1447344330246194505: Received:  { Ans: , MgmtId: 90592323948, via: 1(c2.bqjr.me), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2017-12-21 08:55:33,153 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-bc667caa) (logid:3522282c) Seq 4-500462508591547714: Received:  { Ans: , MgmtId: 90592323948, via: 4(c4.bqjr.me), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2017-12-21 08:55:33,204 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-bc667caa) (logid:3522282c) Seq 5-4092646161372939536: Received:  { Ans: , MgmtId: 90592323948, via: 5(c5.bqjr.me), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2017-12-21 08:55:33,261 DEBUG [c.c.a.t.Request] (StatsCollector-4:ctx-bc667caa) (logid:3522282c) Seq 6-4302907968975800432: Received:  { Ans: , MgmtId: 90592323948, via: 6(c6.bqjr.me), Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2017-12-21 08:55:34,552 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-21ef64fd) (logid:9be3d404) Zone 1 is ready to launch console proxy
2017-12-21 08:55:34,700 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-61c860eb) (logid:e480fd98) Zone 1 is ready to launch secondary storage VM
2017-12-21 08:55:35,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-f0939c3f) (logid:966bfc08) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817733188
2017-12-21 08:55:35,760 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-f0939c3f ctx-144fcbd6) (logid:966bfc08) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817733188
2017-12-21 08:55:35,981 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b0f27e7) (logid:18635b47) Begin cleanup expired async-jobs
2017-12-21 08:55:35,987 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-6b0f27e7) (logid:18635b47) End cleanup expired async-jobs
2017-12-21 08:55:37,831 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-0d6f770f) (logid:62b1f185) VmStatsCollector is running...
2017-12-21 08:55:37,904 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0d6f770f) (logid:62b1f185) Seq 6-4302907968975800433: Received:  { Ans: , MgmtId: 90592323948, via: 6(c6.bqjr.me), Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2017-12-21 08:55:38,728 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-181e0f22) (logid:cea88a9f) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817736188
2017-12-21 08:55:38,761 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-181e0f22 ctx-02f183ab) (logid:cea88a9f) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817736188
2017-12-21 08:55:41,322 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) SeqA 9-8310: Processing Seq 9-8310:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:41,350 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) (logid:) SeqA 9-8310: Sending Seq 9-8310:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:41,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-e14dea31) (logid:cf49dab5) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817739187
2017-12-21 08:55:41,760 DEBUG [c.c.a.ApiServlet] (catalina-exec-6:ctx-e14dea31 ctx-0aa7210f) (logid:cf49dab5) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817739187
2017-12-21 08:55:43,740 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) StorageCollector is running...
2017-12-21 08:55:43,750 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2017-12-21 08:55:43,750 DEBUG [c.c.h.XenServerGuru] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2017-12-21 08:55:43,802 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) Seq 10-5682416829834724332: Received:  { Ans: , MgmtId: 90592323948, via: 10(s-17-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2017-12-21 08:55:43,804 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2017-12-21 08:55:43,804 DEBUG [c.c.h.XenServerGuru] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) getCommandHostDelegation: class com.cloud.agent.api.GetStorageStatsCommand
2017-12-21 08:55:43,955 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-7274b627) (logid:ada53ec5) Seq 6-4302907968975800434: Received:  { Ans: , MgmtId: 90592323948, via: 6(c6.bqjr.me), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2017-12-21 08:55:44,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-2c8c72d6) (logid:7b52cec3) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817742187
2017-12-21 08:55:44,751 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-2c8c72d6 ctx-580f0c02) (logid:7b52cec3) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817742187
2017-12-21 08:55:45,980 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-13193cd5) (logid:692c3810) Begin cleanup expired async-jobs
2017-12-21 08:55:45,983 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-13193cd5) (logid:692c3810) End cleanup expired async-jobs
2017-12-21 08:55:46,110 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-36c232de) (logid:99d169fb) Found 0 routers to update status.
2017-12-21 08:55:46,111 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-36c232de) (logid:99d169fb) Found 0 VPC networks to update Redundant State.
2017-12-21 08:55:46,111 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-36c232de) (logid:99d169fb) Found 0 networks to update RvR status.
2017-12-21 08:55:46,121 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Running Capacity Checker ...
2017-12-21 08:55:46,122 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) recalculating system capacity
2017-12-21 08:55:46,122 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Executing cpu/ram capacity update
2017-12-21 08:55:46,124 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 1 VMs on host 1
2017-12-21 08:55:46,125 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 0 VM, not running on host 1
2017-12-21 08:55:46,125 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate cpu capacity, host:1 usedCpu: 500 reservedCpu: 0
2017-12-21 08:55:46,125 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate memory capacity, host:1 usedMem: 1073741824 reservedMem: 0
2017-12-21 08:55:46,143 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 2 VMs on host 4
2017-12-21 08:55:46,144 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 0 VM, not running on host 4
2017-12-21 08:55:46,145 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Calibrate used cpu for host: 4 old usedCpu:2000 new usedCpu:1000
2017-12-21 08:55:46,145 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Calibrate used memory for host: 4 old usedMem: 1879048192 new usedMem: 805306368
2017-12-21 08:55:46,176 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 0 VMs on host 5
2017-12-21 08:55:46,177 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 0 VM, not running on host 5
2017-12-21 08:55:46,177 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate cpu capacity, host:5 usedCpu: 0 reservedCpu: 0
2017-12-21 08:55:46,177 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate memory capacity, host:5 usedMem: 0 reservedMem: 0
2017-12-21 08:55:46,193 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 1 VMs on host 6
2017-12-21 08:55:46,194 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found 0 VM, not running on host 6
2017-12-21 08:55:46,195 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate cpu capacity, host:6 usedCpu: 1000 reservedCpu: 0
2017-12-21 08:55:46,195 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) No need to calibrate memory capacity, host:6 usedMem: 1073741824 reservedMem: 0
2017-12-21 08:55:46,199 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-3ce315cb) (logid:7c71eaa5) Checking if any host reservation can be released ...
2017-12-21 08:55:46,201 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-3ce315cb) (logid:7c71eaa5) Cannot release reservation, Found 1 VMs Running on host 1
2017-12-21 08:55:46,203 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-3ce315cb) (logid:7c71eaa5) Cannot release reservation, Found 2 VMs Running on host 4
2017-12-21 08:55:46,204 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-3ce315cb) (logid:7c71eaa5) Cannot release reservation, Found 1 VMs Running on host 6
2017-12-21 08:55:46,204 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-3ce315cb) (logid:7c71eaa5) Done running HostReservationReleaseChecker ...
2017-12-21 08:55:46,208 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done executing cpu/ram capacity update
2017-12-21 08:55:46,208 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Executing storage capacity update
2017-12-21 08:55:46,210 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Found storage pool primary of type Gluster
2017-12-21 08:55:46,210 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Total over provisioned capacity of the pool primary id: 1 is 1698765209600
2017-12-21 08:55:46,225 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Successfully set Capacity - 1698765209600 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2017-12-21 08:55:46,225 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done executing storage capacity update
2017-12-21 08:55:46,225 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Executing capacity updates for public ip and Vlans
2017-12-21 08:55:46,226 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done capacity updates for public ip and Vlans
2017-12-21 08:55:46,226 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Executing capacity updates for private ip
2017-12-21 08:55:46,228 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done executing capacity updates for private ip
2017-12-21 08:55:46,228 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done recalculating system capacity
2017-12-21 08:55:46,233 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-3619d16a) (logid:062988d1) Done running Capacity Checker ...
2017-12-21 08:55:46,322 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) SeqA 9-8311: Processing Seq 9-8311:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:46,342 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) (logid:) SeqA 9-8311: Sending Seq 9-8311:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:47,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-eeba1a0e) (logid:fa5e38d3) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817745188
2017-12-21 08:55:47,761 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-eeba1a0e ctx-9b1b63b3) (logid:fa5e38d3) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817745188
2017-12-21 08:55:50,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-6e87cd74) (logid:64b4fd31) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817748188
2017-12-21 08:55:50,761 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-6e87cd74 ctx-303a0954) (logid:64b4fd31) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817748188
2017-12-21 08:55:53,727 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-845515dc) (logid:9a9cfb70) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817751187
2017-12-21 08:55:53,763 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-845515dc ctx-48697631) (logid:9a9cfb70) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817751187
2017-12-21 08:55:55,983 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-14e19734) (logid:2063d8fe) Begin cleanup expired async-jobs
2017-12-21 08:55:55,988 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-14e19734) (logid:2063d8fe) End cleanup expired async-jobs
2017-12-21 08:55:56,324 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) SeqA 9-8312: Processing Seq 9-8312:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:55:56,351 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) (logid:) SeqA 9-8312: Sending Seq 9-8312:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:55:56,728 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-1169faf9) (logid:d0ca2fe7) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817754187
2017-12-21 08:55:56,752 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-1169faf9 ctx-bcd3573b) (logid:d0ca2fe7) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817754187
2017-12-21 08:55:59,729 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-9a5816a0) (logid:8a611149) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817757189
2017-12-21 08:55:59,762 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-9a5816a0 ctx-15a4c581) (logid:8a611149) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817757189
2017-12-21 08:56:01,325 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 9-8313: Processing Seq 9-8313:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:56:01,344 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-1:null) (logid:) SeqA 9-8313: Sending Seq 9-8313:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:56:02,730 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-46ef17d6) (logid:7019ab24) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817760189
2017-12-21 08:56:02,762 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-46ef17d6 ctx-dd31a469) (logid:7019ab24) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817760189
2017-12-21 08:56:04,553 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-11c9e8c4) (logid:cdbae60c) Zone 1 is ready to launch console proxy
2017-12-21 08:56:04,700 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-5fe0d4ec) (logid:80763f59) Zone 1 is ready to launch secondary storage VM
2017-12-21 08:56:05,730 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-ce36f887) (logid:c8165601) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817763189
2017-12-21 08:56:05,764 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-ce36f887 ctx-dd8fe621) (logid:c8165601) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817763189
2017-12-21 08:56:05,981 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-fb0c2d7c) (logid:d21a55c7) Begin cleanup expired async-jobs
2017-12-21 08:56:05,986 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-fb0c2d7c) (logid:d21a55c7) End cleanup expired async-jobs
2017-12-21 08:56:08,731 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-773385e4) (logid:c4575a42) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817766190
2017-12-21 08:56:08,763 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-773385e4 ctx-a0007c6f) (logid:c4575a42) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817766190
2017-12-21 08:56:11,327 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 9-8314: Processing Seq 9-8314:  { Cmd , MgmtId: -1, via: 9, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":16,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2017-12-21 08:56:11,354 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) (logid:) SeqA 9-8314: Sending Seq 9-8314:  { Ans: , MgmtId: 90592323948, via: 9, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2017-12-21 08:56:11,732 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-d0819f24) (logid:67061571) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817769191
2017-12-21 08:56:11,764 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-d0819f24 ctx-c54c294e) (logid:67061571) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817769191
2017-12-21 08:56:14,733 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-59beb33f) (logid:4bea63e6) ===START===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817772192
2017-12-21 08:56:14,765 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-59beb33f ctx-fab01ac0) (logid:4bea63e6) ===END===  10.83.14.11 -- GET  command=queryAsyncJobResult&jobId=f1dfa574-5b37-41ce-9dd5-db0bb7c1a486&response=json&_=1513817772192
2017-12-21 08:56:15,980 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-788e0526) (logid:5089b803) Begin cleanup expired async-jobs
2017-12-21 08:56:15,983 INFO  [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-788e0526) (logid:5089b803) End cleanup expired async-jobs
2017-12-21 08:56:16,110 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-43a856e4) (logid:09fc70ca) Found 0 routers to update status.

kvm端的日志如下:
2017-12-21 08:56:58,668 WARN  [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-4:null) (logid:f1dfa574) Timed out waiting for domain i-2-27-VM to shutdown gracefully
当kvm端的日志显示出来之后页面就显示已经关机了。

要回复问题请先登录注册