Volume Snapshots Failing After 3600 Seconds

[whitetiger264]

ISSUE TYPE

• Bug Report

COMPONENT NAME

• Storage & KVM

CLOUDSTACK VERSION

• 4.17.0.1

CONFIGURATION

• 1 X Management Server that hosts /primary & /secondary storage.
• 1 X KVM Server.
• Advanced Network - Default Security Group.

OS / ENVIRONMENT

Both Management & KVM run Almalinux 8

SUMMARY

• Making manual or recurring volume snapshots fails and times out after 3600 seconds. The timeout seems to happen once VM Snapshot is converted to qcow2.

STEPS TO REPRODUCE

• Run volume snapshot of linux VM while VM is online.

Here are a few log entries:

2022-10-17 20:51:30,536 WARN  [o.a.c.f.j.i.AsyncJobMonitor] (Timer-0:ctx-ec4e885c) (logid:0ca5ca78) Task (job-956) has been pending for 3266 seconds
2022-10-17 20:51:30,568 DEBUG [c.c.s.StatsCollector] (secstorage-1:ctx-714f41f7) (logid:da002c15) Verifying image storage [1]. Capacity: total=[870 GB], used=[357 GB], threshold=[89.99999761581421%].
2022-10-17 20:51:30,570 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-714f41f7) (logid:da002c15) Zone [1] is ready to launch secondary storage VM.
2022-10-17 20:51:33,971 DEBUG [o.a.c.h.HAManagerImpl] (BackgroundTaskPollManager-4:ctx-516d88d5) (logid:3305a3a6) HA health check task is running...
2022-10-17 20:51:35,610 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) SeqA 5-1273: Processing Seq 5-1273:  { Cmd , MgmtId: -1, via: 5, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"11","_loadInfo":"{

2022-10-17 20:57:03,623 DEBUG [c.c.a.m.AgentAttache] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Seq 1-8475211548757852179: Waiting some more time because this is the current command
2022-10-17 20:57:03,626 WARN  [c.c.a.m.AgentAttache] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Seq 1-8475211548757852179: Timed out on Seq 1-8475211548757852179:  { Cmd , MgmtId: 2619780474, via: 1(KVMHOSTNAME), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MGMNTSERVERIPADDRESS","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MGMNTSERVERIPADDRESS/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"name":"ROOT-19","size":"(50,00 GB) 53687091200","path":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeId":"24","vmName":"i-2-19-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"24","deviceId":"0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MGMNTSERVERIPADDRESS","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MGMNTSERVERIPADDRESS/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"vmName":"i-2-19-VM","name":"Test006","hypervisorType":"KVM","id":"27","quiescevm":"false","physicalSize":"0"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-17 20:57:03,626 DEBUG [c.c.a.m.AgentAttache] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Seq 1-8475211548757852179: Cancelling.
2022-10-17 20:57:03,626 DEBUG [o.a.c.s.RemoteHostEndPoint] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,627 DEBUG [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Failed to take snapshot: 27
2022-10-17 20:57:03,628 DEBUG [o.a.c.s.s.SnapshotServiceImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) create snapshot Test006 failed: com.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,640 DEBUG [o.a.c.s.s.DefaultSnapshotStrategy] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Failed to take snapshot: com.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,646 DEBUG [c.c.s.s.SnapshotManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Failed to create snapshotcom.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,646 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Updating resource Type = snapshot count for Account = 2 Operation = decreasing Amount = 1
2022-10-17 20:57:03,650 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Updating resource Type = secondary_storage count for Account = 2 Operation = decreasing Amount = (50,00 GB) 53687091200
2022-10-17 20:57:03,654 ERROR [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Take snapshot: 24 failed
2022-10-17 20:57:03,655 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,655 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956 ctx-3220426d) (logid:917cdd39) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 8475211548757852179 to Host 1 timed out after 3600
2022-10-17 20:57:03,656 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Done with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 19, job origin: 955
2022-10-17 20:57:03,656 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Unable to complete AsyncJobVO: {id:956, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAAZaAAthc3luY0JhY2t1cFoACXF1aWVzY2VWbUwADGxvY2F0aW9uVHlwZXQAKUxjb20vY2xvdWQvc3RvcmFnZS9TbmFwc2hvdCRMb2NhdGlvblR5cGU7TAAIcG9saWN5SWR0ABBMamF2YS9sYW5nL0xvbmc7TAAKc25hcHNob3RJZHEAfgACTAAIdm9sdW1lSWRxAH4AAnhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAE3QAFFZvbHVtZUFwaVNlcnZpY2VJbXBsAABwc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAAc3EAfgAHAAAAAAAAABtzcQB-AAcAAAAAAAAAGA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 2619780474, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Oct 17 19:57:03 SAST 2022, removed: null}, job origin:955
2022-10-17 20:57:03,667 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Complete async job-956, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0AMRjb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbjogRmFpbGVkIHRvIHNlbmQgY29tbWFuZCwgZHVlIHRvIEFnZW50OjEsIGNvbS5jbG91ZC5leGNlcHRpb24uT3BlcmF0aW9uVGltZWRvdXRFeGNlcHRpb246IENvbW1hbmRzIDg0NzUyMTE1NDg3NTc4NTIxNzkgdG8gSG9zdCAxIHRpbWVkIG91dCBhZnRlciAzNjAwdXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAuc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAFTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABUwACGZpbGVOYW1lcQB-AAVMAAptZXRob2ROYW1lcQB-AAVMAAptb2R1bGVOYW1lcQB-AAVMAA1tb2R1bGVWZXJzaW9ucQB-AAV4cAEAAAG6dAADYXBwdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLnN0b3JhZ2Uuc25hcHNob3QuRGVmYXVsdFNuYXBzaG90U3RyYXRlZ3l0ABxEZWZhdWx0U25hcHNob3RTdHJhdGVneS5qYXZhdAAMdGFrZVNuYXBzaG90cHBzcQB-AAwBAAAE2HEAfgAOdAAuY29tLmNsb3VkLnN0b3JhZ2Uuc25hcHNob3QuU25hcHNob3RNYW5hZ2VySW1wbHQAGFNuYXBzaG90TWFuYWdlckltcGwuamF2YXEAfgARcHBzcQB-AAwC_____nB0AC1qZGsuaW50ZXJuYWwucmVmbGVjdC5OYXRpdmVNZXRob2RBY2Nlc3NvckltcGx0AB1OYXRpdmVNZXRob2RBY2Nlc3NvckltcGwuamF2YXQAB2ludm9rZTB0AAlqYXZhLmJhc2V0AAkxMS4wLjE2LjFzcQB-AAwCAAAAPnBxAH4AFnEAfgAXdAAGaW52b2tlcQB-ABlxAH4AGnNxAH4ADAIAAAArcHQAMWpkay5pbnRlcm5hbC5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHHEAfgAZcQB-ABpzcQB-AAwCAAACNnB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAccQB-ABlxAH4AGnNxAH4ADAEAAAFYcQB-AA50AChvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5zdXBwb3J0LkFvcFV0aWxzdAANQW9wVXRpbHMuamF2YXQAHmludm9rZUpvaW5wb2ludFVzaW5nUmVmbGVjdGlvbnBwc3EAfgAMAQAAAMZxAH4ADnQAPG9yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmZyYW1ld29yay5SZWZsZWN0aXZlTWV0aG9kSW52b2NhdGlvbnQAH1JlZmxlY3RpdmVNZXRob2RJbnZvY2F0aW9uLmphdmF0AA9pbnZva2VKb2lucG9pbnRwcHNxAH4ADAEAAACjcQB-AA5xAH4AKHEAfgApdAAHcHJvY2VlZHBwc3EAfgAMAQAAAGFxAH4ADnQAP29yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmludGVyY2VwdG9yLkV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvcnQAIEV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvci5qYXZhcQB-ABxwcHNxAH4ADAEAAAC6cQB-AA5xAH4AKHEAfgApcQB-ACxwcHNxAH4ADAEAAADXcQB-AA50ADRvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuSmRrRHluYW1pY0FvcFByb3h5dAAXSmRrRHluYW1pY0FvcFByb3h5LmphdmFxAH4AHHBwc3EAfgAMAP____9wdAAXY29tLnN1bi5wcm94eS4kUHJveHkyMjFwcQB-ABFwcHNxAH4ADAEAAAqDcQB-AA50ADZvcmcuYXBhY2hlLmNsb3Vkc3RhY2suc3RvcmFnZS52b2x1bWUuVm9sdW1lU2VydmljZUltcGx0ABZWb2x1bWVTZXJ2aWNlSW1wbC5qYXZhcQB-ABFwcHNxAH4ADAEAAAzLcQB-AA50ACZjb20uY2xvdWQuc3RvcmFnZS5Wb2x1bWVBcGlTZXJ2aWNlSW1wbHQAGVZvbHVtZUFwaVNlcnZpY2VJbXBsLmphdmF0AB1vcmNoZXN0cmF0ZVRha2VWb2x1bWVTbmFwc2hvdHBwc3EAfgAMAQAAEONxAH4ADnEAfgA6cQB-ADtxAH4APHBwc3EAfgAMAv____5wcQB-ABZxAH4AF3EAfgAYcQB-ABlxAH4AGnNxAH4ADAIAAAA-cHEAfgAWcQB-ABdxAH4AHHEAfgAZcQB-ABpzcQB-AAwCAAAAK3BxAH4AHnEAfgAfcQB-ABxxAH4AGXEAfgAac3EAfgAMAgAAAjZwcQB-ACFxAH4AInEAfgAccQB-ABlxAH4AGnNxAH4ADAEAAABrcQB-AA50ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4ADAEAABDpcQB-AA5xAH4AOnEAfgA7cQB-AEVwcHNxAH4ADAL____-cHEAfgAWcQB-ABdxAH4AGHEAfgAZcQB-ABpzcQB-AAwCAAAAPnBxAH4AFnEAfgAXcQB-ABxxAH4AGXEAfgAac3EAfgAMAgAAACtwcQB-AB5xAH4AH3EAfgAccQB-ABlxAH4AGnNxAH4ADAIAAAI2cHEAfgAhcQB-ACJxAH4AHHEAfgAZcQB-ABpzcQB-AAwBAAABWHEAfgAOcQB-ACRxAH4AJXEAfgAmcHBzcQB-AAwBAAAAxnEAfgAOcQB-AChxAH4AKXEAfgAqcHBzcQB-AAwBAAAAo3EAfgAOcQB-AChxAH4AKXEAfgAscHBzcQB-AAwBAAAAYXEAfgAOcQB-AC5xAH4AL3EAfgAccHBzcQB-AAwBAAAAunEAfgAOcQB-AChxAH4AKXEAfgAscHBzcQB-AAwBAAAA13EAfgAOcQB-ADJxAH4AM3EAfgAccHBzcQB-AAwA_____3B0ABdjb20uc3VuLnByb3h5LiRQcm94eTIyOXBxAH4ARXBwc3EAfgAMAQAAAGZxAH4ADnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-AAwBAAACbHEAfgAOdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-AAwBAAAAMHEAfgAOdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4ADAEAAAA3cQB-AA50AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4ADAEAAABmcQB-AA50AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-AGF0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4ADAEAAAA0cQB-AA5xAH4AZHEAfgBhdAAOcnVuV2l0aENvbnRleHRwcHNxAH4ADAEAAAAtcQB-AA50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AXXEAfgBecHBzcQB-AAwBAAACOHEAfgAOcQB-AFhxAH4AWXEAfgBecHBzcQB-AAwCAAACA3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AYnEAfgAZcQB-ABpzcQB-AAwCAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-AF5xAH4AGXEAfgAac3EAfgAMAgAABGhwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AGXEAfgAac3EAfgAMAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgBzcQB-AF5xAH4AGXEAfgAac3EAfgAMAgAAAz1wdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-AF5xAH4AGXEAfgAac3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweAAAEJp3CAAAAAAAAAAAeA
2022-10-17 20:57:03,668 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Publish async job-956 complete on message bus
2022-10-17 20:57:03,668 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Wake up jobs related to job-956
2022-10-17 20:57:03,668 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Update db status for job-956
2022-10-17 20:57:03,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Wake up jobs joined with job-956 and disjoin all subjobs created from job- 956
2022-10-17 20:57:03,676 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Done executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-956
2022-10-17 20:57:03,677 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-ecdbd329 job-955/job-956) (logid:917cdd39) Remove job-956 from job monitoring
2022-10-17 20:57:03,688 ERROR [o.a.c.a.c.u.s.CreateSnapshotCmd] (API-Job-Executor-1:ctx-4c0df155 job-955 ctx-04b40830) (logid:917cdd39) Failed to create snapshot due to an internal error creating snapshot for volume 635fd5b5-bf14-4cf4-979c-be8a649d5189
2022-10-17 20:57:03,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Complete async job-955, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Failed to create snapshot due to an internal error creating snapshot for volume 635fd5b5-bf14-4cf4-979c-be8a649d5189"}
2022-10-17 20:57:03,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Publish async job-955 complete on message bus
2022-10-17 20:57:03,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Wake up jobs related to job-955
2022-10-17 20:57:03,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Update db status for job-955
2022-10-17 20:57:03,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Wake up jobs joined with job-955 and disjoin all subjobs created from job- 955
2022-10-17 20:57:03,699 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Done executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-955
2022-10-17 20:57:03,699 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-4c0df155 job-955) (logid:917cdd39) Remove job-955 from job monitoring

EXPECTED RESULTS

• Volume snapshot is created and transported to primary storage.

ACTUAL RESULTS

• Volume Snap process can successfully create VM Snapshot, however, when conversion to qcow2 starts the process hangs and times out after 3600 seconds. Checking the logs, it does not ever reach the point in which the snapshot is copied to the snapshots directory on primary storage and it may be taking too long. Currently, the operation is being timeout after 3600 seconds. We increased the wait time from 1800 seconds to 3600 seconds but made no difference, the time out continues to stop at 3600 seconds.
• I was recommended: If you have taken vm snapshot (or volume snapshot on running vms) multiple times, The QCOW2 image might be very big. The whole process (including vm snapshotting and qemu-img convert) might exceed the timeout limit (3600 seconds = 1 hour). But there's not a lot of snaps:

root@HOSTNAME ~ $ virsh snapshot-list i-2-19-VM
 Name                                   Creation Time               State
-----------------------------------------------------------------------------------
 0843e6b1-cb12-495c-8d5f-35c9a3338db7   2022-10-17 18:41:08 +0200   disk-snapshot
 2e77acb7-1be4-4417-858e-a1d0890f44f0   2022-10-17 19:57:03 +0200   disk-snapshot
 68476e2a-aec8-4637-9c4b-2dc49d79bd82   2022-10-18 09:44:21 +0200   disk-snapshot
 c110058b-4661-42c0-b648-a54f4ba4beb7   2022-10-17 22:34:21 +0200   disk-snapshot
 i-2-19-VM_VS_20221018072924            2022-10-18 09:29:25 +0200   running

root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ du * -sh
48G    340cc676-4683-4424-beb7-8b33a5cb3dfe
42G    4a56546f-4f63-41c2-a314-27619fe5c2dc
15G    635fd5b5-bf14-4cf4-979c-be8a649d5189
21G    70ffef79-3aad-43ab-93d1-153fcd34ad15
26G    777b5149-50c0-4c0d-944b-873050c85419
20G    867a61e8-4635-40e4-b1b1-c94b2a325b49
4.8G    b21551c6-8276-4e58-841e-4e5a02c0e163
11G    d2c4feca-da5c-44b3-8ecc-40a01fd6c243
40G    f50c0bca-3ae2-48ee-aa9d-0e2d4ec6ba92
24G    f9336d09-0b3d-42d8-9a24-883b022b6712
8.9G    f962cb2c-e03b-4ed2-a035-1870a367aa46
47G    fd573618-885e-48c7-86e6-b019e2311d76
8.0K    KVMHA
15G    snapshots
root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ 

I have started this matter via the email newsletter "Recurring Snaps Failing", and we have tested multiple solutions with no fix in sight.

[nvazquez]

This might need to increase the timeout for the create snapshot command, but needs investigation on which is the correct configuration value to increase, initially 'wait' was proposed but had no effect

[weizhouapache]

@whitetiger264
as we have discussed, it looks "qemu-img convert" takes too long time, which exceeds 3600 seconds (1 hour).
There is no way to speed it up, as far as I know, unless you use faster cpu/memory and disk.

I think the only way to avoid the issue, is to increase the timeout.

I have suggested you to change backup.snapshot.wait, which you replied it does not work for you.
However it works in my testing. For example, when I change it to 3700, the wait of CopyCommand is 3700.

[whitetiger264]

@weizhouapache Sorry, I think there was a misunderstanding, the default value for backup.snapshot.wait is currently set to 21600 seconds, which is 6 hours. I do not think making it anymore would help with the timeout time as it continues to end at 3600 seconds, regardless.

[whitetiger264]

What also puzzles me, is that there is one VM that works perfectly fine. The rest of my other VMs fails when making a volume snapshot while online.

For some reason ONLY this VM works fine:

root@HOSTNAME ~ $ virsh snapshot-list i-2-28-VM
 Name                                   Creation Time               State
-----------------------------------------------------------------------------------
 49197cd4-14e6-4507-9721-a47845f62df2   2022-10-17 21:58:15 +0200   disk-snapshot

root@HOSTNAME ~ $ 

root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ virsh domblklist i-2-28-VM
 Target   Source
------------------------------------------------------------------------------------------
 hda      /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/d17e1814-84c1-4526-946e-76486d8dc654
 hdc      -

root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ du * -sh
48G	340cc676-4683-4424-beb7-8b33a5cb3dfe
42G	4a56546f-4f63-41c2-a314-27619fe5c2dc
12G	635fd5b5-bf14-4cf4-979c-be8a649d5189
21G	70ffef79-3aad-43ab-93d1-153fcd34ad15
26G	777b5149-50c0-4c0d-944b-873050c85419
20G	867a61e8-4635-40e4-b1b1-c94b2a325b49
4.8G	b21551c6-8276-4e58-841e-4e5a02c0e163
5.9M	d17e1814-84c1-4526-946e-76486d8dc654
11G	d2c4feca-da5c-44b3-8ecc-40a01fd6c243
40G	f50c0bca-3ae2-48ee-aa9d-0e2d4ec6ba92
24G	f9336d09-0b3d-42d8-9a24-883b022b6712
8.9G	f962cb2c-e03b-4ed2-a035-1870a367aa46
47G	fd573618-885e-48c7-86e6-b019e2311d76
8.0K	KVMHA
666M	snapshots
root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ 

Here we can see it was successful:

• https://tinyurl.com/2ksrvbaf

But for ALL other VMs I have, they seem to all fail but this one. And they are all from the same template, same CPU, same RAM and same disk. Just different hostnames hosting different domain names.

It makes no sense why this one VM works perfect but the rest are failing. Here are some images of a working VM and a non-working VM:

• Working VM: https://tinyurl.com/2pnavpdf
• Same VM with same specs but not working: https://tinyurl.com/2kfhro6y

[whitetiger264]

Here's the agent.log for the successful volume snapshot for this one VM:

2022-10-18 20:12:04,515 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:12:04,515 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,536 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,546 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:2b718228) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:12:04,556 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,577 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,597 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,617 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,626 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,634 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,656 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:04,665 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:e6b6cd8e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:21,094 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:21,107 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:12:21,107 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:12:21,114 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:12:21,135 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:12:21,135 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:12:42,073 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:12:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:12:42,194 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:12:42,194 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:42,213 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1589:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:12:42,285 DEBUG [cloud.agent.Agent] (Agent-Handler-5:null) (logid:b59cc776) Received response: Seq 1-1589:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:12:54,473 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-3:null) (logid:5af967f1) Copied volumeTO[uuid=b21551c6-8276-4e58-841e-4e5a02c0e163|path=b21551c6-8276-4e58-841e-4e5a02c0e163|datastore=PrimaryDataStoreTO[uuid=81ffca3a-9775-375d-a1c0-9504c0ec3d89|name=Primary|id=2|pooltype=NetworkFilesystem]] snapshot from [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/b21551c6-8276-4e58-841e-4e5a02c0e163] to [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654].
2022-10-18 20:12:54,473 DEBUG [resource.wrapper.LibvirtUtilitiesHelper] (agentRequest-Handler-3:null) (logid:5af967f1) The current Libvirt's version [8000000] supports the flag '--delete' on command 'virsh blockcommit'.
2022-10-18 20:12:54,473 DEBUG [utils.script.Script] (agentRequest-Handler-3:null) (logid:5af967f1) Executing: /bin/bash -c virsh blockcommit i-2-28-VM hda --base /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/b21551c6-8276-4e58-841e-4e5a02c0e163 --active --wait --delete --pivot 
2022-10-18 20:12:54,474 DEBUG [utils.script.Script] (agentRequest-Handler-3:null) (logid:5af967f1) Executing while with timeout : 3600000
2022-10-18 20:12:56,843 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:8da874d3) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:12:56,843 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8da874d3) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:12:56,843 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:8da874d3) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:56,856 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8da874d3) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:12:56,858 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8da874d3) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402666496 Available: (1,6795 TB) 1846644981760
2022-10-18 20:12:56,946 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:8da874d3) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:12:56,946 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8da874d3) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:12:56,946 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:8da874d3) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:56,959 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8da874d3) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:12:57,087 DEBUG [utils.script.Script] (agentRequest-Handler-3:null) (logid:5af967f1) Execution is successful.
2022-10-18 20:12:57,087 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-3:null) (logid:5af967f1) Successfully merged snapshot [d17e1814-84c1-4526-946e-76486d8dc654] into VM [i-2-28-VM] volumeTO[uuid=b21551c6-8276-4e58-841e-4e5a02c0e163|path=b21551c6-8276-4e58-841e-4e5a02c0e163|datastore=PrimaryDataStoreTO[uuid=81ffca3a-9775-375d-a1c0-9504c0ec3d89|name=Primary|id=2|pooltype=NetworkFilesystem]] base file.
2022-10-18 20:12:57,087 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-3:null) (logid:5af967f1) The current Libvirt's version supports the flag '--delete' on command 'virsh blockcommit', we will skip the manually deletion of the unused snapshot file [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/d17e1814-84c1-4526-946e-76486d8dc654] as it already was automatically deleted.
2022-10-18 20:12:57,088 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:5af967f1) Seq 1-1590615093391918180:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
  2022-10-18 20:12:57,227 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:5af967f1) Request:Seq 1-1590615093391918295:  { Cmd , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654","volume":{"uuid":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"name":"ROOT-28","size":"(60,00 GB) 64424509440","path":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeId":"35","vmName":"i-2-28-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"35","deviceId":"0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"vmName":"i-2-28-VM","name":"Confidente_test001","hypervisorType":"KVM","id":"36","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/35","volume":{"uuid":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"name":"ROOT-28","size":"(60,00 GB) 64424509440","path":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeId":"35","vmName":"i-2-28-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"35","deviceId":"0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://MANAGEMENTHOSTIP/mnt/secondary","_role":"Image"}},"vmName":"i-2-28-VM","name":"Confidente_test001","hypervisorType":"KVM","id":"36","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"true"},"options2":{},"wait":"21600","bypassHostMaintenance":"false"}}] }
