You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Chandan Purushothama (JIRA)" <ji...@apache.org> on 2014/10/21 22:01:35 UTC
[jira] [Created] (CLOUDSTACK-7761) [Automation] Rebooting System
VMs - VMs are getting stopped and started instead of reboot
Chandan Purushothama created CLOUDSTACK-7761:
------------------------------------------------
Summary: [Automation] Rebooting System VMs - VMs are getting stopped and started instead of reboot
Key: CLOUDSTACK-7761
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7761
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Automation
Affects Versions: 4.5.0
Reporter: Chandan Purushothama
Assignee: Anthony Xu
Priority: Critical
Fix For: 4.5.0
Rebooting System VM using cases are failing on the automation as shown below:
*Error Message*
Check Private IP after reboot with that of before reboot
*Stacktrace*
File "/usr/lib/python2.7/unittest/case.py", line 332, in run
testMethod()
File "/root/cloudstack/test/integration/smoke/test_ssvm.py", line 725, in test_07_reboot_ssvm
"Check Private IP after reboot with that of before reboot"
File "/usr/lib/python2.7/unittest/case.py", line 516, in assertEqual
assertion_func(first, second, msg=msg)
File "/usr/lib/python2.7/unittest/case.py", line 927, in assertMultiLineEqual
self.fail(self._formatMessage(msg, standardMsg))
File "/usr/lib/python2.7/unittest/case.py", line 413, in fail
raise self.failureException(msg)
'Check Private IP after reboot with that of before reboot\n
On further analysis, we found that the reboot command is actually calling Stopcommand in the later part of the job. This results in the change in private ip address.
{noformat}
2014-10-21 17:06:35,451 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-f76226cf) ===START=== 10.220.135.30 -- GET response=json&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=rebootSystemVm&id=0d3261c0-18af-4f4f-8052-78398ea3d319&signature=TXvdc%2FRdiaOYDVvVKjoo%2FYaoMho%3D
2014-10-21 17:06:35,476 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-21:ctx-f76226cf ctx-64e39462 ctx-47749a02) submit async job-547, details: AsyncJobVO {id:547, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 2, cmd: org.apache.cloudstack.api.command.admin.systemvm.RebootSystemVmCmd, cmdInfo: {"response":"json","id":"0d3261c0-18af-4f4f-8052-78398ea3d319","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"0d3261c0-18af-4f4f-8052-78398ea3d319\"}","cmdEventType":"PROXY.REBOOT","ctxUserId":"2","httpmethod":"GET","uuid":"0d3261c0-18af-4f4f-8052-78398ea3d319","ctxAccountId":"2","ctxStartEventId":"1702","apiKey":"8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg","signature":"TXvdc/RdiaOYDVvVKjoo/YaoMho\u003d"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 59825535280071, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-10-21 17:06:35,476 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-44:ctx-7d84e64c job-547) Add job-547 into job monitoring
2014-10-21 17:06:35,476 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547) Executing AsyncJobVO {id:547, userId: 2, accountId: 2, instanceType: SystemVm, instanceId: 2, cmd: org.apache.cloudstack.api.command.admin.systemvm.RebootSystemVmCmd, cmdInfo: {"response":"json","id":"0d3261c0-18af-4f4f-8052-78398ea3d319","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"0d3261c0-18af-4f4f-8052-78398ea3d319\"}","cmdEventType":"PROXY.REBOOT","ctxUserId":"2","httpmethod":"GET","uuid":"0d3261c0-18af-4f4f-8052-78398ea3d319","ctxAccountId":"2","ctxStartEventId":"1702","apiKey":"8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg","signature":"TXvdc/RdiaOYDVvVKjoo/YaoMho\u003d"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 59825535280071, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-10-21 17:06:35,477 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-f76226cf ctx-64e39462 ctx-47749a02) ===END=== 10.220.135.30 -- GET response=json&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=rebootSystemVm&id=0d3261c0-18af-4f4f-8052-78398ea3d319&signature=TXvdc%2FRdiaOYDVvVKjoo%2FYaoMho%3D
2014-10-21 17:06:35,483 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-a631c521) ===START=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:35,504 DEBUG [c.c.a.t.Request] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Seq 2-7242632625741890164: Sending { Cmd , MgmtId: 59825535280071, via: 2(cl09-A-08), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.RebootCommand":{"vmName":"v-2-VM","wait":0}}] }
2014-10-21 17:06:35,506 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-a631c521 ctx-75530939 ctx-3d3149fb) ===END=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:36,025 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3--1: Processing Seq 3--1: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 111, [{"com.cloud.agent.api.ShutdownCommand":{"reason":"sig.kill","wait":0}}] }
2014-10-21 17:06:36,025 INFO [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) Host 3 has informed us that it is shutting down with reason sig.kill and detail null
2014-10-21 17:06:36,026 INFO [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Host 3 is disconnecting with event ShutdownRequested
2014-10-21 17:06:36,027 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) The next status of agent 3 is Disconnected, current status is Up
2014-10-21 17:06:36,027 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Deregistering link for 3 with state Disconnected
2014-10-21 17:06:36,027 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Remove Agent : 3
2014-10-21 17:06:36,027 DEBUG [c.c.a.m.ConnectedAgentAttache] (AgentTaskPool-4:ctx-430ab573) Processing Disconnect.
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.hypervisor.xenserver.discoverer.XcpServerDiscoverer
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.hypervisor.hyperv.discoverer.HypervServerDiscoverer
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: org.apache.cloudstack.engine.orchestration.NetworkOrchestrator
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.deploy.DeploymentPlanningManagerImpl
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.storage.listener.StoragePoolMonitor
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.vm.ClusteredVirtualMachineManagerImpl
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.hypervisor.vmware.manager.VmwareManagerImpl
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.security.SecurityGroupListener
2014-10-21 17:06:36,028 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.storage.secondary.SecondaryStorageListener
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.SshKeysDistriMonitor
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.router.VpcVirtualNetworkApplianceManagerImpl
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.NetworkUsageManagerImpl$DirectNetworkStatsListener
2014-10-21 17:06:36,029 DEBUG [c.c.n.NetworkUsageManagerImpl] (AgentTaskPool-4:ctx-430ab573) Disconnected called on 3 with status Disconnected
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.SshKeysDistriMonitor
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.network.router.VirtualNetworkApplianceManagerImpl
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.agent.manager.AgentManagerImpl$BehindOnPingListener
2014-10-21 17:06:36,029 DEBUG [c.c.a.m.AgentManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sending Disconnect to listener: com.cloud.consoleproxy.ConsoleProxyListener
2014-10-21 17:06:36,030 INFO [c.c.c.ConsoleProxyManagerImpl] (AgentTaskPool-4:ctx-430ab573) Console proxy agent disconnected, proxy: v-2-VM
2014-10-21 17:06:36,033 WARN [o.a.c.f.j.AsyncJobExecutionContext] (AgentTaskPool-4:ctx-430ab573) Job is executed without a context, setup psudo job for the executing thread
2014-10-21 17:06:36,047 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AgentTaskPool-4:ctx-430ab573) Sync job-549 execution on object VmWorkJobQueue.2
2014-10-21 17:06:38,015 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-30e36079) Execute sync-queue item: SyncQueueItemVO {id:206, queueId: 2, contentType: AsyncJob, contentId: 549, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Tue Oct 21 17:06:36 UTC 2014}
2014-10-21 17:06:38,016 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-30e36079) Schedule queued job-549
2014-10-21 17:06:38,019 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549) Add job-549 into job monitoring
2014-10-21 17:06:38,019 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549) Executing AsyncJobVO {id:549, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAAnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 59825535280071, completeMsid: null, lastUpdated: null, lastPolled: null, created: Tue Oct 21 17:06:36 UTC 2014}
2014-10-21 17:06:38,019 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549) Run VM work job: com.cloud.vm.VmWorkStop for VM 2, job origin: 548
2014-10-21 17:06:38,020 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549 ctx-f142c8e2) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":2,"handlerName":"VirtualMachineManagerImpl"}
2014-10-21 17:06:38,031 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549 ctx-f142c8e2) VM state transitted from :Running to Stopping with event: StopRequestedvm's original host id: 2 new host id: 2 host id before state transition: 2
2014-10-21 17:06:38,035 DEBUG [c.c.a.t.Request] (Work-Job-Executor-41:ctx-966b6925 job-548/job-549 ctx-f142c8e2) Seq 2-7242632625741890165: Sending { Cmd , MgmtId: 59825535280071, via: 2(cl09-A-08), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"v-2-VM","wait":0}}] }
2014-10-21 17:06:38,456 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-2:ctx-308251fd) Storage pool garbage collector found 0 templates to clean up in storage pool: XenRT-Zone-0-Pod-0-Cluster-0-Primary-Store-0
2014-10-21 17:06:38,460 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-2:ctx-308251fd) Secondary storage garbage collector found 0 templates to cleanup on template_store_ref for store: nfs://10.220.160.33/vol/export/871375-eLdP6E
2014-10-21 17:06:38,462 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-2:ctx-308251fd) Secondary storage garbage collector found 0 snapshots to cleanup on snapshot_store_ref for store: nfs://10.220.160.33/vol/export/871375-eLdP6E
2014-10-21 17:06:38,463 DEBUG [c.c.s.StorageManagerImpl] (StorageManager-Scavenger-2:ctx-308251fd) Secondary storage garbage collector found 0 volumes to cleanup on volume_store_ref for store: nfs://10.220.160.33/vol/export/871375-eLdP6E
2014-10-21 17:06:40,016 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-5cc6c3b3) Begin cleanup expired async-jobs
2014-10-21 17:06:40,023 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-5cc6c3b3) End cleanup expired async-jobs
2014-10-21 17:06:40,518 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e1d836e8) ===START=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:40,543 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-e1d836e8 ctx-0e5aa01c ctx-7e1a08f9) ===END=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:42,567 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null) Seq 2-7242632625741890164: Processing: { Ans: , MgmtId: 59825535280071, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.RebootAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2014-10-21 17:06:42,567 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-13:null) Seq 2-7242632625741890164: No more commands found
2014-10-21 17:06:42,567 DEBUG [c.c.a.t.Request] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Seq 2-7242632625741890164: Received: { Ans: , MgmtId: 59825535280071, via: 2, Ver: v1, Flags: 110, { RebootAnswer } }
2014-10-21 17:06:42,567 DEBUG [c.c.c.ConsoleProxyManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Successfully reboot console proxy v-2-VM
2014-10-21 17:06:42,567 DEBUG [c.c.a.ConsoleProxyAlertAdapter] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) received console proxy alert
2014-10-21 17:06:42,573 DEBUG [c.c.a.ConsoleProxyAlertAdapter] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Console proxy is rebooted, zone: XenRT-Zone-0, proxy: v-2-VM, public IP: 10.220.166.18, private IP: 10.220.165.114
2014-10-21 17:06:42,574 WARN [o.a.c.alerts] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) alertType:: 10 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Console proxy rebooted in zone: XenRT-Zone-0, proxy: v-2-VM, public IP: 10.220.166.18, private IP: 10.220.165.114
2014-10-21 17:06:42,617 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Complete async job-547, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SystemVmResponse/systemvm/{"id":"0d3261c0-18af-4f4f-8052-78398ea3d319","systemvmtype":"consoleproxy","zoneid":"32923188-631a-4b07-891b-b58cea6ad6ea","zonename":"XenRT-Zone-0","dns1":"10.220.160.11","gateway":"10.220.160.1","name":"v-2-VM","podid":"e96d1dd8-7ad4-45c1-b5be-8272cf0457e6","hostid":"ca2466c0-1866-4d5e-a744-379ab7838659","hostname":"cl09-A-08","hypervisor":"KVM","privateip":"10.220.165.114","privatemacaddress":"06:b8:96:00:00:02","privatenetmask":"255.255.240.0","linklocalip":"169.254.3.162","linklocalmacaddress":"0e:00:a9:fe:03:a2","linklocalnetmask":"255.255.0.0","publicip":"10.220.166.18","publicmacaddress":"06:8c:56:00:00:16","publicnetmask":"255.255.240.0","templateid":"cad1e542-5933-11e4-b66b-366937c763c7","created":"2014-10-21T15:27:32+0000","state":"Stopping","activeviewersessions":0}
2014-10-21 17:06:42,619 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Publish async job-547 complete on message bus
2014-10-21 17:06:42,619 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Wake up jobs related to job- 547
2014-10-21 17:06:42,619 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Update db status for job- 547
2014-10-21 17:06:42,620 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547 ctx-dfce25f5) Wake up jobs joined with job- 547 and disjoin all subjobs created from job- 547
2014-10-21 17:06:42,622 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-44:ctx-7d84e64c job-547) Done executing org.apache.cloudstack.api.command.admin.systemvm.RebootSystemVmCmd for job-547
2014-10-21 17:06:42,626 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-44:ctx-7d84e64c job-547) Remove job-547 from job monitoring
2014-10-21 17:06:45,555 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-9f3a9300) ===START=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:45,580 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-9f3a9300 ctx-9ebd0eb1 ctx-129b5c4d) ===END=== 10.220.135.30 -- GET jobid=89c344f2-54de-40b7-b1ea-2a9f5b573a4e&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=queryAsyncJobResult&response=json&signature=9GRPDgWSdAC0UuqA0wooTnJ%2FMZc%3D
2014-10-21 17:06:45,586 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-1dcb8d0a) ===START=== 10.220.135.30 -- GET response=json&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=listSystemVms&id=0d3261c0-18af-4f4f-8052-78398ea3d319&signature=ggcw%2Fd7ZoFscmonFgxTTWGX5uyc%3D
2014-10-21 17:06:45,635 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-1dcb8d0a ctx-cdaa7314 ctx-015ea415) ===END=== 10.220.135.30 -- GET response=json&apiKey=8zS-PDiww66KLa3apG55n-SpVbHRv7o4m1yTKiJTghk3NmbsfVAcE_Y1ymDuc-7huYpOW1Q221BgVCCQXcy_Zg&command=listSystemVms&id=0d3261c0-18af-4f4f-8052-78398ea3d319&signature=ggcw%2Fd7ZoFscmonFgxTTWGX5uyc%3D
2014-10-21 17:06:47,887 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 2
2014-10-21 17:06:47,887 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) Process host VM state report from ping process. host: 2
2014-10-21 17:06:47,891 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) Process VM state report. host: 2, number of records in report: 2
2014-10-21 17:06:47,891 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) VM state report. host: 2, vm id: 1, power state: PowerOn
2014-10-21 17:06:47,895 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) VM state report is updated. host: 2, vm id: 1, power state: PowerOn
2014-10-21 17:06:47,900 DEBUG [c.c.c.CapacityManagerImpl] (AgentManager-Handler-14:null) VM state transitted from :Running to Running with event: FollowAgentPowerOnReportvm's original host id: 2 new host id: 2 host id before state transition: 2
2014-10-21 17:06:47,901 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) VM state report. host: 2, vm id: 2, power state: PowerOn
2014-10-21 17:06:47,903 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) VM power state does not change, skip DB writing. vm id: 2
2014-10-21 17:06:47,906 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-14:null) Done with process of VM state report. host: 2
2014-10-21 17:06:49,862 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:ctx-f9b42727) Found 0 running routers.
2014-10-21 17:06:49,868 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4e93a5dc) Found 0 routers to update status.
2014-10-21 17:06:49,869 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-4e93a5dc) Found 0 networks to update RvR status.
2014-10-21 17:06:49,959 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:ctx-72bd0997) External devices stats collector is running...
2014-10-21 17:06:49,963 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:ctx-8823a15d) Found 0 removed accounts to cleanup
2014-10-21 17:06:49,964 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:ctx-8823a15d) Found 0 disabled accounts to cleanup
2014-10-21 17:06:49,965 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:ctx-8823a15d) Found 0 inactive domains to cleanup
2014-10-21 17:06:49,966 INFO [c.c.u.AccountManagerImpl] (AccountChecker-1:ctx-8823a15d) Found 0 disabled projects to cleanup
2014-10-21 17:06:49,974 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-5b81523d) Snapshot scheduler.poll is being called at 2014-10-21 17:06:49 GMT
2014-10-21 17:06:49,975 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-5b81523d) Got 0 snapshots to be executed at 2014-10-21 17:06:49 GMT
2014-10-21 17:06:50,015 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-147bce4d) Begin cleanup expired async-jobs
2014-10-21 17:06:50,020 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-147bce4d) End cleanup expired async-jobs
2014-10-21 17:06:50,032 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-4:ctx-ac7c6374) checking health of usage server
2014-10-21 17:06:50,033 DEBUG [c.c.h.HighAvailabilityManagerImpl] (HA-4:ctx-ac7c6374) usage server running? false, heartbeat: null
2014-10-21 17:06:50,035 WARN [o.a.c.alerts] (HA-4:ctx-ac7c6374) alertType:: 13 // dataCenterId:: 0 // podId:: 0 // clusterId:: null // message:: No usage server process running
2014-10-21 17:06:50,037 DEBUG [c.c.a.AlertManagerImpl] (HA-4:ctx-ac7c6374) Have already sent: 1 emails for alert type '13' -- skipping send email
2014-10-21 17:06:51,042 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 1
2014-10-21 17:06:51,043 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Process host VM state report from ping process. host: 1
2014-10-21 17:06:51,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Process VM state report. host: 1, number of records in report: 1
2014-10-21 17:06:51,045 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM state report. host: 1, vm id: 56, power state: PowerOn
2014-10-21 17:06:51,048 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) VM power state does not change, skip DB writing. vm id: 56
2014-10-21 17:06:51,050 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-15:null) Done with process of VM state report. host: 1
2014-10-21 17:06:54,987 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-1c80f4d4) Expunge completed work job-431
2014-10-21 17:06:54,991 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-1c80f4d4) Expunge completed work job-433
2014-10-21 17:06:54,996 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-1c80f4d4) Expunge completed work job-434
2014-10-21 17:06:59,245 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-aee314ec) HostStatsCollector is running...
2014-10-21 17:06:59,833 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-aee314ec) Seq 1-5688046329368937055: Received: { Ans: , MgmtId: 59825535280071, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-10-21 17:06:59,982 DEBUG [c.c.n.l.LBHealthCheckManagerImpl] (LBHealthCheck-1:ctx-d87cef3b) LB HealthCheck Manager is running and getting the updates from LB providers and updating service status
2014-10-21 17:06:59,995 DEBUG [c.c.n.l.LBHealthCheckManagerImpl] (LBHealthCheck-1:ctx-d87cef3b) LB HealthCheck Manager is running and getting the updates from LB providers and updating service status
2014-10-21 17:07:00,015 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-09122581) Begin cleanup expired async-jobs
2014-10-21 17:07:00,020 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-09122581) End cleanup expired async-jobs
2014-10-21 17:07:00,433 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-aee314ec) Seq 2-7242632625741890166: Received: { Ans: , MgmtId: 59825535280071, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-10-21 17:07:01,877 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-c9e7c76e) Zone 1 is ready to launch secondary storage VM
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)