Yes, I have updated it. I can upload templates but not volumes. The URL is on server's public IP
On 3/19/19, Dag Sonstebo <[email protected]> wrote: > Fariborz, > > Have you updated "secstorage.allowed.internal.sites" to allow upload from > the internal IP range your management server is on? > > Regards, > Dag Sonstebo > Cloud Architect > ShapeBlue > > > On 18/03/2019, 17:24, "Fariborz Navidan" <[email protected]> wrote: > > 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. > > > > [email protected] > www.shapeblue.com > Amadeus House, Floral Street, London WC2E 9DPUK > @shapeblue > > > >