2022-10-18 20:12:57,227 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null) (logid:5af967f1) Processing command: org.apache.cloudstack.storage.command.CopyCommand
2022-10-18 20:12:57,227 DEBUG [storage.resource.StorageSubsystemCommandHandlerBase] (agentRequest-Handler-5:null) (logid:5af967f1) Executing command CopyCommand: [{"srcTO":{"path":"/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654","volume":{"uuid":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeType":"ROOT","dataStore":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":2,"poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":2049,"url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE\u003dPrimary\u0026STOREUUID\u003d81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":false},"name":"ROOT-28","size":64424509440,"path":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeId":35,"vmName":"i-2-28-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","poolId":2,"id":35,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM","directDownload":false,"deployAsIs":false},"dataStore":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":2,"poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":2049,"url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE\u003dPrimary\u0026STOREUUID\u003d81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":false},"vmName":"i-2-28-VM","name":"Confidente_test001","hypervisorType":"KVM","id":36,"quiescevm":false,"physicalSize":0},"destTO":{"path":"snapshots/2/35","volume":{"uuid":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeType":"ROOT","dataStore":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":2,"poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":2049,"url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE\u003dPrimary\u0026STOREUUID\u003d81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":false},"name":"ROOT-28","size":64424509440,"path":"b21551c6-8276-4e58-841e-4e5a02c0e163","volumeId":35,"vmName":"i-2-28-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","poolId":2,"id":35,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM","directDownload":false,"deployAsIs":false},"dataStore":{"_url":"nfs://MANAGEMENTHOSTIP/mnt/secondary","_role":"Image"},"vmName":"i-2-28-VM","name":"Confidente_test001","hypervisorType":"KVM","id":36,"quiescevm":false,"physicalSize":0},"executeInSequence":false,"options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"true"},"options2":{},"contextMap":{"logid":"5af967f1","job":"job-1000/job-1001"},"wait":21600,"bypassHostMaintenance":false}].
2022-10-18 20:12:57,227 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:5af967f1) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:57,240 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Attempting to create storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b (NetworkFilesystem) in libvirt
2022-10-18 20:12:57,240 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:5af967f1) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:57,253 WARN  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b was not found running in libvirt. Need to create it.
2022-10-18 20:12:57,253 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Didn't find an existing storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b by UUID, checking for pools with duplicate paths
2022-10-18 20:12:57,735 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Checking path of existing pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 against pool we want to create
2022-10-18 20:12:57,736 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8da874d3) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (355,81 GB) 382049714176 Available: (515,05 GB) 553031565312
2022-10-18 20:12:57,736 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Checking path of existing pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 against pool we want to create
2022-10-18 20:12:57,737 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Attempting to create storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b
2022-10-18 20:12:57,737 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) <pool type='netfs'>
<name>6ff3840c-b5c3-3355-8a93-5b9d5c44901b</name>
<uuid>6ff3840c-b5c3-3355-8a93-5b9d5c44901b</uuid>
<source>
<host name='MANAGEMENTHOSTIP'/>
<dir path='/mnt/secondary'/>
</source>
<target>
<path>/mnt/6ff3840c-b5c3-3355-8a93-5b9d5c44901b</path>
</target>
</pool>

