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)