[
https://issues.apache.org/jira/browse/CLOUDSTACK-7761?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Chandan Purushothama updated CLOUDSTACK-7761:
---------------------------------------------
Attachment: management-server.zip
> [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
>
> Attachments: management-server.zip
>
>
> 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)