2022-10-18 20:12:57,737 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) (logid:5af967f1) Executing: /bin/bash -c mountpoint -q /mnt/6ff3840c-b5c3-3355-8a93-5b9d5c44901b 
2022-10-18 20:12:57,738 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) (logid:5af967f1) Executing while with timeout : 3600000
2022-10-18 20:12:57,741 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) (logid:5af967f1) Exit value is 1
2022-10-18 20:12:57,742 DEBUG [utils.script.Script] (agentRequest-Handler-5:null) (logid:5af967f1) 1
2022-10-18 20:12:57,812 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Trying to fetch storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b from libvirt
2022-10-18 20:12:57,812 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:5af967f1) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:57,815 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Successfully refreshed pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b Capacity: (870,86 GB) 935081279488 Used: (355,81 GB) 382049714176 Available: (515,05 GB) 553031565312
2022-10-18 20:12:57,815 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:12:57,815 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:5af967f1) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:12:57,830 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (355,81 GB) 382049714176 Available: (515,05 GB) 553031565312
2022-10-18 20:12:57,857 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-5:null) (logid:5af967f1) Executing: /usr/share/cloudstack-common/scripts/storage/qcow2/managesnapshot.sh -b /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654 -n d17e1814-84c1-4526-946e-76486d8dc654 -p /mnt/6ff3840c-b5c3-3355-8a93-5b9d5c44901b/snapshots/2/35 -t d17e1814-84c1-4526-946e-76486d8dc654 
2022-10-18 20:12:57,858 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-5:null) (logid:5af967f1) Executing while with timeout : 21600000
2022-10-18 20:13:04,555 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:ad2edd40) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:13:04,756 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:37ed398c) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:13:04,756 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,779 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,801 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,823 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,845 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,866 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,887 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,896 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,917 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:04,926 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:37ed398c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:21,135 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:21,148 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:13:21,148 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:13:21,149 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:13:21,387 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:13:21,387 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:13:42,073 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:13:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:13:42,207 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:13:42,207 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:42,226 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1590:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:13:42,277 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1590:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:13:57,820 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:9012cb2c) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:13:57,820 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:9012cb2c) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:13:57,820 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:9012cb2c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:57,835 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:9012cb2c) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:13:57,837 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:9012cb2c) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402703360 Available: (1,6795 TB) 1846644944896
2022-10-18 20:13:57,932 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:9012cb2c) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:13:57,932 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:9012cb2c) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:13:57,932 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:9012cb2c) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:13:57,946 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:9012cb2c) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:14:04,574 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:28aca9fd) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:14:05,028 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:af4d41c4) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:14:05,028 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,048 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,070 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,091 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,101 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,122 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,144 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,153 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,163 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:05,172 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:af4d41c4) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:10,249 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:9012cb2c) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (356,51 GB) 382798397440 Available: (514,35 GB) 552282882048
2022-10-18 20:14:21,387 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:21,400 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:14:21,400 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:14:21,401 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:14:21,930 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:14:21,930 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:14:42,073 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:14:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:14:42,202 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:14:42,202 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:14:42,223 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1591:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:14:42,266 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1591:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:15:04,634 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:a77d7b60) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:15:05,281 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:5321060e) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:15:05,281 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,302 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,324 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,345 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,355 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,375 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,397 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,419 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,429 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:05,439 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:5321060e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:10,335 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:c76bb337) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:15:10,335 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:c76bb337) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:15:10,335 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:c76bb337) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:10,349 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:c76bb337) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:15:10,350 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:c76bb337) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402723840 Available: (1,6795 TB) 1846644924416
2022-10-18 20:15:10,405 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:c76bb337) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:15:10,405 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:c76bb337) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:15:10,405 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:c76bb337) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:10,419 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:c76bb337) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:15:20,253 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:c76bb337) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (357,19 GB) 383527157760 Available: (513,67 GB) 551554121728
2022-10-18 20:15:21,930 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:21,943 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:15:21,943 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:15:21,944 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:15:22,506 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:15:22,506 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:15:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:15:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:15:42,199 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:15:42,199 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:15:42,219 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1592:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:15:42,260 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1592:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:16:04,692 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:ee561336) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:16:07,734 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:11593dfb) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:16:07,734 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,755 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,776 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,797 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,818 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,827 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,836 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,857 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,877 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:07,886 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:11593dfb) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:20,384 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:582cef47) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:16:20,384 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:582cef47) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:16:20,384 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:582cef47) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:20,398 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:582cef47) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:16:20,399 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:582cef47) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402756608 Available: (1,6795 TB) 1846644891648
2022-10-18 20:16:20,455 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:582cef47) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:16:20,455 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:582cef47) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:16:20,455 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:582cef47) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:20,457 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:582cef47) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:16:22,506 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:32,834 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:16:32,834 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:16:32,835 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:582cef47) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (357,90 GB) 384290521088 Available: (512,96 GB) 550790758400
2022-10-18 20:16:32,835 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:16:33,315 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:16:33,316 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:16:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:16:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:16:42,195 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:16:42,195 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:16:42,214 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1593:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:16:42,250 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1593:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:17:04,748 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:d8b75b0f) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:17:07,984 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:54100322) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:17:07,985 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,005 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,027 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,048 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,070 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,080 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,090 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,114 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,135 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:08,157 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:54100322) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:32,979 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:8d052b63) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:17:32,979 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8d052b63) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:17:32,979 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:8d052b63) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:32,992 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8d052b63) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:17:32,993 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:8d052b63) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402772992 Available: (1,6795 TB) 1846644875264
2022-10-18 20:17:33,051 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:8d052b63) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:17:33,051 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8d052b63) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:17:33,051 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:8d052b63) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:33,065 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8d052b63) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:17:33,316 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:40,359 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:17:40,359 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:17:40,360 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:8d052b63) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (358,56 GB) 385002504192 Available: (512,30 GB) 550078775296
2022-10-18 20:17:40,360 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:17:40,815 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:17:40,816 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:17:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:17:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:17:42,198 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:17:42,198 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:17:42,217 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1594:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:17:42,258 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1594:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:18:04,803 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:63303b0b) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:18:08,257 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:18:08,257 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,279 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,287 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,308 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,316 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,325 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,345 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,354 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,374 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:08,383 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:0f2b3e7e) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:40,492 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:7b99468f) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:18:40,492 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:7b99468f) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:18:40,492 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:7b99468f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:40,506 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:7b99468f) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:18:40,507 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:7b99468f) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402797568 Available: (1,6795 TB) 1846644850688
2022-10-18 20:18:40,565 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:7b99468f) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:18:40,565 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:7b99468f) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:18:40,565 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:7b99468f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:40,579 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:7b99468f) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:18:40,816 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:18:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:18:42,194 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:18:42,194 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:18:42,215 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1595:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:18:42,296 DEBUG [cloud.agent.Agent] (Agent-Handler-2:null) (logid:a8c0b95d) Received response: Seq 1-1595:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:18:49,154 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:18:49,154 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:18:49,154 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:7b99468f) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,24 GB) 385731264512 Available: (511,62 GB) 549350014976
2022-10-18 20:18:49,155 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:18:49,699 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:18:49,700 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:19:04,860 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:0f67a2e7) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:19:08,483 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:26fb333f) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:19:08,483 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,505 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,526 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,535 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,544 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,564 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,579 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,602 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,610 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:08,619 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:26fb333f) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:40,499 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:f0185ee6) Request:Seq 1-1590615093391918320:  { Cmd , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.GetRouterMonitorResultsCommand":{"performFreshChecks":"false","validateBasicTestsOnly":"true","accessDetails":{"router.ip":"169.254.158.98","router.name":"r-32-VM"},"wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:40,499 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:f0185ee6) Processing command: com.cloud.agent.api.routing.GetRouterMonitorResultsCommand
2022-10-18 20:19:40,499 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f0185ee6) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh filesystem_writable_check.py 169.254.158.98 
2022-10-18 20:19:40,500 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f0185ee6) Executing while with timeout : 1800000
2022-10-18 20:19:40,701 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f0185ee6) Execution is successful.
2022-10-18 20:19:40,701 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:f0185ee6) Executing script in VR: filesystem_writable_check.py
2022-10-18 20:19:40,701 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-1:null) (logid:f0185ee6) Router connectivity and file system writable check passed
2022-10-18 20:19:40,702 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:f0185ee6) Seq 1-1590615093391918320:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GetRouterMonitorResultsAnswer":{"monitoringResults":"success","result":"true","details":"success","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:40,749 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:f0185ee6) Request:Seq 1-1590615093391918321:  { Cmd , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SetMonitorServiceCommand":{"healthChecksConfig":{"gateways":"gatewaysIps=41.72.146.241 169.254.0.1 ","portForwarding":"","systemThresholds":"minDiskNeeded=100.0,maxCpuUsage=100.0,maxMemoryUsage=100.0;","haproxyData":"","virtualMachines":"vmName=RocketChat,macAddress=1e:00:e7:00:00:03,ip=41.72.146.244,dhcp=true,dns=true;vmName=HMA,macAddress=1e:00:4a:00:00:05,ip=41.72.146.246,dhcp=true,dns=true;vmName=Mabaruli,macAddress=1e:00:38:00:00:06,ip=41.72.146.247,dhcp=true,dns=true;vmName=Confidente,macAddress=1e:00:f1:00:00:07,ip=41.72.146.248,dhcp=true,dns=true;vmName=NAMFISA,macAddress=1e:00:f0:00:00:08,ip=41.72.146.249,dhcp=true,dns=true;vmName=CKNam,macAddress=1e:00:66:00:00:0a,ip=41.72.146.251,dhcp=true,dns=true;vmName=SSConsultings,macAddress=1e:00:59:00:00:04,ip=41.72.146.245,dhcp=true,dns=true;vmName=Benade,macAddress=1e:00:84:00:00:0b,ip=41.72.146.252,dhcp=true,dns=true;vmName=RTC,macAddress=1e:00:ca:00:00:0c,ip=41.72.146.253,dhcp=true,dns=true;vmName=Nacdo,macAddress=1e:00:9b:00:00:0d,ip=41.72.146.254,dhcp=true,dns=true;","routerVersion":"templateVersion=Cloudstack Release 4.17.0 Mon 02 May 2022 04:00:10 PM UTC,scriptsVersion=45795a9522a88a70d2640809db5ba452
"},"reconfigureAfterUpdate":"true","deleteFromProcessedCache":"true","accessDetails":{"router.health.checks.enabled":"true","router.ip":"169.254.158.98","router.name":"r-32-VM","router.health.checks.advanced.interval":"10","router.health.checks.basic.interval":"3","router.health.checks.excluded":""},"wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:40,749 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:f0185ee6) Processing command: com.cloud.agent.api.routing.SetMonitorServiceCommand
2022-10-18 20:19:40,749 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Transforming com.cloud.agent.api.routing.SetMonitorServiceCommand to ConfigItems
2022-10-18 20:19:40,749 DEBUG [virtualnetwork.facade.AbstractConfigItemFacade] (agentRequest-Handler-2:null) (logid:f0185ee6) Transformed filename: monitor_service.json to: monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93
2022-10-18 20:19:40,749 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Creating file in VR, with ip: 169.254.158.98, file: monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93
2022-10-18 20:19:40,983 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Processing FileConfigItem, copying 1353 characters to monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93 took 234ms
2022-10-18 20:19:40,984 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh update_config.py 169.254.158.98 monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93 false 
2022-10-18 20:19:40,985 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing while with timeout : 600000
2022-10-18 20:19:41,453 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Execution is successful.
2022-10-18 20:19:41,453 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing script in VR: update_config.py
2022-10-18 20:19:41,453 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Processing ScriptConfigItem, executing update_config.py monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93 false took 469ms
2022-10-18 20:19:41,453 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh configure.py 169.254.158.98 monitor_service.json 
2022-10-18 20:19:41,454 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing while with timeout : 600000
2022-10-18 20:19:41,762 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Execution is successful.
2022-10-18 20:19:41,762 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Executing script in VR: configure.py
2022-10-18 20:19:41,762 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Processing ScriptConfigItem, executing configure.py monitor_service.json took 309ms
2022-10-18 20:19:41,762 WARN  [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-2:null) (logid:f0185ee6) Expected 1 answers while executing SetMonitorServiceCommand but received 3
2022-10-18 20:19:41,763 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:f0185ee6) Seq 1-1590615093391918321:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GroupAnswer":{"results":["null - success: Creating file in VR, with ip: 169.254.158.98, file: monitor_service.json.7d87d541-deef-42c7-96bf-b8f04ff95a93","null - success: ","null - success: "],"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:41,819 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:667daea7) Request:Seq 1-1590615093391918322:  { Cmd , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.GetRouterMonitorResultsCommand":{"performFreshChecks":"false","validateBasicTestsOnly":"false","accessDetails":{"router.ip":"169.254.158.98","router.name":"r-32-VM"},"wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:41,819 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:667daea7) Processing command: com.cloud.agent.api.routing.GetRouterMonitorResultsCommand
2022-10-18 20:19:41,819 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh filesystem_writable_check.py 169.254.158.98 
2022-10-18 20:19:41,820 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing while with timeout : 1800000
2022-10-18 20:19:41,957 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Execution is successful.
2022-10-18 20:19:41,957 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing script in VR: filesystem_writable_check.py
2022-10-18 20:19:41,957 DEBUG [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-3:null) (logid:667daea7) Router connectivity and file system writable check passed
2022-10-18 20:19:41,957 INFO  [resource.virtualnetwork.VirtualRoutingResource] (agentRequest-Handler-3:null) (logid:667daea7) Fetching health check result for 169.254.158.98 and executing fresh checks: false
2022-10-18 20:19:41,957 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing: /usr/share/cloudstack-common/scripts/network/domr/router_proxy.sh getRouterMonitorResults.sh 169.254.158.98 false 
2022-10-18 20:19:41,958 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing while with timeout : 1800000
2022-10-18 20:19:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:19:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:19:42,084 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Execution is successful.
2022-10-18 20:19:42,084 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-3:null) (logid:667daea7) Executing script in VR: getRouterMonitorResults.sh
2022-10-18 20:19:42,086 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:667daea7) Seq 1-1590615093391918322:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.routing.GetRouterMonitorResultsAnswer":{"failingChecks":[],"monitoringResults":"{"basic":{"lastRun": {"duration": "11.4090528488", "start": "2022-10-18 18:18:01.684931", "end": "2022-10-18 18:18:13.093984"}, "disk_space_check.py": {"lastRunDuration": "15.7380104065", "lastUpdate": "1666117093042", "message": "Sufficient free space is 2019 MB", "success": "true"}, "memory_usage_check.py": {"lastRunDuration": "27.8658866882", "lastUpdate": "1666117092998", "message": "Memory Usage within limits with current at 30.9631%", "success": "true"}, "ssh.service": {"lastRunDuration": "15.6829357147", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}, "dhcp.service": {"lastRunDuration": "7.36212730408", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}, "gateways_check.py": {"lastRunDuration": "8044.89517212", "lastUpdate": "1666117084953", "message": "All 2 gateways are reachable via ping", "success": "true"}, "cpu_usage_check.py": {"lastRunDuration": "3203.67717743", "lastUpdate": "1666117081749", "message": "CPU Usage within limits with current at 0.3%", "success": "true"}, "router_version_check.py": {"lastRunDuration": "16.2389278412", "lastUpdate": "1666117093077", "message": "Template and scripts version match successful", "success": "true"}, "webserver.service": {"lastRunDuration": "11.5239620209", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}},"advanced":{"lastRun": {"duration": "0.173095941544", "start": "2022-10-18 18:10:01.507455", "end": "2022-10-18 18:10:01.680551"}, "haproxy_check.py": {"lastRunDuration": "16.4968967438", "lastUpdate": "1666116601538", "message": "No data provided to check, skipping", "success": "true"}, "dhcp_check.py": {"lastRunDuration": "16.9341564178", "lastUpdate": "1666116601508", "message": "All 10 VMs are present in dhcphosts.txt", "success": "true"}, "dns_check.py": {"lastRunDuration": "15.9339904785", "lastUpdate": "1666116601613", "message": "All 10 VMs are present in /etc/hosts", "success": "true"}, "iptables_check.py": {"lastRunDuration": "19.2470550537", "lastUpdate": "1666116601645", "message": "No portforwarding rules provided to check, skipping", "success": "true"}}}","result":"true","details":"{"basic":{"lastRun": {"duration": "11.4090528488", "start": "2022-10-18 18:18:01.684931", "end": "2022-10-18 18:18:13.093984"}, "disk_space_check.py": {"lastRunDuration": "15.7380104065", "lastUpdate": "1666117093042", "message": "Sufficient free space is 2019 MB", "success": "true"}, "memory_usage_check.py": {"lastRunDuration": "27.8658866882", "lastUpdate": "1666117092998", "message": "Memory Usage within limits with current at 30.9631%", "success": "true"}, "ssh.service": {"lastRunDuration": "15.6829357147", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}, "dhcp.service": {"lastRunDuration": "7.36212730408", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}, "gateways_check.py": {"lastRunDuration": "8044.89517212", "lastUpdate": "1666117084953", "message": "All 2 gateways are reachable via ping", "success": "true"}, "cpu_usage_check.py": {"lastRunDuration": "3203.67717743", "lastUpdate": "1666117081749", "message": "CPU Usage within limits with current at 0.3%", "success": "true"}, "router_version_check.py": {"lastRunDuration": "16.2389278412", "lastUpdate": "1666117093077", "message": "Template and scripts version match successful", "success": "true"}, "webserver.service": {"lastRunDuration": "11.5239620209", "lastUpdate": "1666117081686", "message": "service is running", "success": "true"}},"advanced":{"lastRun": {"duration": "0.173095941544", "start": "2022-10-18 18:10:01.507455", "end": "2022-10-18 18:10:01.680551"}, "haproxy_check.py": {"lastRunDuration": "16.4968967438", "lastUpdate": "1666116601538", "message": "No data provided to check, skipping", "success": "true"}, "dhcp_check.py": {"lastRunDuration": "16.9341564178", "lastUpdate": "1666116601508", "message": "All 10 VMs are present in dhcphosts.txt", "success": "true"}, "dns_check.py": {"lastRunDuration": "15.9339904785", "lastUpdate": "1666116601613", "message": "All 10 VMs are present in /etc/hosts", "success": "true"}, "iptables_check.py": {"lastRunDuration": "19.2470550537", "lastUpdate": "1666116601645", "message": "No portforwarding rules provided to check, skipping", "success": "true"}}}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:42,195 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:19:42,195 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:42,214 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1596:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:42,299 DEBUG [cloud.agent.Agent] (Agent-Handler-3:null) (logid:a8c0b95d) Received response: Seq 1-1596:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:19:49,288 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:834f7792) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:19:49,288 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:834f7792) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:19:49,288 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:834f7792) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:49,302 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:834f7792) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:19:49,303 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:834f7792) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402985984 Available: (1,6795 TB) 1846644662272
2022-10-18 20:19:49,399 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:834f7792) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:19:49,399 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:834f7792) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:19:49,399 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:834f7792) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:49,412 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:834f7792) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:19:49,700 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,524 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:cd004f6b) Processing command: com.cloud.agent.api.GetVolumeStatsCommand
2022-10-18 20:19:55,524 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,536 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:19:55,536 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,551 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402985984 Available: (1,6795 TB) 1846644662272
2022-10-18 20:19:55,552 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:19:55,552 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,566 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402985984 Available: (1,6795 TB) 1846644662272
2022-10-18 20:19:55,568 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:19:55,568 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,570 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:cd004f6b) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6402985984 Available: (1,6795 TB) 1846644662272
2022-10-18 20:19:55,625 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:cd004f6b) Processing command: com.cloud.agent.api.GetVolumeStatsCommand
2022-10-18 20:19:55,625 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:55,638 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:19:55,638 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:19:59,296 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:19:59,297 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:19:59,297 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:834f7792) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:19:59,297 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:19:59,298 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:19:59,761 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:19:59,761 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:20:00,310 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:00,310 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:00,325 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:01,690 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:01,690 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:01,705 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:04,876 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:0f4c2a79) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:20:05,142 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:05,142 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:05,156 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:08,038 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:08,038 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,052 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:08,715 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Processing command: com.cloud.agent.api.GetVmStatsCommand
2022-10-18 20:20:08,715 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,737 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,745 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,767 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,789 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,810 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,819 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,842 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,850 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:08,872 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:a7d8ff1a) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:11,014 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:11,014 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:11,028 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:12,946 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:12,947 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:12,961 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:15,153 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:15,153 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:15,167 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:17,449 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:17,449 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:17,464 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:21,103 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:20:21,103 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:cd004f6b) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:21,117 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:cd004f6b) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,93 GB) 386472607744 Available: (510,93 GB) 548608671744
2022-10-18 20:20:42,074 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-18 20:20:42,075 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-18 20:20:42,204 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.
2022-10-18 20:20:42,204 DEBUG [kvm.resource.LibvirtConnection] (UgentTask-5:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:42,224 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-1597:  { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{"i-2-38-VM":["38","3"],"i-2-37-VM":["37","3"],"i-2-27-VM":["27","9"],"i-2-23-VM":["23","12"],"i-2-19-VM":["19","11"],"i-2-31-VM":["31","6"],"i-2-35-VM":["35","5"],"i-2-29-VM":["29","6"],"i-2-36-VM":["36","3"],"i-2-28-VM":["28","8"]},"_hostVmStateReport":{"s-43-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-27-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-23-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-19-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-31-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-35-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-36-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-38-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-37-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"r-32-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-29-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"i-2-28-VM":{"state":"PowerOn","host":"KVMHOSTNAME"},"v-11-VM":{"state":"PowerOn","host":"KVMHOSTNAME"}},"_gatewayAccessible":"true","_vnetAccessible":"true","hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:20:42,268 DEBUG [cloud.agent.Agent] (Agent-Handler-4:null) (logid:b59cc776) Received response: Seq 1-1597:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":"1","wait":"0","bypassHostMaintenance":"false"},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-18 20:20:59,403 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:df16d286) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:20:59,403 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:df16d286) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-18 20:20:59,403 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:df16d286) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:59,417 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:df16d286) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-18 20:20:59,418 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:df16d286) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,96 GB) 6403018752 Available: (1,6795 TB) 1846644629504
2022-10-18 20:20:59,761 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:20:59,774 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-18 20:20:59,774 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-18 20:20:59,775 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-18 20:20:59,813 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-18 20:20:59,813 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-18 20:21:01,116 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:df16d286) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-18 20:21:01,116 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:df16d286) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-18 20:21:01,116 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:df16d286) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:21:01,130 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:df16d286) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-18 20:21:04,894 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:08cebab6) Processing command: com.cloud.agent.api.GetHostStatsCommand
2022-10-18 20:21:06,498 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-5:null) (logid:5af967f1) Execution is successful.
2022-10-18 20:21:06,582 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:df16d286) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (355,81 GB) 382049714176 Available: (515,05 GB) 553031565312
2022-10-18 20:21:07,047 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Attempting to remove storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b from libvirt
2022-10-18 20:21:07,047 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-5:null) (logid:5af967f1) Looking for libvirtd connection at: qemu:///system
2022-10-18 20:21:07,060 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b has no corresponding secret. Not removing any secret.
2022-10-18 20:21:07,104 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:5af967f1) Storage pool 6ff3840c-b5c3-3355-8a93-5b9d5c44901b was successfully removed from libvirt.

