cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Chandan Purushothama (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CLOUDSTACK-7761) [Automation] Rebooting System VMs - VMs are getting stopped and started instead of reboot
Date Tue, 21 Oct 2014 20:01:35 GMT
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)

Mime
View raw message