search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
2k stars 1.09k forks source link

Import VM logging improvements #9284

Closed sureshanaparti closed 3 months ago

sureshanaparti commented 3 months ago

Description

This PR improves logs while importing vm from remote/external KVM host.

Fixes #8779

Types of changes

Feature/Enhancement Scale or Bug Severity

Feature/Enhancement Scale

Bug Severity

Screenshots (if appropriate):

How Has This Been Tested?

Manually tested import vm operation and checked the import logs in MS / KVM host.

MS logs =>

2024-06-21 19:45:11,411 DEBUG [c.c.a.t.Request] (qtp1866850137-19:ctx-7f9bf2bb ctx-a94593d9) (logid:a066305c) Seq 1-168603511049682964: Sending  { Cmd , MgmtId: 32986204471710, via: 1(ref-trl-6881-k-M7-suresh-anaparti-kvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetRemoteVmsCommand":{"remoteIp":"10.x.x.x","username":"root","wait":"0","bypassHostMaintenance":"false"}}] }
2024-06-21 19:45:11,467 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) (logid:) Seq 1-168603511049682964: Processing:  { Ans: , MgmtId: 32986204471710, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetRemoteVmsAnswer":{"remoteIp":"10.x.x.x","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }
2024-06-21 19:45:11,467 DEBUG [c.c.a.t.Request] (qtp1866850137-19:ctx-7f9bf2bb ctx-a94593d9) (logid:a066305c) Seq 1-168603511049682964: Received:  { Ans: , MgmtId: 32986204471710, via: 1(ref-trl-6881-k-M7-suresh-anaparti-kvm1), Ver: v1, Flags: 10, { GetRemoteVmsAnswer } }
...
2024-06-21 19:46:11,369 ERROR [o.a.c.v.UnmanagedVMsManagerImpl] (API-Job-Executor-1:ctx-b1fc397c job-43 ctx-8e262883) (logid:f12d765a) Initiating copy remote volume /root/kvm.qcow2 from 10.x.x.x, timeout 900 secs
2024-06-21 19:46:11,371 DEBUG [c.c.a.t.Request] (API-Job-Executor-1:ctx-b1fc397c job-43 ctx-8e262883) (logid:f12d765a) Seq 2-521854606821556251: Sending  { Cmd , MgmtId: 32986204471710, via: 2(ref-trl-6881-k-M7-suresh-anaparti-kvm2), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CopyRemoteVolumeCommand":{"remoteIp":"10.x.x.x","username":"root","srcFile":"/root/kvm.qcow2","tmpPath":"/tmp/","storageFilerTO":{"id":"2","uuid":"f860203f-18b5-3ef8-ad58-66f40316f09d","host":"10.x.x.x","path":"/acs/primary/ref-trl-6881-k-M7-suresh-anaparti/ref-trl-6881-k-M7-suresh-anaparti-kvm-pri2","port":"2049","type":"NetworkFilesystem"},"wait":"900","bypassHostMaintenance":"false"}}] }
2024-06-21 19:46:12,151 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) (logid:) Seq 2-521854606821556251: Processing:  { Ans: , MgmtId: 32986204471710, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.CopyRemoteVolumeAnswer":{"remoteIp":"10.x.x.x","filename":"f1779731-5b6a-4006-96c6-431143929fd8","size":"(1.00 GB) 1073741824","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }
2024-06-21 19:46:12,152 DEBUG [c.c.a.t.Request] (API-Job-Executor-1:ctx-b1fc397c job-43 ctx-8e262883) (logid:f12d765a) Seq 2-521854606821556251: Received:  { Ans: , MgmtId: 32986204471710, via: 2(ref-trl-6881-k-M7-suresh-anaparti-kvm2), Ver: v1, Flags: 10, { CopyRemoteVolumeAnswer } }

KVM host logs =>

2024-06-21 19:45:11,421 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:a066305c) Request:Seq 1-168603511049682964:  { Cmd , MgmtId: 32986204471710, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.GetRemoteVmsCommand":{"remoteIp":"10.x.x.x","username":"root","wait":"0","bypassHostMaintenance":"false"}}] }
2024-06-21 19:45:11,421 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:a066305c) Processing command: com.cloud.agent.api.GetRemoteVmsCommand
2024-06-21 19:45:11,422 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:a066305c) Looking for libvirtd connection at: qemu+tcp://10.x.x.x/system
2024-06-21 19:45:11,422 INFO  [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:a066305c) No existing libvirtd connection found. Opening a new one
2024-06-21 19:45:11,427 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:a066305c) Successfully connected to libvirt at: qemu+tcp://10.x.x.x/system
2024-06-21 19:45:11,436 INFO  [resource.wrapper.LibvirtGetRemoteVmsCommandWrapper] (agentRequest-Handler-3:null) (logid:a066305c) Found 3 VMs on the remote host 10.x.x.x
2024-06-21 19:45:11,437 DEBUG [resource.wrapper.LibvirtGetRemoteVmsCommandWrapper] (agentRequest-Handler-3:null) (logid:a066305c) Remote VM guest1-rhel7 - powerstate: VIR_DOMAIN_SHUTOFF, state: PowerOff
2024-06-21 19:45:11,461 DEBUG [resource.wrapper.LibvirtGetRemoteVmsCommandWrapper] (agentRequest-Handler-3:null) (logid:a066305c) Remote VM i-2-7-VM - powerstate: VIR_DOMAIN_RUNNING, state: PowerOn
2024-06-21 19:45:11,462 DEBUG [resource.wrapper.LibvirtGetRemoteVmsCommandWrapper] (agentRequest-Handler-3:null) (logid:a066305c) Remote VM i-2-6-VM - powerstate: VIR_DOMAIN_RUNNING, state: PowerOn
2024-06-21 19:45:11,464 DEBUG [resource.wrapper.LibvirtGetRemoteVmsCommandWrapper] (agentRequest-Handler-3:null) (logid:a066305c) Found 1 stopped VMs on remote host 10.x.x.x
2024-06-21 19:45:11,466 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:a066305c) Seq 1-168603511049682964:  { Ans: , MgmtId: 32986204471710, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.GetRemoteVmsAnswer":{"remoteIp":"10.x.x.x","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }
...
2024-06-21 19:46:11,422 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:f12d765a) Request:Seq 2-521854606821556251:  { Cmd , MgmtId: 32986204471710, via: 2, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.CopyRemoteVolumeCommand":{"remoteIp":"10.x.x.x","username":"root","srcFile":"/root/kvm.qcow2","tmpPath":"/tmp/","storageFilerTO":{"id":"2","uuid":"f860203f-18b5-3ef8-ad58-66f40316f09d","host":"10.x.x.x","path":"/acs/primary/ref-trl-6881-k-M7-suresh-anaparti/ref-trl-6881-k-M7-suresh-anaparti-kvm-pri2","port":"2049","type":"NetworkFilesystem"},"wait":"900","bypassHostMaintenance":"false"}}] }
2024-06-21 19:46:11,431 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:f12d765a) Successfully refreshed pool f860203f-18b5-3ef8-ad58-66f40316f09d Capacity: (1.9990 TB) 2197949513728 Used: (1.2908 TB) 1419287461888 Available: (725.19 GB) 778662051840
2024-06-21 19:46:11,432 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f12d765a) Converting remote disk file: /root/kvm.qcow2, output file: /tmp/f1779731-5b6a-4006-96c6-431143929fd8 (timeout: 900 secs)
2024-06-21 19:46:11,871 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f12d765a) Copying converted remote disk file f1779731-5b6a-4006-96c6-431143929fd8 to: /mnt/f860203f-18b5-3ef8-ad58-66f40316f09d
2024-06-21 19:46:12,104 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f12d765a) Successfully copied converted remote disk file to: /mnt/f860203f-18b5-3ef8-ad58-66f40316f09d/f1779731-5b6a-4006-96c6-431143929fd8
2024-06-21 19:46:12,105 DEBUG [resource.wrapper.LibvirtCopyRemoteVolumeCommandWrapper] (agentRequest-Handler-1:null) (logid:f12d765a) Volume /root/kvm.qcow2 copy successful, copied to file: f1779731-5b6a-4006-96c6-431143929fd8
2024-06-21 19:46:12,111 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:f12d765a) Could not find volume f1779731-5b6a-4006-96c6-431143929fd8: Storage volume not found: no storage vol with matching name 'f1779731-5b6a-4006-96c6-431143929fd8'
2024-06-21 19:46:12,112 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:f12d765a) Refreshing storage pool f860203f-18b5-3ef8-ad58-66f40316f09d
2024-06-21 19:46:12,128 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:f12d765a) Found volume f1779731-5b6a-4006-96c6-431143929fd8 in storage pool f860203f-18b5-3ef8-ad58-66f40316f09d after refreshing the pool
2024-06-21 19:46:12,156 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:f12d765a) Seq 2-521854606821556251:  { Ans: , MgmtId: 32986204471710, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.CopyRemoteVolumeAnswer":{"remoteIp":"10.x.x.x","filename":"f1779731-5b6a-4006-96c6-431143929fd8","size":"(1.00 GB) 1073741824","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }

How did you try to break this feature and the system with this change?

vishesh92 commented 3 months ago

@blueorangutan package

blueorangutan commented 3 months ago

@vishesh92 a [SL] Jenkins job has been kicked to build packages. It will be bundled with KVM, XenServer and VMware SystemVM templates. I'll keep you posted as I make progress.

blueorangutan commented 3 months ago

Packaging result [SF]: ✔️ el7 ✔️ el8 ✔️ el9 ✔️ debian ✔️ suse15. SL-JID 10070

sureshanaparti commented 3 months ago

@blueorangutan test

blueorangutan commented 3 months ago

@sureshanaparti a [SL] Trillian-Jenkins test job (centos7 mgmt + kvm-centos7) has been kicked to run smoke tests

blueorangutan commented 3 months ago

[SF] Trillian test result (tid-10572) Environment: kvm-centos7 (x2), Advanced Networking with Mgmt server 7 Total time taken: 40774 seconds Marvin logs: https://github.com/blueorangutan/acs-prs/releases/download/trillian/pr9284-t10572-kvm-centos7.zip Smoke tests completed. 131 look OK, 0 have errors, 0 did not run Only failed and skipped tests results shown below:

Test Result Time (s) Test File