[weizhouapache]

@whitetiger264
From agent.log , it looks everything is ok . The wait in CopyCommand is 21600, and the script timeout is also 21600. If you check the snap directory on secondary storage, you may find the snapshots in snapshots/2/35

2022-10-18 20:12:57,857 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-5:null) (logid:5af967f1) Executing: /usr/share/cloudstack-common/scripts/storage/qcow2/managesnapshot.sh -b /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/d17e1814-84c1-4526-946e-76486d8dc654 -n d17e1814-84c1-4526-946e-76486d8dc654 -p /mnt/6ff3840c-b5c3-3355-8a93-5b9d5c44901b/snapshots/2/35 -t d17e1814-84c1-4526-946e-76486d8dc654 
2022-10-18 20:12:57,858 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-5:null) (logid:5af967f1) Executing while with timeout : 21600000

I agree with @nvazquez that the timeout 3600 is twice of wait in global configuration. I notice you have increased it from 1800 to 3600. Please restart cloudstack-management service and retry manually.

[whitetiger264]

@weizhouapache

I have already increased wait from 1800 to 3600 and restarted cloudstack-management service and when I ran the volume snapshot, it still fails and times out at 3600 seconds, regardless. So the wait setting made no difference, unfortunately.

[slavkap]

Hello everyone,

