Hello
I have a web server on the management server and a qcow2 format volume.
When request cloudstack to download the volume, it keeps it in
"UploadNotStarted" state and does not start downloading it to the secondary
storage. I've checked SSVM and secondary storage mount point, free disk
space, max template size and allowed local ips. Below is the log since last
cloudstack restart up to requesting volume upload
2019-03-18 18:21:13,559 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 21-76888: Processing Seq
21-76888: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:13,560 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 21-76888: Sending Seq
21-76888: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:21:20,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-3179a01e) (logid:33ac3532) Begin cleanup
expired async-jobs
2019-03-18 18:21:20,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-3179a01e) (logid:33ac3532) End cleanup expired
async-jobs
2019-03-18 18:21:23,284 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-88fad0b1) (logid:ef76ea22) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:21:23,285 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-88fad0b1)
(logid:ef76ea22) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:21:23,285 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-88fad0b1) (logid:ef76ea22) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:21:23,285 DEBUG [c.c.a.t.Request] (Timer-8:ctx-88fad0b1)
(logid:ef76ea22) Seq 22-6353734649289638105: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:21:23,330 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-10:null) (logid:) Seq 22-6353734649289638105:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:23,560 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 21-76889: Processing Seq
21-76889: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:23,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 21-76889: Sending Seq
21-76889: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:21:30,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e38890d7) (logid:6a68f0ff) Begin cleanup
expired async-jobs
2019-03-18 18:21:30,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e38890d7) (logid:6a68f0ff) End cleanup expired
async-jobs
2019-03-18 18:21:33,332 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-9960a19f) (logid:d57bfd75) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:21:33,332 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-9960a19f)
(logid:d57bfd75) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:21:33,332 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-9960a19f) (logid:d57bfd75) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:21:33,333 DEBUG [c.c.a.t.Request] (Timer-8:ctx-9960a19f)
(logid:d57bfd75) Seq 22-6353734649289638106: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:21:33,382 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-11:null) (logid:) Seq 22-6353734649289638106:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:33,560 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) (logid:) SeqA 21-76890: Processing Seq
21-76890: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:33,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) (logid:) SeqA 21-76890: Sending Seq
21-76890: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:21:34,277 DEBUG [c.c.a.ApiServlet]
(qtp788117692-19:ctx-cd761b99) (logid:35f7ba4a) ===START=== 2.190.217.131
-- GET
command=uploadVolume&response=json&name=DATA-126&zoneId=bc4565d8-4029-4dbd-93eb-47137ff45188&format=QCOW2&url=http%3A%2F%2F178.33.230.41%2Fvps%2FYounes.qcow2&diskofferingid=9b38dd2b-daab-4a7a-ac01-8d1eb9375169&_=1552929696128
2019-03-18 18:21:34,279 DEBUG [c.c.a.ApiServer]
(qtp788117692-19:ctx-cd761b99 ctx-d790b9d4) (logid:35f7ba4a) CIDRs from
which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2019-03-18 18:21:34,287 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-8:ctx-c344cf91 job-3446) (logid:c61a744c) Add job-3446
into job monitoring
2019-03-18 18:21:34,290 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446) (logid:04ecbb06) Executing
AsyncJobVO {id:3446, userId: 2, accountId: 2, instanceType: None,
instanceId: null, cmd:
org.apache.cloudstack.api.command.admin.volume.UploadVolumeCmdByAdmin,
cmdInfo: {"format":"QCOW2","httpmethod":"GET","ctxAccountId":"2","url":"
http://178.33.230.41/vps/Younes.qcow2","cmdEventType":"VOLUME.UPLOAD","diskofferingid":"9b38dd2b-daab-4a7a-ac01-8d1eb9375169","response":"json","ctxUserId":"2","name":"DATA-126","zoneId":"bc4565d8-4029-4dbd-93eb-47137ff45188","ctxStartEventId":"2396","ctxDetails":"{\"interface
com.cloud.offering.DiskOffering\":\"9b38dd2b-daab-4a7a-ac01-8d1eb9375169\",\"interface
com.cloud.dc.DataCenter\":\"bc4565d8-4029-4dbd-93eb-47137ff45188\"}","_":"1552929696128"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 279278805450774, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null}
2019-03-18 18:21:34,291 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp788117692-19:ctx-cd761b99 ctx-d790b9d4) (logid:35f7ba4a) submit async
job-3446, details: AsyncJobVO {id:3446, userId: 2, accountId: 2,
instanceType: None, instanceId: null, cmd:
org.apache.cloudstack.api.command.admin.volume.UploadVolumeCmdByAdmin,
cmdInfo: {"format":"QCOW2","httpmethod":"GET","ctxAccountId":"2","url":"
http://178.33.230.41/vps/Younes.qcow2","cmdEventType":"VOLUME.UPLOAD","diskofferingid":"9b38dd2b-daab-4a7a-ac01-8d1eb9375169","response":"json","ctxUserId":"2","name":"DATA-126","zoneId":"bc4565d8-4029-4dbd-93eb-47137ff45188","ctxStartEventId":"2396","ctxDetails":"{\"interface
com.cloud.offering.DiskOffering\":\"9b38dd2b-daab-4a7a-ac01-8d1eb9375169\",\"interface
com.cloud.dc.DataCenter\":\"bc4565d8-4029-4dbd-93eb-47137ff45188\"}","_":"1552929696128"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 279278805450774, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null}
2019-03-18 18:21:34,291 DEBUG [c.c.a.ApiServlet]
(qtp788117692-19:ctx-cd761b99 ctx-d790b9d4) (logid:35f7ba4a) ===END===
2.190.217.131 -- GET
command=uploadVolume&response=json&name=DATA-126&zoneId=bc4565d8-4029-4dbd-93eb-47137ff45188&format=QCOW2&url=http%3A%2F%2F178.33.230.41%2Fvps%2FYounes.qcow2&diskofferingid=9b38dd2b-daab-4a7a-ac01-8d1eb9375169&_=1552929696128
2019-03-18 18:21:34,298 DEBUG [c.c.s.VolumeApiServiceImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Checking url: http://178.33.230.41/vps/Younes.qcow2
2019-03-18 18:21:34,302 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Updating resource Type = volume count for Account = 2 Operation =
increasing Amount = 1
2019-03-18 18:21:34,305 DEBUG [c.c.r.ResourceLimitManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Updating resource Type = secondary_storage count for Account = 2 Operation
= increasing Amount = 584142618624
2019-03-18 18:21:34,316 DEBUG [o.a.c.s.i.BaseImageStoreDriverImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Downloading volume to data store 2
2019-03-18 18:21:34,323 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadCommand
2019-03-18 18:21:34,324 DEBUG [c.c.h.XenServerGuru]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06) We
are returning the default host to execute commands because the command is
not of Copy type.
2019-03-18 18:21:34,324 DEBUG [o.a.c.s.RemoteHostEndPoint]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Sending command org.apache.cloudstack.storage.command.DownloadCommand to
host: 22
2019-03-18 18:21:34,325 DEBUG [c.c.a.t.Request]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Seq 22-6353734649289638107: Sending { Cmd , MgmtId: 279278805450774, via:
22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadCommand":{"hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:21:34,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Complete async job-3446, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.VolumeResponse/volume/{"id":"f6934fc6-3b45-44e1-a45a-ace0e722f581","name":"DATA-126","zoneid":"bc4565d8-4029-4dbd-93eb-47137ff45188","zonename":"France","type":"DATADISK","provisioningtype":"thin","size":0,"created":"2019-03-18T18:21:34+0100","state":"UploadNotStarted","account":"admin","domainid":"1321ad62-3907-11e9-87ab-a4bf012ed1a6","domain":"ROOT","storagetype":"shared","hypervisor":"KVM","diskofferingid":"9b38dd2b-daab-4a7a-ac01-8d1eb9375169","diskofferingname":"Custom-SATA","diskofferingdisplaytext":"Custom
Disk on
SATA","destroyed":false,"isextractable":true,"status":"","displayvolume":true,"quiescevm":false,"tags":[]}
2019-03-18 18:21:34,330 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Publish async job-3446 complete on message bus
2019-03-18 18:21:34,330 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Wake up jobs related to job-3446
2019-03-18 18:21:34,330 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Update db status for job-3446
2019-03-18 18:21:34,331 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446 ctx-a94e9ce2) (logid:04ecbb06)
Wake up jobs joined with job-3446 and disjoin all subjobs created from job-
3446
2019-03-18 18:21:34,332 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-c344cf91 job-3446) (logid:04ecbb06) Done executing
org.apache.cloudstack.api.command.admin.volume.UploadVolumeCmdByAdmin for
job-3446
2019-03-18 18:21:34,332 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-8:ctx-c344cf91 job-3446) (logid:04ecbb06) Remove job-3446
from job monitoring
2019-03-18 18:21:37,399 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-15:null) (logid:) Seq 22-6353734649289638107:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:37,455 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-49801bee) (logid:982757ab) ===START=== 2.190.217.131
-- GET
command=queryAsyncJobResult&jobId=04ecbb06-22b6-43a4-b0aa-23d4f64ea48c&response=json&_=1552929699447
2019-03-18 18:21:37,457 DEBUG [c.c.a.ApiServer]
(qtp788117692-12:ctx-49801bee ctx-9bc5abda) (logid:982757ab) CIDRs from
which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2019-03-18 18:21:37,464 DEBUG [c.c.a.ApiServlet]
(qtp788117692-12:ctx-49801bee ctx-9bc5abda) (logid:982757ab) ===END===
2.190.217.131 -- GET
command=queryAsyncJobResult&jobId=04ecbb06-22b6-43a4-b0aa-23d4f64ea48c&response=json&_=1552929699447
2019-03-18 18:21:37,633 DEBUG [c.c.a.ApiServlet]
(qtp788117692-19:ctx-06a18760) (logid:0d6813d5) ===START=== 2.190.217.131
-- GET
command=listVolumes&response=json&listAll=true&page=1&pagesize=20&_=1552929699626
2019-03-18 18:21:37,634 DEBUG [c.c.a.ApiServer]
(qtp788117692-19:ctx-06a18760 ctx-82e14241) (logid:0d6813d5) CIDRs from
which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2019-03-18 18:21:37,656 DEBUG [c.c.a.ApiServlet]
(qtp788117692-19:ctx-06a18760 ctx-82e14241) (logid:0d6813d5) ===END===
2.190.217.131 -- GET
command=listVolumes&response=json&listAll=true&page=1&pagesize=20&_=1552929699626
2019-03-18 18:21:40,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-0c77acd2) (logid:b9bfcfe3) Begin cleanup
expired async-jobs
2019-03-18 18:21:40,618 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-0c77acd2) (logid:b9bfcfe3) End cleanup expired
async-jobs
2019-03-18 18:21:40,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-9814f0f5) (logid:146b7f38) Found 0 routers to
update status.
2019-03-18 18:21:40,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-9814f0f5) (logid:146b7f38) Found 0 VPC networks
to update Redundant State.
2019-03-18 18:21:40,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-9814f0f5) (logid:146b7f38) Found 0 networks to
update RvR status.
2019-03-18 18:21:42,841 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-1:null) (logid:) Ping from 21(v-97-VM)
2019-03-18 18:21:42,898 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-3:null) (logid:) Ping from 20(fr-kvm1)
2019-03-18 18:21:42,898 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) Process host VM state report from
ping process. host: 20
2019-03-18 18:21:42,921 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) Process VM state report. host: 20,
number of records in report: 27
2019-03-18 18:21:42,921 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
21, power state: PowerOn
2019-03-18 18:21:42,922 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 21
2019-03-18 18:21:42,922 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
22, power state: PowerOn
2019-03-18 18:21:42,922 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 22
2019-03-18 18:21:42,922 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
90, power state: PowerOn
2019-03-18 18:21:42,923 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 90
2019-03-18 18:21:42,923 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
94, power state: PowerOn
2019-03-18 18:21:42,924 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 94
2019-03-18 18:21:42,924 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
32, power state: PowerOn
2019-03-18 18:21:42,925 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 32
2019-03-18 18:21:42,925 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
96, power state: PowerOn
2019-03-18 18:21:42,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 96
2019-03-18 18:21:42,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
97, power state: PowerOn
2019-03-18 18:21:42,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 97
2019-03-18 18:21:42,926 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
99, power state: PowerOn
2019-03-18 18:21:42,927 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 99
2019-03-18 18:21:42,927 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
36, power state: PowerOn
2019-03-18 18:21:42,928 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 36
2019-03-18 18:21:42,928 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
37, power state: PowerOn
2019-03-18 18:21:42,929 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 37
2019-03-18 18:21:42,929 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
101, power state: PowerOn
2019-03-18 18:21:42,930 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 101
2019-03-18 18:21:42,930 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
39, power state: PowerOn
2019-03-18 18:21:42,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 39
2019-03-18 18:21:42,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
103, power state: PowerOn
2019-03-18 18:21:42,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 103
2019-03-18 18:21:42,931 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
104, power state: PowerOn
2019-03-18 18:21:42,932 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 104
2019-03-18 18:21:42,932 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
40, power state: PowerOn
2019-03-18 18:21:42,933 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 40
2019-03-18 18:21:42,933 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
106, power state: PowerOn
2019-03-18 18:21:42,934 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 106
2019-03-18 18:21:42,934 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
42, power state: PowerOn
2019-03-18 18:21:42,935 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 42
2019-03-18 18:21:42,935 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
108, power state: PowerOn
2019-03-18 18:21:42,936 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 108
2019-03-18 18:21:42,936 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
44, power state: PowerOn
2019-03-18 18:21:42,938 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 44
2019-03-18 18:21:42,938 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
109, power state: PowerOn
2019-03-18 18:21:42,939 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 109
2019-03-18 18:21:42,939 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
113, power state: PowerOn
2019-03-18 18:21:42,940 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 113
2019-03-18 18:21:42,940 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
114, power state: PowerOn
2019-03-18 18:21:42,941 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 114
2019-03-18 18:21:42,941 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
115, power state: PowerOn
2019-03-18 18:21:42,942 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 115
2019-03-18 18:21:42,942 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
116, power state: PowerOn
2019-03-18 18:21:42,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 116
2019-03-18 18:21:42,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
118, power state: PowerOn
2019-03-18 18:21:42,944 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 118
2019-03-18 18:21:42,944 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
121, power state: PowerOn
2019-03-18 18:21:42,945 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 121
2019-03-18 18:21:42,945 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM state report. host: 20, vm id:
127, power state: PowerOn
2019-03-18 18:21:42,946 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) VM power state does not change, skip
DB writing. vm id: 127
2019-03-18 18:21:42,954 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) Run missing VM report. current time:
1552929702954
2019-03-18 18:21:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) Detected missing VM. host: 20, vm
id: 119, power state: PowerReportMissing, last state update: 1552929642000
2019-03-18 18:21:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) vm id: 119 - time since last state
update(60954ms) has not passed graceful period yet
2019-03-18 18:21:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-3:null) (logid:) Done with process of VM state
report. host: 20
2019-03-18 18:21:43,284 DEBUG [c.c.s.d.DownloadListener]
(Timer-8:ctx-77fa16de) (logid:22584d57) Scheduling timeout at 30000 ms,
VOLUME: 125 at host 22
2019-03-18 18:21:43,560 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) (logid:) SeqA 21-76892: Processing Seq
21-76892: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:43,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) (logid:) SeqA 21-76892: Sending Seq
21-76892: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:21:46,062 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Resetting hosts suitable for reconnect
2019-03-18 18:21:46,063 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Completed resetting hosts suitable for
reconnect
2019-03-18 18:21:46,063 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Acquiring hosts for clusters already
owned by this management server
2019-03-18 18:21:46,063 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Completed acquiring hosts for clusters
already owned by this management server
2019-03-18 18:21:46,063 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Acquiring hosts for clusters not owned
by any management server
2019-03-18 18:21:46,064 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-d9f3ba82) (logid:5694d767) Completed acquiring hosts for clusters
not owned by any management server
2019-03-18 18:21:47,402 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-6ecb1240) (logid:1db30098) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:21:47,402 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-6ecb1240)
(logid:1db30098) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:21:47,403 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-6ecb1240) (logid:1db30098) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:21:47,403 DEBUG [c.c.a.t.Request] (Timer-9:ctx-6ecb1240)
(logid:1db30098) Seq 22-6353734649289638108: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:21:47,405 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-2:null) (logid:) Seq 22-6353734649289638108:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:48,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 21-76893: Processing Seq
21-76893: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:48,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 21-76893: Sending Seq
21-76893: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:21:50,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-8773678c) (logid:5a2fb9a4) Begin cleanup
expired async-jobs
2019-03-18 18:21:50,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-8773678c) (logid:5a2fb9a4) End cleanup expired
async-jobs
2019-03-18 18:21:52,062 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) (logid:) Ping from 22(s-96-VM)
2019-03-18 18:21:53,285 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-8b8a42e7) (logid:b7941832) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:21:53,285 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-8b8a42e7)
(logid:b7941832) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:21:53,285 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-8b8a42e7) (logid:b7941832) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:21:53,286 DEBUG [c.c.a.t.Request] (Timer-8:ctx-8b8a42e7)
(logid:b7941832) Seq 22-6353734649289638109: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:21:53,328 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-6:null) (logid:) Seq 22-6353734649289638109:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:55,689 DEBUG [c.c.s.StatsCollector]
(StatsCollector-5:ctx-ca661a34) (logid:080c0514) AutoScaling Monitor is
running...
2019-03-18 18:21:56,504 DEBUG [c.c.s.StatsCollector]
(StatsCollector-2:ctx-af66d9f3) (logid:8f36fe6b) HostStatsCollector is
running...
2019-03-18 18:21:56,509 DEBUG [c.c.a.t.Request]
(StatsCollector-2:ctx-af66d9f3) (logid:8f36fe6b) Seq 20-451485862643892809:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetHostStatsAnswer } }
2019-03-18 18:21:57,407 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-df3ac45b) (logid:aaef0e7d) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:21:57,408 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-df3ac45b)
(logid:aaef0e7d) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:21:57,408 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-df3ac45b) (logid:aaef0e7d) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:21:57,408 DEBUG [c.c.a.t.Request] (Timer-9:ctx-df3ac45b)
(logid:aaef0e7d) Seq 22-6353734649289638110: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:21:57,453 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-8:null) (logid:) Seq 22-6353734649289638110:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:21:58,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 21-76894: Processing Seq
21-76894: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:21:58,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 21-76894: Sending Seq
21-76894: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:00,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e06aa01e) (logid:39d69648) Begin cleanup
expired async-jobs
2019-03-18 18:22:00,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-e06aa01e) (logid:39d69648) End cleanup expired
async-jobs
2019-03-18 18:22:02,861 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) StorageCollector is
running...
2019-03-18 18:22:02,865 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:22:02,865 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:22:02,914 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) Seq
22-6353734649289638111: Received: { Ans: , MgmtId: 279278805450774, via:
22(s-96-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:22:02,915 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:22:02,915 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:22:03,000 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) Seq 20-451485862643892810:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:22:03,001 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:22:03,001 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:22:03,181 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-859d6d89) (logid:8ee4570e) Seq 20-451485862643892811:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:22:03,331 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-2c45748d) (logid:4e34918e) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:03,332 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-2c45748d)
(logid:4e34918e) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:03,332 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-2c45748d) (logid:4e34918e) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:03,333 DEBUG [c.c.a.t.Request] (Timer-8:ctx-2c45748d)
(logid:4e34918e) Seq 22-6353734649289638112: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:22:03,380 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-14:null) (logid:) Seq 22-6353734649289638112:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:04,321 DEBUG [c.c.s.d.DownloadListener]
(Timer-9:ctx-b24595f3) (logid:468fb5fc) Scheduling timeout at 30000 ms,
VOLUME: 126 at host 22
2019-03-18 18:22:08,561 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-15:null) (logid:) SeqA 21-76895: Processing Seq
21-76895: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:08,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-15:null) (logid:) SeqA 21-76895: Sending Seq
21-76895: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:10,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-d5ed005b) (logid:9b42e3a5) Begin cleanup
expired async-jobs
2019-03-18 18:22:10,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-d5ed005b) (logid:9b42e3a5) End cleanup expired
async-jobs
2019-03-18 18:22:10,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-11ded2b4) (logid:f1482383) Found 0 routers to
update status.
2019-03-18 18:22:10,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-11ded2b4) (logid:f1482383) Found 0 VPC networks
to update Redundant State.
2019-03-18 18:22:10,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-11ded2b4) (logid:f1482383) Found 0 networks to
update RvR status.
2019-03-18 18:22:11,045 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Running Capacity Checker
...
2019-03-18 18:22:11,045 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) recalculating system
capacity
2019-03-18 18:22:11,045 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Executing cpu/ram capacity
update
2019-03-18 18:22:11,055 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Found 28 VMs on host 20
2019-03-18 18:22:11,064 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Found 1 VM, not running on
host 20
2019-03-18 18:22:11,066 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) No need to calibrate cpu
capacity, host:20 usedCpuCore: 46 reservedCpuCore: 0
2019-03-18 18:22:11,066 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) No need to calibrate cpu
capacity, host:20 usedCpu: 74500 reservedCpu: 0
2019-03-18 18:22:11,066 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) No need to calibrate memory
capacity, host:20 usedMem: 42144366592 reservedMem: 0
2019-03-18 18:22:11,067 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done executing cpu/ram
capacity update
2019-03-18 18:22:11,067 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Executing storage capacity
update
2019-03-18 18:22:11,071 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Found storage pool Primary1
of type NetworkFilesystem with overprovisioning factor 2
2019-03-18 18:22:11,071 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Total over provisioned
capacity calculated is 2 * 855968317440
2019-03-18 18:22:11,071 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Total over provisioned
capacity of the pool Primary1 id: 1 is 1711936634880
2019-03-18 18:22:11,071 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Successfully set Capacity -
1711936634880 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1,
PodId 1
2019-03-18 18:22:11,074 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Found storage pool Primary2
of type NetworkFilesystem with overprovisioning factor 2
2019-03-18 18:22:11,074 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Total over provisioned
capacity calculated is 2 * 3936540950528
2019-03-18 18:22:11,074 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Total over provisioned
capacity of the pool Primary2 id: 3 is 7873081901056
2019-03-18 18:22:11,074 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Successfully set Capacity -
7873081901056 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 3,
PodId 1
2019-03-18 18:22:11,074 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done executing storage
capacity update
2019-03-18 18:22:11,074 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Executing capacity updates
for public ip and Vlans
2019-03-18 18:22:11,076 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done capacity updates for
public ip and Vlans
2019-03-18 18:22:11,076 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Executing capacity updates
for private ip
2019-03-18 18:22:11,078 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done executing capacity
updates for private ip
2019-03-18 18:22:11,078 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done recalculating system
capacity
2019-03-18 18:22:11,090 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-2bf4d518) (logid:f683e63a) Done running Capacity
Checker ...
2019-03-18 18:22:13,235 DEBUG [c.c.a.t.Request]
(StatsCollector-4:ctx-933a9939) (logid:53b50dc9) Seq 20-451485862643892812:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetVmStatsAnswer } }
2019-03-18 18:22:13,284 DEBUG [c.c.s.d.DownloadListener]
(Timer-8:ctx-9e32ea59) (logid:b1621f9b) Scheduling timeout at 30000 ms,
VOLUME: 125 at host 22
2019-03-18 18:22:13,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-3:null) (logid:) SeqA 21-76896: Processing Seq
21-76896: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:13,564 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-3:null) (logid:) SeqA 21-76896: Sending Seq
21-76896: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:14,321 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-0526daf1) (logid:aeaf6688) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:14,322 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-0526daf1)
(logid:aeaf6688) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:14,322 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-0526daf1) (logid:aeaf6688) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:14,323 DEBUG [c.c.a.t.Request] (Timer-9:ctx-0526daf1)
(logid:aeaf6688) Seq 22-6353734649289638113: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:22:14,366 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-4:null) (logid:) Seq 22-6353734649289638113:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:20,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-8e7deed4) (logid:55b2332a) Begin cleanup
expired async-jobs
2019-03-18 18:22:20,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-8e7deed4) (logid:55b2332a) End cleanup expired
async-jobs
2019-03-18 18:22:23,284 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-f4a031b4) (logid:77d2f916) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:23,285 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-f4a031b4)
(logid:77d2f916) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:23,285 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-f4a031b4) (logid:77d2f916) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:23,286 DEBUG [c.c.a.t.Request] (Timer-8:ctx-f4a031b4)
(logid:77d2f916) Seq 22-6353734649289638114: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:22:23,331 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-2:null) (logid:) Seq 22-6353734649289638114:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:23,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 21-76897: Processing Seq
21-76897: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:23,563 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 21-76897: Sending Seq
21-76897: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:24,370 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-bd09047f) (logid:54153dd4) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:24,370 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-bd09047f)
(logid:54153dd4) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:24,370 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-bd09047f) (logid:54153dd4) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:24,371 DEBUG [c.c.a.t.Request] (Timer-9:ctx-bd09047f)
(logid:54153dd4) Seq 22-6353734649289638115: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:22:24,415 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-13:null) (logid:) Seq 22-6353734649289638115:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:25,418 DEBUG [c.c.a.ApiServlet]
(qtp788117692-20:ctx-c3f35c2e) (logid:14a3bf67) ===START=== 2.190.217.131
-- GET
command=listVolumes&response=json&keyword=data&listAll=true&page=1&pagesize=20&_=1552929747269
2019-03-18 18:22:25,419 DEBUG [c.c.a.ApiServer]
(qtp788117692-20:ctx-c3f35c2e ctx-8bbbef10) (logid:14a3bf67) CIDRs from
which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2019-03-18 18:22:25,427 DEBUG [c.c.a.ApiServlet]
(qtp788117692-20:ctx-c3f35c2e ctx-8bbbef10) (logid:14a3bf67) ===END===
2.190.217.131 -- GET
command=listVolumes&response=json&keyword=data&listAll=true&page=1&pagesize=20&_=1552929747269
2019-03-18 18:22:30,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-588e65c5) (logid:0e2099b3) Begin cleanup
expired async-jobs
2019-03-18 18:22:30,618 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-588e65c5) (logid:0e2099b3) End cleanup expired
async-jobs
2019-03-18 18:22:33,333 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-6b95bcbf) (logid:f7da1462) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:33,334 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-6b95bcbf)
(logid:f7da1462) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:33,334 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-6b95bcbf) (logid:f7da1462) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:33,334 DEBUG [c.c.a.t.Request] (Timer-8:ctx-6b95bcbf)
(logid:f7da1462) Seq 22-6353734649289638116: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:22:33,382 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-6:null) (logid:) Seq 22-6353734649289638116:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:33,562 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-7:null) (logid:) SeqA 21-76898: Processing Seq
21-76898: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:33,563 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-7:null) (logid:) SeqA 21-76898: Sending Seq
21-76898: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:34,321 DEBUG [c.c.s.d.DownloadListener]
(Timer-9:ctx-cb8bc21f) (logid:fbb39dcb) Scheduling timeout at 30000 ms,
VOLUME: 126 at host 22
2019-03-18 18:22:37,884 DEBUG [c.c.a.ApiServlet]
(qtp788117692-16:ctx-54bffb38) (logid:76ddb185) ===START=== 2.190.217.131
-- GET
command=listVolumes&id=f6934fc6-3b45-44e1-a45a-ace0e722f581&response=json&_=1552929759880
2019-03-18 18:22:37,886 DEBUG [c.c.a.ApiServer]
(qtp788117692-16:ctx-54bffb38 ctx-3f6a5bec) (logid:76ddb185) CIDRs from
which account 'Acct[27cd01ef-3907-11e9-87ab-a4bf012ed1a6-admin]' is allowed
to perform API calls: 0.0.0.0/0,::/0
2019-03-18 18:22:37,893 DEBUG [c.c.a.ApiServlet]
(qtp788117692-16:ctx-54bffb38 ctx-3f6a5bec) (logid:76ddb185) ===END===
2.190.217.131 -- GET
command=listVolumes&id=f6934fc6-3b45-44e1-a45a-ace0e722f581&response=json&_=1552929759880
2019-03-18 18:22:40,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-095d2667) (logid:08b01e7e) Begin cleanup
expired async-jobs
2019-03-18 18:22:40,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-095d2667) (logid:08b01e7e) End cleanup expired
async-jobs
2019-03-18 18:22:40,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-0ed49e3a) (logid:93a97b5b) Found 0 routers to
update status.
2019-03-18 18:22:40,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-0ed49e3a) (logid:93a97b5b) Found 0 VPC networks
to update Redundant State.
2019-03-18 18:22:40,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-0ed49e3a) (logid:93a97b5b) Found 0 networks to
update RvR status.
2019-03-18 18:22:42,841 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) (logid:) Ping from 21(v-97-VM)
2019-03-18 18:22:42,910 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) Ping from 20(fr-kvm1)
2019-03-18 18:22:42,910 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) Process host VM state report from
ping process. host: 20
2019-03-18 18:22:42,940 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) Process VM state report. host: 20,
number of records in report: 27
2019-03-18 18:22:42,940 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
21, power state: PowerOn
2019-03-18 18:22:42,941 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 21
2019-03-18 18:22:42,941 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
22, power state: PowerOn
2019-03-18 18:22:42,942 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 22
2019-03-18 18:22:42,942 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
90, power state: PowerOn
2019-03-18 18:22:42,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 90
2019-03-18 18:22:42,943 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
94, power state: PowerOn
2019-03-18 18:22:42,944 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 94
2019-03-18 18:22:42,944 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
32, power state: PowerOn
2019-03-18 18:22:42,945 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 32
2019-03-18 18:22:42,945 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
96, power state: PowerOn
2019-03-18 18:22:42,946 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 96
2019-03-18 18:22:42,946 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
97, power state: PowerOn
2019-03-18 18:22:42,947 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 97
2019-03-18 18:22:42,947 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
99, power state: PowerOn
2019-03-18 18:22:42,948 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 99
2019-03-18 18:22:42,948 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
36, power state: PowerOn
2019-03-18 18:22:42,949 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 36
2019-03-18 18:22:42,949 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
37, power state: PowerOn
2019-03-18 18:22:42,950 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 37
2019-03-18 18:22:42,950 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
101, power state: PowerOn
2019-03-18 18:22:42,951 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 101
2019-03-18 18:22:42,951 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
39, power state: PowerOn
2019-03-18 18:22:42,953 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 39
2019-03-18 18:22:42,953 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
103, power state: PowerOn
2019-03-18 18:22:42,954 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 103
2019-03-18 18:22:42,954 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
104, power state: PowerOn
2019-03-18 18:22:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 104
2019-03-18 18:22:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
40, power state: PowerOn
2019-03-18 18:22:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 40
2019-03-18 18:22:42,955 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
106, power state: PowerOn
2019-03-18 18:22:42,956 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 106
2019-03-18 18:22:42,956 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
42, power state: PowerOn
2019-03-18 18:22:42,957 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 42
2019-03-18 18:22:42,957 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
108, power state: PowerOn
2019-03-18 18:22:42,958 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 108
2019-03-18 18:22:42,958 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
44, power state: PowerOn
2019-03-18 18:22:42,959 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 44
2019-03-18 18:22:42,959 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
109, power state: PowerOn
2019-03-18 18:22:42,960 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 109
2019-03-18 18:22:42,960 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
113, power state: PowerOn
2019-03-18 18:22:42,961 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 113
2019-03-18 18:22:42,961 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
114, power state: PowerOn
2019-03-18 18:22:42,962 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 114
2019-03-18 18:22:42,962 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
115, power state: PowerOn
2019-03-18 18:22:42,963 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 115
2019-03-18 18:22:42,963 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
116, power state: PowerOn
2019-03-18 18:22:42,964 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 116
2019-03-18 18:22:42,964 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
118, power state: PowerOn
2019-03-18 18:22:42,965 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 118
2019-03-18 18:22:42,965 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
121, power state: PowerOn
2019-03-18 18:22:42,966 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 121
2019-03-18 18:22:42,966 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report. host: 20, vm id:
127, power state: PowerOn
2019-03-18 18:22:42,967 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM power state does not change, skip
DB writing. vm id: 127
2019-03-18 18:22:42,975 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) Run missing VM report. current time:
1552929762975
2019-03-18 18:22:42,975 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) Detected missing VM. host: 20, vm
id: 119, power state: PowerReportMissing, last state update: 1552929642000
2019-03-18 18:22:42,975 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) vm id: 119 - time since last state
update(120975ms) has passed graceful period
2019-03-18 18:22:42,977 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) VM state report is updated. host:
20, vm id: 119, power state: PowerReportMissing
2019-03-18 18:22:42,978 INFO [c.c.v.VirtualMachineManagerImpl]
(AgentManager-Handler-9:null) (logid:) VM i-2-119-VM is at Running and we
received a power-off report while there is no pending jobs on it
2019-03-18 18:22:42,979 INFO [c.c.v.VirtualMachineManagerImpl]
(AgentManager-Handler-9:null) (logid:) Detected out-of-band stop of a HA
enabled VM i-2-119-VM, will schedule restart
2019-03-18 18:22:42,988 INFO [c.c.h.HighAvailabilityManagerImpl]
(AgentManager-Handler-9:null) (logid:) Schedule vm for HA:
VM[User|i-2-119-VM]
2019-03-18 18:22:42,988 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(AgentManager-Handler-9:null) (logid:) Done with process of VM state
report. host: 20
2019-03-18 18:22:42,990 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Processing work
HAWork[1083-HA-119-Running-Investigating]
2019-03-18 18:22:42,991 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) HA on
VM[User|i-2-119-VM]
2019-03-18 18:22:42,993 DEBUG [c.c.a.t.Request] (HA-Worker-3:ctx-9deb1ae0
work-1083) (logid:fbd7bc58) Seq 20-451485862643892813: Sending { Cmd ,
MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckVirtualMachineCommand":{"vmName":"i-2-119-VM","wait":20}}]
}
2019-03-18 18:22:42,996 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-10:null) (logid:) Seq 20-451485862643892813:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.CheckVirtualMachineAnswer":{"state":"PowerOff","result":true,"wait":0}}]
}
2019-03-18 18:22:42,996 DEBUG [c.c.a.t.Request] (HA-Worker-3:ctx-9deb1ae0
work-1083) (logid:fbd7bc58) Seq 20-451485862643892813: Received: { Ans: ,
MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, {
CheckVirtualMachineAnswer } }
2019-03-18 18:22:42,996 DEBUG [c.c.h.CheckOnAgentInvestigator]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Agent responded with
state PowerOff
2019-03-18 18:22:42,996 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) SimpleInvestigator
found VM[User|i-2-119-VM] to be alive? false
2019-03-18 18:22:42,996 WARN [o.a.c.f.j.AsyncJobExecutionContext]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Job is executed
without a context, setup psudo job for the executing thread
2019-03-18 18:22:43,002 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Sync job-3447
execution on object VmWorkJobQueue.119
2019-03-18 18:22:43,284 DEBUG [c.c.s.d.DownloadListener]
(Timer-8:ctx-1d2632b2) (logid:c1478366) Scheduling timeout at 30000 ms,
VOLUME: 125 at host 22
2019-03-18 18:22:43,563 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 21-76900: Processing Seq
21-76900: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:43,564 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 21-76900: Sending Seq
21-76900: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:44,321 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-647d8f4f) (logid:bfe92640) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:44,322 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-647d8f4f)
(logid:bfe92640) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:44,322 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-647d8f4f) (logid:bfe92640) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:44,323 DEBUG [c.c.a.t.Request] (Timer-9:ctx-647d8f4f)
(logid:bfe92640) Seq 22-6353734649289638117: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:22:44,369 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-11:null) (logid:) Seq 22-6353734649289638117:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:44,615 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-92295f27) (logid:1e2c37b1) Execute sync-queue
item: SyncQueueItemVO {id:2403, queueId: 528, contentType: AsyncJob,
contentId: 3447, lastProcessMsid: 279278805450774, lastprocessNumber: 2172,
lastProcessTime: Mon Mar 18 18:22:44 CET 2019, created: Mon Mar 18 18:22:43
CET 2019}
2019-03-18 18:22:44,616 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-92295f27) (logid:1e2c37b1) Schedule queued
job-3447
2019-03-18 18:22:44,618 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:c48d4387) Add
job-3447 into job monitoring
2019-03-18 18:22:44,621 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:fea932f3)
Executing AsyncJobVO {id:3447, userId: 1, accountId: 1, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo:
rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAd3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwB,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 279278805450774, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 18 18:22:43 CET 2019}
2019-03-18 18:22:44,621 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:fea932f3) Run
VM work job: com.cloud.vm.VmWorkStop for VM 119, job origin: 3398
2019-03-18 18:22:44,622 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Execute VM work job:
com.cloud.vm.VmWorkStop{"cleanup":true,"userId":1,"accountId":1,"vmId":119,"handlerName":"VirtualMachineManagerImpl"}
2019-03-18 18:22:44,625 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) VM state transitted from :Running to Stopping with event:
StopRequestedvm's original host id: 20 new host id: 20 host id before state
transition: 20
2019-03-18 18:22:44,627 DEBUG [c.c.v.UserVmManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Collect vm disk statistics from host before stopping Vm
2019-03-18 18:22:44,670 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-14:null) (logid:) Seq 20-451485862643892814:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.GetVmDiskStatsAnswer":{"hostName":"fr-kvm1","vmDiskStatsMap":{},"result":true,"details":"","wait":0}}]
}
2019-03-18 18:22:44,670 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Seq 20-451485862643892814: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, {
GetVmDiskStatsAnswer } }
2019-03-18 18:22:44,670 DEBUG [c.c.a.m.AgentManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Details from executing class
com.cloud.agent.api.GetVmDiskStatsCommand:
2019-03-18 18:22:44,670 DEBUG [c.c.v.UserVmManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Collect vm network statistics from host before stopping Vm
2019-03-18 18:22:44,752 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-15:null) (logid:) Seq 20-451485862643892815:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.GetVmNetworkStatsAnswer":{"hostName":"fr-kvm1","vmNetworkStatsMap":{},"result":true,"details":"","wait":0}}]
}
2019-03-18 18:22:44,752 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Seq 20-451485862643892815: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, {
GetVmNetworkStatsAnswer } }
2019-03-18 18:22:44,752 DEBUG [c.c.a.m.AgentManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Details from executing class
com.cloud.agent.api.GetVmNetworkStatsCommand:
2019-03-18 18:22:44,754 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Seq 20-451485862643892816: Sending { Cmd , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":true,"volumesToDisconnect":[],"vmName":"i-2-119-VM","executeInSequence":false,"wait":0}}]
}
2019-03-18 18:22:45,003 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-1:null) (logid:) Seq 20-451485862643892816:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:45,003 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Seq 20-451485862643892816: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, { StopAnswer } }
2019-03-18 18:22:45,005 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) VM[User|i-2-119-VM] is stopped on the host. Proceeding to
release resource held.
2019-03-18 18:22:45,006 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:45,007 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Changing active number of nics for network id=204 on -1
2019-03-18 18:22:45,010 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Asking VirtualRouter to release
NicProfile[148-119-bd4804c3-2602-4e0f-ab98-b96ab54a31ab-137.74.35.65-vlan://untagged
2019-03-18 18:22:45,010 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Successfully released network resources for the vm
VM[User|i-2-119-VM]
2019-03-18 18:22:45,010 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Successfully released storage resources for the vm
VM[User|i-2-119-VM]
2019-03-18 18:22:45,017 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:45,018 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:45,018 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) VM state transitted from :Stopping to Stopped with event:
OperationSucceededvm's original host id: 20 new host id: null host id
before state transition: 20
2019-03-18 18:22:45,021 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Hosts's actual total CPU: 33600 and CPU after applying
overprovisioning: 168000
2019-03-18 18:22:45,021 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Hosts's actual total RAM: 67312107520 and RAM after
applying overprovisioning: 67312107520
2019-03-18 18:22:45,021 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) release cpu from host: 20, old used: 74500,reserved: 0,
actual total: 33600, total with overprovisioning: 168000; new used:
72500,reserved:2000; movedfromreserved: false,moveToReserveredtrue
2019-03-18 18:22:45,021 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) release mem from host: 20, old used: 42144366592,reserved:
0, total: 67312107520; new used: 41607495680,reserved:536870912;
movedfromreserved: false,moveToReserveredtrue
2019-03-18 18:22:45,033 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Done executing VM work job:
com.cloud.vm.VmWorkStop{"cleanup":true,"userId":1,"accountId":1,"vmId":119,"handlerName":"VirtualMachineManagerImpl"}
2019-03-18 18:22:45,033 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Complete async job-3447, jobStatus: SUCCEEDED, resultCode:
0, result: null
2019-03-18 18:22:45,034 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Publish async job-3447 complete on message bus
2019-03-18 18:22:45,034 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Wake up jobs related to job-3447
2019-03-18 18:22:45,034 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Update db status for job-3447
2019-03-18 18:22:45,034 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447 ctx-d7838953)
(logid:fea932f3) Wake up jobs joined with job-3447 and disjoin all subjobs
created from job- 3447
2019-03-18 18:22:45,036 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:fea932f3) Done
with run of VM work job: com.cloud.vm.VmWorkStop for VM 119, job origin:
3398
2019-03-18 18:22:45,036 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:fea932f3) Done
executing com.cloud.vm.VmWorkStop for job-3447
2019-03-18 18:22:45,037 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-67:ctx-8493592b job-3398/job-3447) (logid:fea932f3)
Remove job-3447 from job monitoring
2019-03-18 18:22:45,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Sync job-3448
execution on object VmWorkJobQueue.119
2019-03-18 18:22:46,615 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-509aa522) (logid:2f4e9ccb) Execute sync-queue
item: SyncQueueItemVO {id:2404, queueId: 528, contentType: AsyncJob,
contentId: 3448, lastProcessMsid: 279278805450774, lastprocessNumber: 2173,
lastProcessTime: Mon Mar 18 18:22:46 CET 2019, created: Mon Mar 18 18:22:45
CET 2019}
2019-03-18 18:22:46,615 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-509aa522) (logid:2f4e9ccb) Schedule queued
job-3448
2019-03-18 18:22:46,617 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:abfe4690) Add
job-3448 into job monitoring
2019-03-18 18:22:46,623 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:fea932f3)
Executing AsyncJobVO {id:3448, userId: 1, accountId: 1, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAd3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AAtIYU9wZXJhdGlvbnQAP3JPMEFCWE55QUJGcVlYWmhMbXhoYm1jdVFtOXZiR1ZoYnMwZ2NvRFZuUHJ1QWdBQldnQUZkbUZzZFdWNGNBRXhw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 279278805450774, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Mar 18 18:22:45 CET 2019}
2019-03-18 18:22:46,623 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:fea932f3) Run
VM work job: com.cloud.vm.VmWorkStart for VM 119, job origin: 3398
2019-03-18 18:22:46,624 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Execute VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"HaOperation":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":1,"accountId":1,"vmId":119,"handlerName":"VirtualMachineManagerImpl"}
2019-03-18 18:22:46,628 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) VM state transitted from :Stopped to Starting with event:
StartRequestedvm's original host id: 20 new host id: null host id before
state transition: null
2019-03-18 18:22:46,628 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Successfully transitioned to start state for
VM[User|i-2-119-VM] reservation id = 785ba7e4-975c-4f0d-a11b-9c19e4e31f8b
2019-03-18 18:22:46,635 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Deploy avoids pods: null, clusters: null, hosts: null
2019-03-18 18:22:46,636 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Root volume is ready, need to place VM in volume's cluster
2019-03-18 18:22:46,636 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Vol[109|vm=119|ROOT] is READY, changing deployment plan to
use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2019-03-18 18:22:46,640 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) DeploymentPlanner allocation algorithm: null
2019-03-18 18:22:46,640 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Trying to allocate a host and storage pools from dc:1,
pod:1,cluster:1, requested cpu: 2000, requested ram: 536870912
2019-03-18 18:22:46,640 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Is ROOT volume READY (pool already allocated)?: Yes
2019-03-18 18:22:46,643 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Deploy avoids pods: [], clusters: [], hosts: []
2019-03-18 18:22:46,643 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) This VM has last host_id specified, trying to choose the
same host: 20
2019-03-18 18:22:46,646 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Host: 20 has cpu capability (cpu:8, speed:4200) to support
requested CPU: 1 and requested speed: 2000
2019-03-18 18:22:46,646 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Checking if host: 20 has enough capacity for requested
CPU: 2000 and requested RAM: 536870912 , cpuOverprovisioningFactor: 5.0
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Hosts's actual total CPU: 33600 and CPU after applying
overprovisioning: 168000
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) We need to allocate to the last host again, so checking if
there is enough reserved capacity
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Reserved CPU: 2000 , Requested CPU: 2000
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Reserved RAM: 536870912 , Requested RAM: 536870912
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Host has enough CPU and RAM available
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) STATS: Can alloc CPU from host: 20, used: 72500, reserved:
2000, actual total: 33600, total with overprovisioning: 168000; requested
cpu:2000,alloc_from_last_host?:true ,considerReservedCapacity?: true
2019-03-18 18:22:46,647 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) STATS: Can alloc MEM from host: 20, used: 41607495680,
reserved: 536870912, total: 67312107520; requested mem:
536870912,alloc_from_last_host?:true ,considerReservedCapacity?: true
2019-03-18 18:22:46,647 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) The last host of this VM is UP and has enough capacity
2019-03-18 18:22:46,647 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Now checking for suitable pools under zone: 1, pod: 1,
cluster: 1
2019-03-18 18:22:46,648 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Checking suitable pools for volume (Id, Type): (109,ROOT)
2019-03-18 18:22:46,648 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Volume has pool already allocated, checking if pool can be
reused, poolId: 3
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Planner need not allocate a pool for this volume since its
READY
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Trying to find a potenial host and associated storage
pools from the suitable host/pool lists for this VM
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Checking if host: 20 can access any suitable storage pool
for volume: ROOT
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Host: 20 can access pool: 3
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Found a potential host id: 20 name: fr-kvm1 and associated
storage pools for this VM
2019-03-18 18:22:46,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Returning Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(20)-Storage()]
2019-03-18 18:22:46,649 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Deployment found - P0=VM[User|i-2-119-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(20)-Storage()]
2019-03-18 18:22:46,658 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) VM state transitted from :Starting to Starting with event:
OperationRetryvm's original host id: 20 new host id: 20 host id before
state transition: null
2019-03-18 18:22:46,658 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) VM starting again on the last host it was stopped on
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Hosts's actual total CPU: 33600 and CPU after applying
overprovisioning: 168000
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) We are allocating VM, increasing the used capacity of this
host:20
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Current Used CPU: 72500 , Free CPU:93500 ,Requested CPU:
2000
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Current Used RAM: 41607495680 , Free RAM:25167740928
,Requested RAM: 536870912
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) We are allocating VM to the last host again, so adjusting
the reserved capacity if it is not less than required
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Reserved CPU: 2000 , Requested CPU: 2000
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Reserved RAM: 536870912 , Requested RAM: 536870912
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) CPU STATS after allocation: for host: 20, old used: 72500,
old reserved: 2000, actual total: 33600, total with overprovisioning:
168000; new used:74500, reserved:0; requested cpu:2000,alloc_from_last:true
2019-03-18 18:22:46,662 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) RAM STATS after allocation: for host: 20, old used:
41607495680, old reserved: 536870912, total: 67312107520; new used:
42144366592, reserved: 0; requested mem: 536870912,alloc_from_last:true
2019-03-18 18:22:46,666 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Network id=204 is already implemented
2019-03-18 18:22:46,670 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:46,672 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Changing active number of nics for network id=204 on 1
2019-03-18 18:22:46,675 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Asking VirtualRouter to prepare for
Nic[148-119-785ba7e4-975c-4f0d-a11b-9c19e4e31f8b-137.74.35.65]
2019-03-18 18:22:46,684 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) CONFIG DHCP FOR SUBNETS RULES
2019-03-18 18:22:46,690 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) APPLYING DHCP ENTRY RULES
2019-03-18 18:22:46,690 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Applying dhcp entry in network Ntwk[204|Guest|7]
2019-03-18 18:22:46,698 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892817: Sending { Cmd , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:e1:00:00:ff","vmIpAddress":"137.74.35.65","vmName":"MikroTik-FR","defaultRouter":"137.74.35.126","duid":"00:03:00:01:1e:00:e1:00:00:ff","isDefault":true,"executeInSequence":false,"accessDetails":{"
router.name":"r-90-VM","router.guest.ip":"137.74.11.141","router.ip":"169.254.1.145","zone.network.type":"Basic"},"wait":0}}]
}
2019-03-18 18:22:47,391 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-3:null) (logid:) Seq 20-451485862643892817:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success:
Creating file in VR, with ip: 169.254.1.145, file:
vm_dhcp_entry.json.1c529eeb-8031-4869-993c-5a75fffb237b","null - success:
"],"result":true,"wait":0}}] }
2019-03-18 18:22:47,391 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892817: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, { GroupAnswer } }
2019-03-18 18:22:47,396 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) APPLYING USERDATA RULES
2019-03-18 18:22:47,396 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Applying userdata and password entry in network
Ntwk[204|Guest|7]
2019-03-18 18:22:47,402 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892818: Sending { Cmd , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"137.74.35.65","vmName":"MikroTik-FR","executeInSequence":false,"accessDetails":{"
router.name":"r-90-VM","router.guest.ip":"137.74.11.141","router.ip":"169.254.1.145","zone.network.type":"Basic"},"wait":0}}]
}
2019-03-18 18:22:48,302 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-4:null) (logid:) Seq 20-451485862643892818:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success:
Creating file in VR, with ip: 169.254.1.145, file:
vm_metadata.json.e938bfce-94f0-4698-b6b1-7aa8851d6282","null - success:
"],"result":true,"wait":0}}] }
2019-03-18 18:22:48,302 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892818: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, { GroupAnswer } }
2019-03-18 18:22:48,303 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:48,305 DEBUG [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) No need to recreate the volume: Vol[109|vm=119|ROOT],
since it already has a pool assigned: 3, adding disk to VM
2019-03-18 18:22:48,329 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892819: Sending { Cmd , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":119,"name":"i-2-119-VM","type":"User","cpus":1,"minSpeed":400,"maxSpeed":2000,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other
Linux (64-bit)","platformEmulator":"Other
Linux","bootArgs":"","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ccar-5uGy5DiOLpHc2mh0w","params":{"cpuNumber":"1","memory":"512","cpuSpeed":"2000","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"5","rootDiskController":"osdefault"},"uuid":"4fa6bfb0-fe1a-49cf-9a0e-111d220cde33","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"088a0fa2-e48d-3c0b-997e-cca9c37bd03b","id":3,"poolType":"NetworkFilesystem","host":"192.168.0.1","path":"/home2/primary2","port":2049,"url":"NetworkFilesystem://
192.168.0.1/home2/primary2/?ROLE=Primary&STOREUUID=088a0fa2-e48d-3c0b-997e-cca9c37bd03b","isManaged":false}},"name":"ROOT-119","size":1073741824,"path":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","volumeId":109,"vmName":"i-2-119-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":109,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","type":"ROOT","_details":{"storageHost":"192.168.0.1","managed":"false","storagePort":"2049","volumeSize":"1073741824"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false,"bootable":false,"directDownload":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":500,"defaultNic":true,"pxeDisable":false,"nicUuid":"908decef-1520-4869-92f4-da69f32bc3b0","details":{"PromiscuousMode":"false","ForgedTransmits":"true","MacAddressChanges":"true"},"uuid":"6e644551-5aee-4c9b-a75f-134f544ee97c","ip":"137.74.35.65","netmask":"255.255.255.192","gateway":"137.74.35.126","mac":"1e:00:e1:00:00:ff","dns1":"8.8.8.8","dns2":"4.2.2.4","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"}],"guestOsDetails":{}},"hostIp":"192.168.0.1","executeInSequence":false,"wait":0}}]
}
2019-03-18 18:22:49,559 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-2:null) (logid:) Seq 20-451485862643892819:
Processing: { Ans: , MgmtId: 279278805450774, via: 20, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":119,"name":"i-2-119-VM","type":"User","cpus":1,"minSpeed":400,"maxSpeed":2000,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Other
Linux (64-bit)","platformEmulator":"Other
Linux","bootArgs":"","enableHA":true,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"ccar-5uGy5DiOLpHc2mh0w","vncAddr":"192.168.0.1","params":{"cpuNumber":"1","memory":"512","cpuSpeed":"2000","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"5","rootDiskController":"osdefault"},"uuid":"4fa6bfb0-fe1a-49cf-9a0e-111d220cde33","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"088a0fa2-e48d-3c0b-997e-cca9c37bd03b","id":3,"poolType":"NetworkFilesystem","host":"192.168.0.1","path":"/home2/primary2","port":2049,"url":"NetworkFilesystem://
192.168.0.1/home2/primary2/?ROLE=Primary&STOREUUID=088a0fa2-e48d-3c0b-997e-cca9c37bd03b","isManaged":false}},"name":"ROOT-119","size":1073741824,"path":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","volumeId":109,"vmName":"i-2-119-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":109,"deviceId":0,"bytesReadRate":0,"bytesWriteRate":0,"iopsReadRate":0,"iopsWriteRate":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"6f4a0da2-0866-4fc8-9414-a3c5dfa68182","type":"ROOT","_details":{"storageHost":"192.168.0.1","managed":"false","storagePort":"2049","volumeSize":"1073741824"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false,"bootable":false,"directDownload":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":500,"defaultNic":true,"pxeDisable":false,"nicUuid":"908decef-1520-4869-92f4-da69f32bc3b0","details":{"PromiscuousMode":"false","ForgedTransmits":"true","MacAddressChanges":"true"},"uuid":"6e644551-5aee-4c9b-a75f-134f544ee97c","ip":"137.74.35.65","netmask":"255.255.255.192","gateway":"137.74.35.126","mac":"1e:00:e1:00:00:ff","dns1":"8.8.8.8","dns2":"4.2.2.4","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"}],"guestOsDetails":{}},"result":true,"wait":0}}]
}
2019-03-18 18:22:49,559 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Seq 20-451485862643892819: Received: { Ans: , MgmtId:
279278805450774, via: 20(fr-kvm1), Ver: v1, Flags: 10, { StartAnswer } }
2019-03-18 18:22:49,577 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:49,580 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Service SecurityGroup is not supported in the network
id=204
2019-03-18 18:22:49,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) VM state transitted from :Starting to Running with event:
OperationSucceededvm's original host id: 20 new host id: 20 host id before
state transition: 20
2019-03-18 18:22:49,587 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Start completed for VM VM[User|i-2-119-VM]
2019-03-18 18:22:49,588 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Done executing VM work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"HaOperation":"rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE"},"userId":1,"accountId":1,"vmId":119,"handlerName":"VirtualMachineManagerImpl"}
2019-03-18 18:22:49,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Complete async job-3448, jobStatus: SUCCEEDED, resultCode:
0, result: null
2019-03-18 18:22:49,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Publish async job-3448 complete on message bus
2019-03-18 18:22:49,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Wake up jobs related to job-3448
2019-03-18 18:22:49,588 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Update db status for job-3448
2019-03-18 18:22:49,589 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448 ctx-bc502c4b)
(logid:fea932f3) Wake up jobs joined with job-3448 and disjoin all subjobs
created from job- 3448
2019-03-18 18:22:49,592 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:fea932f3) Done
with run of VM work job: com.cloud.vm.VmWorkStart for VM 119, job origin:
3398
2019-03-18 18:22:49,592 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:fea932f3) Done
executing com.cloud.vm.VmWorkStart for job-3448
2019-03-18 18:22:49,592 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-68:ctx-b99a9405 job-3398/job-3448) (logid:fea932f3)
Remove job-3448 from job monitoring
2019-03-18 18:22:49,596 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) VM is now restarted:
119 on 20
2019-03-18 18:22:49,596 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-9deb1ae0 work-1083) (logid:fbd7bc58) Completed work
HAWork[1083-HA-119-Running-Scheduled]
2019-03-18 18:22:50,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-790ed46a) (logid:01db6d29) Begin cleanup
expired async-jobs
2019-03-18 18:22:50,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-790ed46a) (logid:01db6d29) End cleanup expired
async-jobs
2019-03-18 18:22:52,062 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) Ping from 22(s-96-VM)
2019-03-18 18:22:53,284 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-9b303689) (logid:9a3e5653) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:53,285 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-9b303689)
(logid:9a3e5653) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:53,285 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-9b303689) (logid:9a3e5653) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:53,285 DEBUG [c.c.a.t.Request] (Timer-8:ctx-9b303689)
(logid:9a3e5653) Seq 22-6353734649289638118: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:22:53,331 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-13:null) (logid:) Seq 22-6353734649289638118:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:53,564 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) (logid:) SeqA 21-76901: Processing Seq
21-76901: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:22:53,565 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) (logid:) SeqA 21-76901: Sending Seq
21-76901: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:22:54,371 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-9:ctx-67a9d187) (logid:57c8b2a4) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:22:54,371 DEBUG [c.c.h.XenServerGuru] (Timer-9:ctx-67a9d187)
(logid:57c8b2a4) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:22:54,372 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-9:ctx-67a9d187) (logid:57c8b2a4) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:22:54,372 DEBUG [c.c.a.t.Request] (Timer-9:ctx-67a9d187)
(logid:57c8b2a4) Seq 22-6353734649289638119: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":126,"resourceType":"VOLUME","installPath":"volumes/2/126","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-126","wait":0}}]
}
2019-03-18 18:22:54,417 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 22-6353734649289638119:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"aa3dfe84-4d99-47eb-90ec-9854e16229d0","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/126/dnld7531023510809315785tmp_","installPath":"volumes/2/126","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:22:55,690 DEBUG [c.c.s.StatsCollector]
(StatsCollector-6:ctx-9024df8e) (logid:ed9a1588) AutoScaling Monitor is
running...
2019-03-18 18:22:56,510 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-0275fdca) (logid:807c0d17) HostStatsCollector is
running...
2019-03-18 18:22:56,515 DEBUG [c.c.a.t.Request]
(StatsCollector-1:ctx-0275fdca) (logid:807c0d17) Seq 20-451485862643892820:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetHostStatsAnswer } }
2019-03-18 18:23:00,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-b858eb97) (logid:f86a93f1) Begin cleanup
expired async-jobs
2019-03-18 18:23:00,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-b858eb97) (logid:f86a93f1) End cleanup expired
async-jobs
2019-03-18 18:23:03,181 DEBUG [c.c.s.StatsCollector]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) StorageCollector is
running...
2019-03-18 18:23:03,185 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:23:03,185 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:23:03,255 DEBUG [c.c.a.t.Request]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) Seq
22-6353734649289638120: Received: { Ans: , MgmtId: 279278805450774, via:
22(s-96-VM), Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:23:03,257 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:23:03,257 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:23:03,334 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Timer-8:ctx-179fa856) (logid:bca22076) getCommandHostDelegation: class
org.apache.cloudstack.storage.command.DownloadProgressCommand
2019-03-18 18:23:03,335 DEBUG [c.c.h.XenServerGuru] (Timer-8:ctx-179fa856)
(logid:bca22076) We are returning the default host to execute commands
because the command is not of Copy type.
2019-03-18 18:23:03,335 DEBUG [o.a.c.s.RemoteHostEndPoint]
(Timer-8:ctx-179fa856) (logid:bca22076) Sending command
org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 22
2019-03-18 18:23:03,336 DEBUG [c.c.a.t.Request] (Timer-8:ctx-179fa856)
(logid:bca22076) Seq 22-6353734649289638121: Sending { Cmd , MgmtId:
279278805450774, via: 22(s-96-VM), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","request":"GET_STATUS","hvm":false,"maxDownloadSizeInBytes":536870912000,"id":125,"resourceType":"VOLUME","installPath":"volumes/2/125","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
192.168.0.1/home2/secondary","_role":"Image"}},"url":"
http://178.33.230.41/vps/Younes.qcow2","format":"QCOW2","accountId":2,"name":"DATA-Younes","wait":0}}]
}
2019-03-18 18:23:03,356 DEBUG [c.c.a.t.Request]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) Seq 20-451485862643892821:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:23:03,357 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2019-03-18 18:23:03,357 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) We are returning the
default host to execute commands because the command is not of Copy type.
2019-03-18 18:23:03,378 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-12:null) (logid:) Seq 22-6353734649289638121:
Processing: { Ans: , MgmtId: 279278805450774, via: 22, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"46ad04c0-44d1-4f79-ac61-189c04f00564","downloadPct":0,"errorString":"
","downloadStatus":"NOT_DOWNLOADED","downloadPath":"/mnt/SecStorage/cf5552bd-cb13-38f0-b01e-1f9d16cd1924/volumes/2/125/dnld1738121055299197614tmp_","installPath":"volumes/2/125","templateSize":0,"templatePhySicalSize":0,"result":true,"details":"
","wait":0}}] }
2019-03-18 18:23:03,551 DEBUG [c.c.a.t.Request]
(StatsCollector-5:ctx-f1ba4e22) (logid:2b60a4d2) Seq 20-451485862643892822:
Received: { Ans: , MgmtId: 279278805450774, via: 20(fr-kvm1), Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2019-03-18 18:23:03,565 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) (logid:) SeqA 21-76902: Processing Seq
21-76902: { Cmd , MgmtId: -1, via: 21, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":97,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2019-03-18 18:23:03,566 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) (logid:) SeqA 21-76902: Sending Seq
21-76902: { Ans: , MgmtId: 279278805450774, via: 21, Ver: v1, Flags:
100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2019-03-18 18:23:04,321 DEBUG [c.c.s.d.DownloadListener]
(Timer-9:ctx-cfbd11cb) (logid:81b469da) Scheduling timeout at 30000 ms,
VOLUME: 126 at host 22
2019-03-18 18:23:10,616 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-4a9c9ff4) (logid:445a4e84) Begin cleanup
expired async-jobs
2019-03-18 18:23:10,619 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-4a9c9ff4) (logid:445a4e84) End cleanup expired
async-jobs
2019-03-18 18:23:10,749 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-cf443d76) (logid:b53666b8) Found 0 routers to
update status.
2019-03-18 18:23:10,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-cf443d76) (logid:b53666b8) Found 0 VPC networks
to update Redundant State.
2019-03-18 18:23:10,750 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-cf443d76) (logid:b53666b8) Found 0 networks to
update RvR status.
