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)