@whitetiger264, can you share everything from the agent.log that contains logid:917cdd39 from 2022-10-17? The snapshot copy

from [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/635fd5b5-bf14-4cf4-979c-be8a649d5189] to [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/2e77acb7-1be4-4417-858e-a1d0890f44f0]

took a lot of time, and the CS mgmt timeout 2 minutes before the CS agent finished the coping

[whitetiger264]

Hi @slavkap here you go:

2022-10-17 19:57:03,622 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:917cdd39) Request:Seq 1-8475211548757852179:  { Cmd , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"name":"ROOT-19","size":"(50,00 GB) 53687091200","path":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeId":"24","vmName":"i-2-19-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"2","id":"24","deviceId":"0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":"2","poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":"2049","url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE=Primary&STOREUUID=81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":"false"}},"vmName":"i-2-19-VM","name":"Test006","hypervisorType":"KVM","id":"27","quiescevm":"false","physicalSize":"0"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-17 19:57:03,623 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:917cdd39) Processing command: org.apache.cloudstack.storage.command.CreateObjectCommand
2022-10-17 19:57:03,623 DEBUG [storage.resource.StorageSubsystemCommandHandlerBase] (agentRequest-Handler-2:null) (logid:917cdd39) Executing command CreateObjectCommand: [{"data":{"volume":{"uuid":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeType":"ROOT","dataStore":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":2,"poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":2049,"url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE\u003dPrimary\u0026STOREUUID\u003d81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":false},"name":"ROOT-19","size":53687091200,"path":"635fd5b5-bf14-4cf4-979c-be8a649d5189","volumeId":24,"vmName":"i-2-19-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","poolId":2,"id":24,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM","directDownload":false,"deployAsIs":false},"dataStore":{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","name":"Primary","id":2,"poolType":"NetworkFilesystem","host":"MANAGEMENTHOSTIP","path":"/mnt/primary","port":2049,"url":"NetworkFilesystem://MANAGEMENTHOSTIP/mnt/primary/?ROLE\u003dPrimary\u0026STOREUUID\u003d81ffca3a-9775-375d-a1c0-9504c0ec3d89","isManaged":false},"vmName":"i-2-19-VM","name":"Test006","hypervisorType":"KVM","id":27,"quiescevm":false,"physicalSize":0},"contextMap":{"logid":"917cdd39","job":"job-955/job-956"},"wait":0,"bypassHostMaintenance":false}].
2022-10-17 19:57:03,623 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:917cdd39) Looking for libvirtd connection at: qemu:///system
2022-10-17 19:57:03,636 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:917cdd39) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-17 19:57:03,636 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:917cdd39) Looking for libvirtd connection at: qemu:///system
2022-10-17 19:57:03,651 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:917cdd39) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (347,48 GB) 373108506624 Available: (523,38 GB) 561972772864
2022-10-17 19:57:03,651 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:917cdd39) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-17 19:57:03,651 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:917cdd39) Looking for libvirtd connection at: qemu:///system
2022-10-17 19:57:03,666 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:917cdd39) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (347,48 GB) 373108506624 Available: (523,38 GB) 561972772864
2022-10-17 19:57:03,694 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-2:null) (logid:917cdd39) Pool [{"uuid":"81ffca3a-9775-375d-a1c0-9504c0ec3d89","localPath":"\/mnt\/81ffca3a-9775-375d-a1c0-9504c0ec3d89"}] has enough available size [561972772864] to take volume [{"name":"635fd5b5-bf14-4cf4-979c-be8a649d5189","path":"\/mnt\/81ffca3a-9775-375d-a1c0-9504c0ec3d89\/635fd5b5-bf14-4cf4-979c-be8a649d5189","size":12770979840}] snapshot.
2022-10-17 19:57:03,862 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-2:null) (logid:917cdd39) Snapshot [2e77acb7-1be4-4417-858e-a1d0890f44f0] took [0] seconds to finish.
2022-10-17 19:57:16,568 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-17 19:57:16,581 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-17 19:57:16,581 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-17 19:57:16,582 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-17 19:57:16,609 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.



2022-10-17 20:59:18,347 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-2:null) (logid:917cdd39) Copied volumeTO[uuid=635fd5b5-bf14-4cf4-979c-be8a649d5189|path=635fd5b5-bf14-4cf4-979c-be8a649d5189|datastore=PrimaryDataStoreTO[uuid=81ffca3a-9775-375d-a1c0-9504c0ec3d89|name=Primary|id=2|pooltype=NetworkFilesystem]] snapshot from [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/635fd5b5-bf14-4cf4-979c-be8a649d5189] to [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/2e77acb7-1be4-4417-858e-a1d0890f44f0].
2022-10-17 20:59:18,347 DEBUG [resource.wrapper.LibvirtUtilitiesHelper] (agentRequest-Handler-2:null) (logid:917cdd39) The current Libvirt's version [8000000] supports the flag '--delete' on command 'virsh blockcommit'.
2022-10-17 20:59:18,347 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:917cdd39) Executing: /bin/bash -c virsh blockcommit i-2-19-VM vda --base /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/635fd5b5-bf14-4cf4-979c-be8a649d5189 --active --wait --delete --pivot 
2022-10-17 20:59:18,348 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:917cdd39) Executing while with timeout : 3600000
2022-10-17 20:59:19,250 DEBUG [kvm.resource.LibvirtConnection] (Thread-1:null) (logid:) Looking for libvirtd connection at: qemu:///system
2022-10-17 20:59:19,263 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Found NFS storage pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89] in libvirt, continuing.
2022-10-17 20:59:19,263 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP 
2022-10-17 20:59:19,264 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Executing while with timeout : 60000
2022-10-17 20:59:19,786 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) Execution is successful.
2022-10-17 20:59:19,786 DEBUG [kvm.resource.KVMHAMonitor] (Thread-1:null) (logid:) The command (/usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh -i MANAGEMENTHOSTIP -p /mnt/primary -m /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 -h KVMHOSTIP ), to the pool [81ffca3a-9775-375d-a1c0-9504c0ec3d89], has the result [null].
2022-10-17 20:59:25,449 DEBUG [utils.script.Script] (agentRequest-Handler-2:null) (logid:917cdd39) Execution is successful.
2022-10-17 20:59:25,449 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-2:null) (logid:917cdd39) Successfully merged snapshot [2e77acb7-1be4-4417-858e-a1d0890f44f0] into VM [i-2-19-VM] volumeTO[uuid=635fd5b5-bf14-4cf4-979c-be8a649d5189|path=635fd5b5-bf14-4cf4-979c-be8a649d5189|datastore=PrimaryDataStoreTO[uuid=81ffca3a-9775-375d-a1c0-9504c0ec3d89|name=Primary|id=2|pooltype=NetworkFilesystem]] base file.
2022-10-17 20:59:25,449 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-2:null) (logid:917cdd39) The current Libvirt's version supports the flag '--delete' on command 'virsh blockcommit', we will skip the manually deletion of the unused snapshot file [/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/2e77acb7-1be4-4417-858e-a1d0890f44f0] as it already was automatically deleted.
2022-10-17 20:59:25,450 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:917cdd39) Seq 1-8475211548757852179:  { Ans: , MgmtId: 2619780474, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/2e77acb7-1be4-4417-858e-a1d0890f44f0","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2022-10-17 20:59:28,398 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:c4d38962) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-17 20:59:28,398 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:c4d38962) Trying to fetch storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 from libvirt
2022-10-17 20:59:28,398 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-4:null) (logid:c4d38962) Looking for libvirtd connection at: qemu:///system
2022-10-17 20:59:28,413 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:c4d38962) Asking libvirt to refresh storage pool ff9a58d8-fb77-49c8-92d1-7c82fc456297
2022-10-17 20:59:28,415 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-4:null) (logid:c4d38962) Successfully refreshed pool ff9a58d8-fb77-49c8-92d1-7c82fc456297 Capacity: (1,6853 TB) 1853047648256 Used: (5,88 GB) 6316314624 Available: (1,6796 TB) 1846731333632
2022-10-17 20:59:28,464 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:c4d38962) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2022-10-17 20:59:28,464 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:c4d38962) Trying to fetch storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 from libvirt
2022-10-17 20:59:28,464 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:c4d38962) Looking for libvirtd connection at: qemu:///system
2022-10-17 20:59:28,478 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:c4d38962) Asking libvirt to refresh storage pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89
2022-10-17 20:59:30,012 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:c4d38962) Successfully refreshed pool 81ffca3a-9775-375d-a1c0-9504c0ec3d89 Capacity: (870,86 GB) 935081279488 Used: (359,39 GB) 385887502336 Available: (511,48 GB) 549193777152
2022-10-17 20:59:37,235 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing: /usr/share/cloudstack-common/scripts/vm/network/security_group.py get_rule_logs_for_vms 
2022-10-17 20:59:37,236 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Executing while with timeout : 1800000
2022-10-17 20:59:37,361 DEBUG [kvm.resource.LibvirtComputingResource] (UgentTask-5:null) (logid:) Execution is successful.

[whitetiger264]

I just realised now why only that one VM is working as expected and the rest are failing. There's no current activity on that VM happening and its volume size seems to be 5.9 MB as shown here:

root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ du * -sh
48G	340cc676-4683-4424-beb7-8b33a5cb3dfe
42G	4a56546f-4f63-41c2-a314-27619fe5c2dc
12G	635fd5b5-bf14-4cf4-979c-be8a649d5189
21G	70ffef79-3aad-43ab-93d1-153fcd34ad15
26G	777b5149-50c0-4c0d-944b-873050c85419
20G	867a61e8-4635-40e4-b1b1-c94b2a325b49
4.8G	b21551c6-8276-4e58-841e-4e5a02c0e163
5.9M	d17e1814-84c1-4526-946e-76486d8dc654
11G	d2c4feca-da5c-44b3-8ecc-40a01fd6c243
40G	f50c0bca-3ae2-48ee-aa9d-0e2d4ec6ba92
24G	f9336d09-0b3d-42d8-9a24-883b022b6712
8.9G	f962cb2c-e03b-4ed2-a035-1870a367aa46
47G	fd573618-885e-48c7-86e6-b019e2311d76
8.0K	KVMHA
666M	snapshots
root@HOSTNAME /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89 $ 

root@HOSTNAME ~ $ virsh snapshot-list i-2-28-VM
 Name                                   Creation Time               State
-----------------------------------------------------------------------------------
 49197cd4-14e6-4507-9721-a47845f62df2   2022-10-17 21:58:15 +0200   disk-snapshot

root@HOSTNAME ~ $ 

I also want to add that my KVM server and Cloudstack Management server are connected via a public network, there's no LAN backlink between the two servers. So it's transferred over the "internet" could this be a factor as to why it's taking too long?

[whitetiger264]

Would it be worth upgrading to 4.17.1.0? Since it fixes a few storage and mount issues?

[whitetiger264]

I cleaned out the snapshot database tables, restarted MySQL, restarted cloudstack-management and tested a new volume snapshot today, and it still failed :(.

• https://tinyurl.com/2yug8exy

Here's a full 1-hour log from agent.log and management-server.log for this attempt:

agent.log: Too long to add here, please download from WeTransfer

• https://we.tl/t-W1ta0AQiCZ

management-server.log: Too long to add here, please download from WeTransfer

• https://we.tl/t-9XaWnPnldQ

I do not know what else needs to be done. I assume I should try upgrading to 4.17.1.0

[slavkap]

@whitetiger264, unfortunately, upgrading will not fix the issue. I've tested with CS 4.18.0.0-SNAPSHOT with a volume around 6G, and the copy took 16mins.

2022-10-19 10:40:45,448 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-1:null) (logid:141fd911) Snapshot [87690418-8d17-4cb5-96d1-de29f209686a] took [0] seconds to finish.
2022-10-19 10:56:09,965 DEBUG [kvm.storage.KVMStorageProcessor] (agentRequest-Handler-1:null) (logid:141fd911) Copied volumeTO[uuid=970c2e54-e52e-4e94-8ece-3bffada02ed6|path=970c2e54-e52e-4e94-8ece-3bffada02ed6|datastore=PrimaryDataStoreTO[uuid=434b557d-e974-3b78-b593-d813b5279b7a|name=nfs|id=7|pooltype=NetworkFilesystem]] snapshot from [/mnt/434b557d-e974-3b78-b593-d813b5279b7a/970c2e54-e52e-4e94-8ece-3bffada02ed6] to [/mnt/434b557d-e974-3b78-b593-d813b5279b7a/snapshots/87690418-8d17-4cb5-96d1-de29f209686a].

I'm not sure why the snapshot is created on the primary at first /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/635fd5b5-bf14-4cf4-979c-be8a649d5189 and then copied again to primary in snapshots directory /mnt/81ffca3a-9775-375d-a1c0-9504c0ec3d89/snapshots/2e77acb7-1be4-4417-858e-a1d0890f44f0