Multiple secondary storage in one zone; problem with volume snapshots

ISSUE TYPE

Bug Report

CLOUDSTACK VERSION

4.19.1.0, xcp-ng hypervisor

SUMMARY

We are planning to add multiple NFS secondary storages for backup purpose. And I don't understand the principle of distribution of storage snapshots among secstors.
I created 10 Intsances in one Account and all their volume snapshots exept one were copied to the first secstore. Only one volume snapshot was copied to the second NFS secstore, but I can't create addiditinal snapshots of this volume. I attach logs in comments.

STEPS TO REPRODUCE

Add multiple NFS secondary storages, try to create volume snapshots of different instances

EXPECTED RESULTS

Snapshots are copied based on free space allocation mode to all secstores

ACTUAL RESULTS

All snapshotes are copied to the first secstore

Example of successful snapshot to the first secstore

2024-09-26 17:21:41,283 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464) (logid:c8e45246) Executing AsyncJobVO: {id:72464, userId: 298, accountId: 225, instanceType: Snapshot, instanceId: 870, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"asyncbackup":"false","response":"json","ctxUserId":"298","volumeid":"5e964ddb-3d14-4037-a241-12972ebc5354","httpmethod":"GET","ctxStartEventId":"1811491","id":"870","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"5e964ddb-3d14-4037-a241-12972ebc5354\",\"interface com.cloud.storage.Snapshot\":\"7bdc207e-974e-41ed-a51f-f104bac1102c\"}","ctxAccountId":"225","uuid":"7bdc207e-974e-41ed-a51f-f104bac1102c","cmdEventType":"SNAPSHOT.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 108597816265214, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2024-09-26 17:21:41,293 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Access to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 17:21:41,304 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-285c7273) (logid:dbfd31f0) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:41,329 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-285c7273 ctx-655df114) (logid:dbfd31f0) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:41,333 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Access to org.apache.cloudstack.storage.volume.VolumeObject@46645c52 granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 17:21:41,341 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Access to VM instance {"id":5474,"instanceName":"i-225-5474-VM","type":"User","uuid":"64c1d590-88a5-4dea-aede-76e0afa0bf32"} granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 17:21:41,350 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Sync job-72465 execution on object VmWorkJobQueue.5474
2024-09-26 17:21:42,578 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465) (logid:c8e45246) Executing AsyncJobVO: {id:72465, userId: 298, accountId: 225, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAAdaAAthc3luY0JhY2t1cFoACXF1aWVzY2VWbUwADGxvY2F0aW9uVHlwZXQAKUxjb20vY2xvdWQvc3RvcmFnZS9TbmFwc2hvdCRMb2NhdGlvblR5cGU7TAAIcG9saWN5SWR0ABBMamF2YS9sYW5nL0xvbmc7TAAKc25hcHNob3RJZHEAfgACTAAIdm9sdW1lSWRxAH4AAkwAB3pvbmVJZHN0ABBMamF2YS91dGlsL0xpc3Q7eHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAOEAAAAAAAABKgAAAAAAABVidAAUVm9sdW1lQXBpU2VydmljZUltcGwAAHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAABzcQB-AAgAAAAAAAADZnNxAH4ACAAAAAAAABgTcA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 108597816265214, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Sep 26 17:21:41 MSK 2024, removed: null}
2024-09-26 17:21:42,579 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465) (logid:c8e45246) Run VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 5474, job origin: 72464
2024-09-26 17:21:42,581 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Execute VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":6163,"policyId":0,"snapshotId":870,"quiesceVm":false,"asyncBackup":false,"userId":298,"accountId":225,"vmId":5474,"handlerName":"VolumeApiServiceImpl"}
2024-09-26 17:21:42,594 DEBUG [o.a.c.s.s.StorPoolSnapshotStrategy] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) StorpoolSnapshotStrategy.canHandle: snapshot=backup-test-karasev-9_ROOT-5474_20240926142141, uuid=7bdc207e-974e-41ed-a51f-f104bac1102c, op=TAKE
2024-09-26 17:21:42,632 DEBUG [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Taking snapshot of org.apache.cloudstack.storage.snapshot.SnapshotObject@4bd9bc84
2024-09-26 17:21:42,666 DEBUG [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Taking snapshot of org.apache.cloudstack.storage.snapshot.SnapshotObject@4bd9bc84 and encryption required is false
2024-09-26 17:21:42,666 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CreateObjectCommand
2024-09-26 17:21:42,667 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) We are returning the default host to execute commands because the command is not of Copy type.
2024-09-26 17:21:42,670 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430185: Sending  { Cmd , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 17:21:42,671 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430185: Executing:  { Cmd , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 17:21:42,672 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase] (DirectAgent-287:ctx-df71784d) (logid:c8e45246) Executing command CreateObjectCommand: [{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":54,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":0,"url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":false}},"name":"ROOT-5474","size":10737418240,"path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":6163,"vmName":"i-225-5474-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":54,"id":6163,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":54,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":0,"url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":false}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":870,"quiescevm":false,"physicalSize":0,"accountId":225,"followRedirects":false}},"wait":0,"bypassHostMaintenance":false}].
2024-09-26 17:21:44,421 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-38b579a2) (logid:2740bef9) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:44,446 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-38b579a2 ctx-9d7b2d8d) (logid:2740bef9) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:47,537 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-eb108eb7) (logid:25800034) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:47,561 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-eb108eb7 ctx-d3852c77) (logid:25800034) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:50,671 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-95e72378) (logid:4e24b10a) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:50,693 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-95e72378 ctx-9321eab1) (logid:4e24b10a) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:53,779 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-581ef07b) (logid:dca0df5b) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:53,811 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-581ef07b ctx-69923e87) (logid:dca0df5b) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:56,898 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-cc466224) (logid:d706fc8d) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:56,926 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-cc466224 ctx-f28715e9) (logid:d706fc8d) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:21:57,319 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-287:ctx-df71784d) (logid:c8e45246) Seq 77360-7409547286931430185: Response Received:
2024-09-26 17:21:57,319 DEBUG [c.c.a.t.Request] (DirectAgent-287:ctx-df71784d) (logid:c8e45246) Seq 77360-7409547286931430185: Processing:  { Ans: , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"d8f3d271-4b1d-4276-b4ea-390c3f82df57","id":"0","quiescevm":"false","physicalSize":"0","accountId":"0","followRedirects":"false"}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 17:21:57,319 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430185: Received:  { Ans: , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 10, { CreateObjectAnswer } }
2024-09-26 17:21:57,377 DEBUG [o.a.c.s.h.HeuristicRuleHelper] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) No heuristic rules found for zone with ID [7] and heuristic type [SNAPSHOT]. Returning null.
2024-09-26 17:21:57,381 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Verifying image storage [7]. Capacity: total=[785 GB], used=[243 GB], threshold=[89.99999761581421%].
2024-09-26 17:21:57,381 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Verifying image storage [9]. Capacity: total=[785 GB], used=[72 GB], threshold=[89.99999761581421%].
2024-09-26 17:21:57,382 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Verifying image storage [7]. Capacity: total=[785 GB], used=[243 GB], threshold=[89.99999761581421%].
2024-09-26 17:21:57,419 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT
2024-09-26 17:21:57,529 ERROR [o.a.c.s.e.DefaultEndPointSelector] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) IR24 select BACKUPSNAPSHOT from primary to secondary 870 dest=870
2024-09-26 17:21:57,535 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand
2024-09-26 17:21:57,537 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) We are returning the default host to execute commands because the source and destination objects are not NFS type.
2024-09-26 17:21:57,540 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430189: Sending  { Cmd , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"d8f3d271-4b1d-4276-b4ea-390c3f82df57","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6163","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"executeInSequence":"true","options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"true"},"options2":{},"wait":"21600","bypassHostMaintenance":"false"}}] }
2024-09-26 17:21:57,562 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430189: Executing:  { Cmd , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"d8f3d271-4b1d-4276-b4ea-390c3f82df57","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6163","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":"54","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":"0","url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":"false"}},"name":"ROOT-5474","size":"(10.00 GB) 10737418240","path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":"6163","vmName":"i-225-5474-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"54","id":"6163","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":"870","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"executeInSequence":"true","options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"true"},"options2":{},"wait":"21600","bypassHostMaintenance":"false"}}] }
2024-09-26 17:21:57,562 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Executing command CopyCommand: [{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"d8f3d271-4b1d-4276-b4ea-390c3f82df57","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":54,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":0,"url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":false}},"name":"ROOT-5474","size":10737418240,"path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":6163,"vmName":"i-225-5474-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":54,"id":6163,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":54,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":0,"url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":false}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":870,"quiescevm":false,"physicalSize":0,"accountId":225,"followRedirects":false}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6163","volume":{"uuid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN4","name":"cluster5-dm7100_lun4","id":54,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN4","port":0,"url":"PreSetup://localhost/DM7100_LUN4/?ROLE=Primary&STOREUUID=DM7100_LUN4","isManaged":false}},"name":"ROOT-5474","size":10737418240,"path":"9c99b264-d618-4030-916b-1502ec5fadba","volumeId":6163,"vmName":"i-225-5474-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":54,"id":6163,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5474-VM","name":"backup-test-karasev-9_ROOT-5474_20240926142141","hypervisorType":"XenServer","id":870,"quiescevm":false,"physicalSize":0,"accountId":225,"followRedirects":false}},"executeInSequence":true,"options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"true"},"options2":{},"wait":21600,"bypassHostMaintenance":false}].
2024-09-26 17:21:59,970 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) No file SR found for path: /var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6163
2024-09-26 17:21:59,970 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Creating file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6163] on host [7fe64564-c05c-4425-8436-ec2da15f740a]
2024-09-26 17:22:00,006 DEBUG [c.c.a.ApiServlet] (qtp501107890-4832815:ctx-29b0404b) (logid:360fad58) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:00,032 DEBUG [c.c.a.ApiServlet] (qtp501107890-4832815:ctx-29b0404b ctx-d7854f91) (logid:360fad58) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:03,119 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-c04fc898) (logid:2219e417) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:03,142 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834338:ctx-c04fc898 ctx-fec4282e) (logid:2219e417) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:06,257 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-63120037) (logid:8a9b8304) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:06,280 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-63120037 ctx-6adff946) (logid:8a9b8304) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:09,402 DEBUG [c.c.a.ApiServlet] (qtp501107890-4832815:ctx-b3166a90) (logid:b7878727) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:09,424 DEBUG [c.c.a.ApiServlet] (qtp501107890-4832815:ctx-b3166a90 ctx-af252453) (logid:b7878727) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:12,536 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-5e16f60d) (logid:ed82faf7) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:12,559 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-5e16f60d ctx-021e66d4) (logid:ed82faf7) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:15,663 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-516e5765) (logid:a4ec32b9) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:15,686 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-516e5765 ctx-f115c344) (logid:a4ec32b9) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:18,799 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824844:ctx-b60f4585) (logid:253c7fb4) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:18,822 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824844:ctx-b60f4585 ctx-cd2c67ed) (logid:253c7fb4) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:21,936 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-863d8a59) (logid:08b2e49f) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:21,959 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-863d8a59 ctx-95f1425b) (logid:08b2e49f) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:25,071 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-6e2f29f1) (logid:724bb944) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:25,094 DEBUG [c.c.a.ApiServlet] (qtp501107890-4821895:ctx-6e2f29f1 ctx-fbc38980) (logid:724bb944) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:27,025 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Host 10.69.105.21 OpaqueRef:ff865e44-ce8f-4670-b990-855700769647: Removing SR
2024-09-26 17:22:27,038 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Host 10.69.105.21 OpaqueRef:d5a56d3b-f5af-461e-bee4-b387938e18fe: Unplugging pbd
2024-09-26 17:22:27,449 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Host 10.69.105.21 OpaqueRef:ff865e44-ce8f-4670-b990-855700769647: Forgetting
2024-09-26 17:22:27,454 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Successfully destroyed snapshot on volume: 9c99b264-d618-4030-916b-1502ec5fadba execept this current snapshot d8f3d271-4b1d-4276-b4ea-390c3f82df57
2024-09-26 17:22:27,454 INFO  [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) New snapshot details: SnapshotTO[datastore=null|volume=null|pathsnapshots/225/6163/07116d77-9286-4eaa-9e40-f4b754def19f.vhd]
2024-09-26 17:22:27,455 INFO  [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) New snapshot physical utilization: (5.46 GB) 5866705408
2024-09-26 17:22:27,455 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Seq 77360-7409547286931430189: Response Received:
2024-09-26 17:22:27,455 DEBUG [c.c.a.t.Request] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Seq 77360-7409547286931430189: Processing:  { Ans: , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6163/07116d77-9286-4eaa-9e40-f4b754def19f.vhd","id":"0","quiescevm":"false","physicalSize":"5866705408","accountId":"0","followRedirects":"false"}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 17:22:27,455 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-366:ctx-f42b18d7) (logid:c8e45246) Seq 77360-7409547286931430189: No more commands found
2024-09-26 17:22:27,455 DEBUG [c.c.a.t.Request] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Seq 77360-7409547286931430189: Received:  { Ans: , MgmtId: 108597816265214, via: 77360(xcp-sr246-u0708.aisrp.local), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2024-09-26 17:22:27,491 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Updating resource Type = secondary_storage count for Account = 225 Operation = decreasing Amount = (4.54 GB) 4870712832
2024-09-26 17:22:27,499 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Done executing VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":6163,"policyId":0,"snapshotId":870,"quiesceVm":false,"asyncBackup":false,"userId":298,"accountId":225,"vmId":5474,"handlerName":"VolumeApiServiceImpl"}
2024-09-26 17:22:27,500 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Complete async job-72465, jobStatus: SUCCEEDED, resultCode: 0, result: rO0ABXNyAA5qYXZhLmxhbmcuTG9uZzuL5JDMjyPfAgABSgAFdmFsdWV4cgAQamF2YS5sYW5nLk51bWJlcoaslR0LlOCLAgAAeHAAAAAAAAADZg
2024-09-26 17:22:27,501 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Publish async job-72465 complete on message bus
2024-09-26 17:22:27,501 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Wake up jobs related to job-72465
2024-09-26 17:22:27,501 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Update db status for job-72465
2024-09-26 17:22:27,502 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465 ctx-75e57019) (logid:c8e45246) Wake up jobs joined with job-72465 and disjoin all subjobs created from job- 72465
2024-09-26 17:22:27,509 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465) (logid:c8e45246) Done with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 5474, job origin: 72464
2024-09-26 17:22:27,509 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465) (logid:c8e45246) Done executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-72465
2024-09-26 17:22:27,511 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-152:ctx-2271fcd8 job-72464/job-72465) (logid:c8e45246) Remove job-72465 from job monitoring
2024-09-26 17:22:27,545 DEBUG [o.a.c.s.s.StorPoolSnapshotStrategy] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) StorpoolSnapshotStrategy.canHandle: snapshot=backup-test-karasev-9_ROOT-5474_20240926142141, uuid=7bdc207e-974e-41ed-a51f-f104bac1102c, op=REVERT
2024-09-26 17:22:27,549 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Complete async job-72464, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"7bdc207e-974e-41ed-a51f-f104bac1102c","account":"karasev-cluster5","domainid":"ce7e4a4a-75b6-4c96-938c-fe3158da9a47","domain":"cluster5","snapshottype":"MANUAL","volumeid":"5e964ddb-3d14-4037-a241-12972ebc5354","volumename":"ROOT-5474","volumetype":"ROOT","created":"2024-09-26T17:21:41+0300","name":"backup-test-karasev-9_ROOT-5474_20240926142141","intervaltype":"MANUAL","state":"BackedUp","physicalsize":"5866705408","zoneid":"9505445a-7164-4675-876d-1a2fee1f7e46","zonename":"xcp-zone-02","revertable":"false","ostypeid":"7b53b54f-d3d2-409f-b9b0-acd39122368a","osdisplayname":"Ubuntu 22.04 LTS","virtualsize":"10737418240","tags":[],"hasannotations":"false"}
2024-09-26 17:22:27,550 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Publish async job-72464 complete on message bus
2024-09-26 17:22:27,550 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Wake up jobs related to job-72464
2024-09-26 17:22:27,550 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Update db status for job-72464
2024-09-26 17:22:27,551 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464 ctx-7ca9e6a7) (logid:c8e45246) Wake up jobs joined with job-72464 and disjoin all subjobs created from job- 72464
2024-09-26 17:22:27,555 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-968ed109 job-72464) (logid:c8e45246) Done executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-72464
2024-09-26 17:22:27,555 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-63:ctx-968ed109 job-72464) (logid:c8e45246) Remove job-72464 from job monitoring
2024-09-26 17:22:28,208 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834306:ctx-41f1ef09) (logid:5789c854) ===START===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json
2024-09-26 17:22:28,238 DEBUG [c.c.a.ApiServlet] (qtp501107890-4834306:ctx-41f1ef09 ctx-be04a227) (logid:5789c854) ===END===  172.16.11.61 -- GET  jobId=c8e45246-57d3-4238-8cf1-6b7fa887c144&command=queryAsyncJobResult&response=json

Example when first volume snapshot was copied to the second secstore and I try to create the next volume snapshot

2024-09-26 16:58:32,135 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Executing AsyncJobVO: {id:72454, userId: 298, accountId: 225, instanceType: Snapshot, instanceId: 867, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"asyncBackup":"false","quiescevm":"false","response":"json","ctxUserId":"298","volumeId":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","httpmethod":"GET","ctxStartEventId":"1811467","id":"867","ctxDetails":"{\"interface com.cloud.storage.Volume\":\"da420806-0ff3-43b8-9ee0-4aa2adfd9b99\",\"interface com.cloud.storage.Snapshot\":\"c62b0aa0-5a1c-475c-b7f6-6c9fab17e325\"}","ctxAccountId":"225","uuid":"c62b0aa0-5a1c-475c-b7f6-6c9fab17e325","cmdEventType":"SNAPSHOT.CREATE"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 108597816265214, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2024-09-26 16:58:32,147 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454 ctx-829ed64e) (logid:f365dd96) Access to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 16:58:32,167 DEBUG [c.c.a.ApiServlet] (qtp501107890-4830812:ctx-4bacce10) (logid:11a55db0) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:32,183 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454 ctx-829ed64e) (logid:f365dd96) Access to org.apache.cloudstack.storage.volume.VolumeObject@f1e18b7 granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 16:58:32,190 DEBUG [c.c.a.ApiServlet] (qtp501107890-4830812:ctx-4bacce10 ctx-aa1d9072) (logid:11a55db0) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:32,192 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454 ctx-829ed64e) (logid:f365dd96) Access to VM instance {"id":5468,"instanceName":"i-225-5468-VM","type":"User","uuid":"d1e26871-d01f-44cc-ac61-f19f46ed741a"} granted to Account [{"accountName":"karasev-cluster5","id":225,"uuid":"fd32d818-5d3b-4d3c-9084-34704beefaf5"}] by DomainChecker
2024-09-26 16:58:32,206 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454 ctx-829ed64e) (logid:f365dd96) Sync job-72455 execution on object VmWorkJobQueue.5468
2024-09-26 16:58:32,575 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Executing AsyncJobVO: {id:72455, userId: 298, accountId: 225, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAAdaAAthc3luY0JhY2t1cFoACXF1aWVzY2VWbUwADGxvY2F0aW9uVHlwZXQAKUxjb20vY2xvdWQvc3RvcmFnZS9TbmFwc2hvdCRMb2NhdGlvblR5cGU7TAAIcG9saWN5SWR0ABBMamF2YS9sYW5nL0xvbmc7TAAKc25hcHNob3RJZHEAfgACTAAIdm9sdW1lSWRxAH4AAkwAB3pvbmVJZHN0ABBMamF2YS91dGlsL0xpc3Q7eHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAOEAAAAAAAABKgAAAAAAABVcdAAUVm9sdW1lQXBpU2VydmljZUltcGwAAHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAABzcQB-AAgAAAAAAAADY3NxAH4ACAAAAAAAABgMcA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 108597816265214, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Sep 26 16:58:32 MSK 2024, removed: null}
2024-09-26 16:58:32,575 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Run VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 5468, job origin: 72454
2024-09-26 16:58:32,576 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Execute VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":6156,"policyId":0,"snapshotId":867,"quiesceVm":false,"asyncBackup":false,"userId":298,"accountId":225,"vmId":5468,"handlerName":"VolumeApiServiceImpl"}
2024-09-26 16:58:32,588 DEBUG [o.a.c.s.s.StorPoolSnapshotStrategy] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) StorpoolSnapshotStrategy.canHandle: snapshot=backup-test-karasev-3_ROOT-5468_20240926135832, uuid=c62b0aa0-5a1c-475c-b7f6-6c9fab17e325, op=TAKE
2024-09-26 16:58:32,622 DEBUG [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Taking snapshot of org.apache.cloudstack.storage.snapshot.SnapshotObject@18f701c2
2024-09-26 16:58:32,653 DEBUG [o.a.c.s.d.d.CloudStackPrimaryDataStoreDriverImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Taking snapshot of org.apache.cloudstack.storage.snapshot.SnapshotObject@18f701c2 and encryption required is false
2024-09-26 16:58:32,653 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CreateObjectCommand
2024-09-26 16:58:32,655 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) We are returning the default host to execute commands because the command is not of Copy type.
2024-09-26 16:58:32,657 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77353-4517673376206130891: Sending  { Cmd , MgmtId: 108597816265214, via: 77353(xcp-sr246-u1314.aisrp.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":"0","accountId":"225","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:32,659 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77353-4517673376206130891: Executing:  { Cmd , MgmtId: 108597816265214, via: 77353(xcp-sr246-u1314.aisrp.local), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":"0","accountId":"225","followRedirects":"false"}},"wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:32,659 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase] (DirectAgent-128:ctx-052ce805) (logid:f365dd96) Executing command CreateObjectCommand: [{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":53,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":0,"url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":false}},"name":"ROOT-5468","size":21474836480,"path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":6156,"vmName":"i-225-5468-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":53,"id":6156,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":53,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":0,"url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":false}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":867,"quiescevm":false,"parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":0,"accountId":225,"followRedirects":false}},"wait":0,"bypassHostMaintenance":false}].
2024-09-26 16:58:35,268 DEBUG [c.c.a.ApiServlet] (qtp501107890-4820302:ctx-f711cc5b) (logid:4e44467e) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:35,290 DEBUG [c.c.a.ApiServlet] (qtp501107890-4820302:ctx-f711cc5b ctx-e8b6659b) (logid:4e44467e) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:38,370 DEBUG [c.c.a.ApiServlet] (qtp501107890-4830812:ctx-fd303fe2) (logid:ef8914d8) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:38,394 DEBUG [c.c.a.ApiServlet] (qtp501107890-4830812:ctx-fd303fe2 ctx-aec37e2b) (logid:ef8914d8) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:39,977 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-128:ctx-052ce805) (logid:f365dd96) Seq 77353-4517673376206130891: Response Received:
2024-09-26 16:58:39,977 DEBUG [c.c.a.t.Request] (DirectAgent-128:ctx-052ce805) (logid:f365dd96) Seq 77353-4517673376206130891: Processing:  { Ans: , MgmtId: 108597816265214, via: 77353(xcp-sr246-u1314.aisrp.local), Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"e1971e58-5b6e-4f59-a256-154280cf4d16","id":"0","quiescevm":"false","physicalSize":"0","accountId":"0","followRedirects":"false"}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:39,977 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77353-4517673376206130891: Received:  { Ans: , MgmtId: 108597816265214, via: 77353(xcp-sr246-u1314.aisrp.local), Ver: v1, Flags: 10, { CreateObjectAnswer } }
2024-09-26 16:58:40,045 DEBUG [o.a.c.s.h.HeuristicRuleHelper] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) No heuristic rules found for zone with ID [7] and heuristic type [SNAPSHOT]. Returning null.
2024-09-26 16:58:40,049 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Verifying image storage [7]. Capacity: total=[785 GB], used=[243 GB], threshold=[89.99999761581421%].
2024-09-26 16:58:40,050 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Verifying image storage [9]. Capacity: total=[785 GB], used=[70 GB], threshold=[89.99999761581421%].
2024-09-26 16:58:40,051 DEBUG [c.c.s.StatsCollector] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Verifying image storage [7]. Capacity: total=[785 GB], used=[243 GB], threshold=[89.99999761581421%].
2024-09-26 16:58:40,101 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT
2024-09-26 16:58:40,224 ERROR [o.a.c.s.e.DefaultEndPointSelector] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) IR24 select BACKUPSNAPSHOT from primary to secondary 867 dest=867
2024-09-26 16:58:40,236 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) getCommandHostDelegation: class org.apache.cloudstack.storage.command.CopyCommand
2024-09-26 16:58:40,238 DEBUG [c.c.h.XenServerGuru] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) We are returning the default host to execute commands because the source and destination objects are not NFS type.
2024-09-26 16:58:40,243 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77358-1940207014466653252: Sending  { Cmd , MgmtId: 108597816265214, via: 77358(xcp-sr246-u1112.aisrp.local), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"e1971e58-5b6e-4f59-a256-154280cf4d16","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":"0","accountId":"225","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6156","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"executeInSequence":"true","options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"false"},"options2":{},"wait":"21600","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:40,245 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77358-1940207014466653252: Executing:  { Cmd , MgmtId: 108597816265214, via: 77358(xcp-sr246-u1112.aisrp.local), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"e1971e58-5b6e-4f59-a256-154280cf4d16","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":"0","accountId":"225","followRedirects":"false"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6156","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":"53","poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":"0","url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":"false"}},"name":"ROOT-5468","size":"(20.00 GB) 21474836480","path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":"6156","vmName":"i-225-5468-VM","accountId":"225","format":"VHD","provisioningType":"THIN","poolId":"53","id":"6156","deviceId":"0","cacheMode":"NONE","hypervisorType":"XenServer","directDownload":"false","deployAsIs":"false","followRedirects":"true"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":"867","quiescevm":"false","physicalSize":"0","accountId":"225","followRedirects":"false"}},"executeInSequence":"true","options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"false"},"options2":{},"wait":"21600","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:40,246 DEBUG [c.c.s.r.StorageSubsystemCommandHandlerBase] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Executing command CopyCommand: [{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"e1971e58-5b6e-4f59-a256-154280cf4d16","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":53,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":0,"url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":false}},"name":"ROOT-5468","size":21474836480,"path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":6156,"vmName":"i-225-5468-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":53,"id":6156,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"parentSnapshotPath":"70424963-5933-4e73-b185-cfdc402175cd","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":53,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":0,"url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":false}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":867,"quiescevm":false,"parents":["70424963-5933-4e73-b185-cfdc402175cd"],"physicalSize":0,"accountId":225,"followRedirects":false}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/225/6156","volume":{"uuid":"da420806-0ff3-43b8-9ee0-4aa2adfd9b99","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DM7100_LUN3","name":"cluster5-dm7100_lun3","id":53,"poolType":"PreSetup","host":"localhost","path":"/DM7100_LUN3","port":0,"url":"PreSetup://localhost/DM7100_LUN3/?ROLE=Primary&STOREUUID=DM7100_LUN3","isManaged":false}},"name":"ROOT-5468","size":21474836480,"path":"9e2a4d6e-3ab8-46f4-85cf-c7454fc9ea17","volumeId":6156,"vmName":"i-225-5468-VM","accountId":225,"format":"VHD","provisioningType":"THIN","poolId":53,"id":6156,"deviceId":0,"cacheMode":"NONE","hypervisorType":"XenServer","directDownload":false,"deployAsIs":false,"followRedirects":true},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.69.105.254/var/NFS","_role":"Image"}},"vmName":"i-225-5468-VM","name":"backup-test-karasev-3_ROOT-5468_20240926135832","hypervisorType":"XenServer","id":867,"quiescevm":false,"physicalSize":0,"accountId":225,"followRedirects":false}},"executeInSequence":true,"options":{"snapshot.backup.to.secondary":"true","fullSnapshot":"false"},"options2":{},"wait":21600,"bypassHostMaintenance":false}].
2024-09-26 16:58:41,264 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) No file SR found for path: /var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156
2024-09-26 16:58:41,264 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Creating file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:41,495 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824844:ctx-107e93ec) (logid:1bc5742a) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:41,518 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824844:ctx-107e93ec ctx-f58fcdf2) (logid:1bc5742a) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:41,520 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Unpluging PBD [c9ae6161-7db8-f308-db93-4fa060c94f9c] of SR [f6204e02-6efe-3005-95a3-095f19b458ac] as it is not working properly.
2024-09-26 16:58:41,536 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Forgetting SR [f6204e02-6efe-3005-95a3-095f19b458ac] as it is not working properly.
2024-09-26 16:58:41,617 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Could not create file SR [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] on host [4208d709-b553-47c0-aee2-7942d370b70c].
2024-09-26 16:58:41,617 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:41,617 WARN  [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) BackupSnapshot Failed due to Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:44,625 DEBUG [c.c.a.ApiServlet] (qtp501107890-4825573:ctx-e72bd43c) (logid:d5a19d4e) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:44,651 DEBUG [c.c.a.ApiServlet] (qtp501107890-4825573:ctx-e72bd43c ctx-707eaf3e) (logid:d5a19d4e) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:47,762 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-517f2c19) (logid:c6e8be8b) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:47,784 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824845:ctx-517f2c19 ctx-9a6894c4) (logid:c6e8be8b) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:47,863 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Seq 77358-1940207014466653252: Response Received:
2024-09-26 16:58:47,864 DEBUG [c.c.a.t.Request] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Seq 77358-1940207014466653252: Processing:  { Ans: , MgmtId: 108597816265214, via: 77358(xcp-sr246-u1112.aisrp.local), Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":"false","details":"BackupSnapshot Failed due to Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]","wait":"0","bypassHostMaintenance":"false"}}] }
2024-09-26 16:58:47,864 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-322:ctx-abb19c96) (logid:f365dd96) Seq 77358-1940207014466653252: No more commands found
2024-09-26 16:58:47,864 DEBUG [c.c.a.t.Request] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Seq 77358-1940207014466653252: Received:  { Ans: , MgmtId: 108597816265214, via: 77358(xcp-sr246-u1112.aisrp.local), Ver: v1, Flags: 110, { CopyCmdAnswer } }
2024-09-26 16:58:47,885 DEBUG [c.c.s.s.SnapshotManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Failed to create snapshotBackupSnapshot Failed due to Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:47,885 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Updating resource Type = snapshot count for Account = 225 Operation = decreasing Amount = 1
2024-09-26 16:58:47,894 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Updating resource Type = secondary_storage count for Account = 225 Operation = decreasing Amount = (20.00 GB) 21474836480
2024-09-26 16:58:47,901 ERROR [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Take snapshot: 6156 failed
2024-09-26 16:58:47,902 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Invocation exception, caused by: com.cloud.utils.exception.CloudRuntimeException: BackupSnapshot Failed due to Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:47,902 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455 ctx-d1890501) (logid:f365dd96) Rethrow exception com.cloud.utils.exception.CloudRuntimeException: BackupSnapshot Failed due to Exception in backupsnapshot stage due to com.cloud.utils.exception.CloudRuntimeException: Could not retrieve an already used file SR for path [/var/cloud_mount/440acca8-622d-3dfb-825d-b3e62d7bba87/snapshots/225/6156] or create a new file SR on host [4208d709-b553-47c0-aee2-7942d370b70c]
2024-09-26 16:58:47,902 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Done with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 5468, job origin: 72454
2024-09-26 16:58:47,902 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Unable to complete AsyncJobVO: {id:72455, userId: 298, accountId: 225, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkTakeVolumeSnapshot, cmdInfo: rO0ABXNyACVjb20uY2xvdWQudm0uVm1Xb3JrVGFrZVZvbHVtZVNuYXBzaG90BL5gG4Li1c8CAAdaAAthc3luY0JhY2t1cFoACXF1aWVzY2VWbUwADGxvY2F0aW9uVHlwZXQAKUxjb20vY2xvdWQvc3RvcmFnZS9TbmFwc2hvdCRMb2NhdGlvblR5cGU7TAAIcG9saWN5SWR0ABBMamF2YS9sYW5nL0xvbmc7TAAKc25hcHNob3RJZHEAfgACTAAIdm9sdW1lSWRxAH4AAkwAB3pvbmVJZHN0ABBMamF2YS91dGlsL0xpc3Q7eHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAOEAAAAAAAABKgAAAAAAABVcdAAUVm9sdW1lQXBpU2VydmljZUltcGwAAHBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAABzcQB-AAgAAAAAAAADY3NxAH4ACAAAAAAAABgMcA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 108597816265214, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Sep 26 16:58:32 MSK 2024, removed: null}, job origin:72454
2024-09-26 16:58:47,904 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Complete async job-72455, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvblZNT3AAAAACAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0ATxCYWNrdXBTbmFwc2hvdCBGYWlsZWQgZHVlIHRvIEV4Y2VwdGlvbiBpbiBiYWNrdXBzbmFwc2hvdCBzdGFnZSBkdWUgdG8gY29tLmNsb3VkLnV0aWxzLmV4Y2VwdGlvbi5DbG91ZFJ1bnRpbWVFeGNlcHRpb246IENvdWxkIG5vdCByZXRyaWV2ZSBhbiBhbHJlYWR5IHVzZWQgZmlsZSBTUiBmb3IgcGF0aCBbL3Zhci9jbG91ZF9tb3VudC80NDBhY2NhOC02MjJkLTNkZmItODI1ZC1iM2U2MmQ3YmJhODcvc25hcHNob3RzLzIyNS82MTU2XSBvciBjcmVhdGUgYSBuZXcgZmlsZSBTUiBvbiBob3N0IFs0MjA4ZDcwOS1iNTUzLTQ3YzAtYWVlMi03OTQyZDM3MGI3MGNddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAtc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAFTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABUwACGZpbGVOYW1lcQB-AAVMAAptZXRob2ROYW1lcQB-AAVMAAptb2R1bGVOYW1lcQB-AAVMAA1tb2R1bGVWZXJzaW9ucQB-AAV4cAEAAAF-dAADYXBwdAA6b3JnLmFwYWNoZS5jbG91ZHN0YWNrLnN0b3JhZ2Uuc25hcHNob3QuU25hcHNob3RTZXJ2aWNlSW1wbHQAGFNuYXBzaG90U2VydmljZUltcGwuamF2YXQADmJhY2t1cFNuYXBzaG90cHBzcQB-AAwBAAAAwXEAfgAOdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLnN0b3JhZ2Uuc25hcHNob3QuRGVmYXVsdFNuYXBzaG90U3RyYXRlZ3l0ABxEZWZhdWx0U25hcHNob3RTdHJhdGVneS5qYXZhcQB-ABFwcHNxAH4ADAEAAAWfcQB-AA50AC5jb20uY2xvdWQuc3RvcmFnZS5zbmFwc2hvdC5TbmFwc2hvdE1hbmFnZXJJbXBsdAAYU25hcHNob3RNYW5hZ2VySW1wbC5qYXZhdAAZYmFja3VwU25hcHNob3RUb1NlY29uZGFyeXBwc3EAfgAMAQAABWxxAH4ADnEAfgAWcQB-ABd0AAx0YWtlU25hcHNob3RwcHNxAH4ADAD_____cHQAMGpkay5pbnRlcm5hbC5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yMTk1N3B0AAZpbnZva2VwcHNxAH4ADAIAAAArcHQAMWpkay5pbnRlcm5hbC5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AHXQACWphdmEuYmFzZXQABzExLjAuMjRzcQB-AAwCAAACNnB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAdcQB-ACFxAH4AInNxAH4ADAEAAAFYcQB-AA50AChvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5zdXBwb3J0LkFvcFV0aWxzdAANQW9wVXRpbHMuamF2YXQAHmludm9rZUpvaW5wb2ludFVzaW5nUmVmbGVjdGlvbnBwc3EAfgAMAQAAAMZxAH4ADnQAPG9yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmZyYW1ld29yay5SZWZsZWN0aXZlTWV0aG9kSW52b2NhdGlvbnQAH1JlZmxlY3RpdmVNZXRob2RJbnZvY2F0aW9uLmphdmF0AA9pbnZva2VKb2lucG9pbnRwcHNxAH4ADAEAAACjcQB-AA5xAH4AK3EAfgAsdAAHcHJvY2VlZHBwc3EAfgAMAQAAAGFxAH4ADnQAP29yZy5zcHJpbmdmcmFtZXdvcmsuYW9wLmludGVyY2VwdG9yLkV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvcnQAIEV4cG9zZUludm9jYXRpb25JbnRlcmNlcHRvci5qYXZhcQB-AB1wcHNxAH4ADAEAAAC6cQB-AA5xAH4AK3EAfgAscQB-AC9wcHNxAH4ADAEAAADXcQB-AA50ADRvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuSmRrRHluYW1pY0FvcFByb3h5dAAXSmRrRHluYW1pY0FvcFByb3h5LmphdmFxAH4AHXBwc3EAfgAMAP____9wdAAXY29tLnN1bi5wcm94eS4kUHJveHkyMzhwcQB-ABpwcHNxAH4ADAEAAArYcQB-AA50ADZvcmcuYXBhY2hlLmNsb3Vkc3RhY2suc3RvcmFnZS52b2x1bWUuVm9sdW1lU2VydmljZUltcGx0ABZWb2x1bWVTZXJ2aWNlSW1wbC5qYXZhcQB-ABpwcHNxAH4ADAEAAA68cQB-AA50ACZjb20uY2xvdWQuc3RvcmFnZS5Wb2x1bWVBcGlTZXJ2aWNlSW1wbHQAGVZvbHVtZUFwaVNlcnZpY2VJbXBsLmphdmF0AB1vcmNoZXN0cmF0ZVRha2VWb2x1bWVTbmFwc2hvdHBwc3EAfgAMAQAAE7lxAH4ADnEAfgA9cQB-AD5xAH4AP3Bwc3EAfgAMAP____9wdAAwamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3IxOTU2cHEAfgAdcHBzcQB-AAwCAAAAK3BxAH4AH3EAfgAgcQB-AB1xAH4AIXEAfgAic3EAfgAMAgAAAjZwcQB-ACRxAH4AJXEAfgAdcQB-ACFxAH4AInNxAH4ADAEAAABpcQB-AA50ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4ADAEAABPHcQB-AA5xAH4APXEAfgA-cQB-AEhwcHNxAH4ADAD_____cHQAMGpkay5pbnRlcm5hbC5yZWZsZWN0LkdlbmVyYXRlZE1ldGhvZEFjY2Vzc29yMTAzNnBxAH4AHXBwc3EAfgAMAgAAACtwcQB-AB9xAH4AIHEAfgAdcQB-ACFxAH4AInNxAH4ADAIAAAI2cHEAfgAkcQB-ACVxAH4AHXEAfgAhcQB-ACJzcQB-AAwBAAABWHEAfgAOcQB-ACdxAH4AKHEAfgApcHBzcQB-AAwBAAAAxnEAfgAOcQB-ACtxAH4ALHEAfgAtcHBzcQB-AAwBAAAAo3EAfgAOcQB-ACtxAH4ALHEAfgAvcHBzcQB-AAwBAAAAYXEAfgAOcQB-ADFxAH4AMnEAfgAdcHBzcQB-AAwBAAAAunEAfgAOcQB-ACtxAH4ALHEAfgAvcHBzcQB-AAwBAAAA13EAfgAOcQB-ADVxAH4ANnEAfgAdcHBzcQB-AAwA_____3B0ABdjb20uc3VuLnByb3h5LiRQcm94eTI0N3BxAH4ASHBwc3EAfgAMAQAAAGZxAH4ADnQAIGNvbS5jbG91ZC52bS5WbVdvcmtKb2JEaXNwYXRjaGVydAAYVm1Xb3JrSm9iRGlzcGF0Y2hlci5qYXZhdAAGcnVuSm9icHBzcQB-AAwBAAACjnEAfgAOdAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0cHBzcQB-AAwBAAAAMHEAfgAOdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5wcHNxAH4ADAEAAAA3cQB-AA50AEJvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0JDF0ABpEZWZhdWx0TWFuYWdlZENvbnRleHQuamF2YXQABGNhbGxwcHNxAH4ADAEAAABmcQB-AA50AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-AGR0AA9jYWxsV2l0aENvbnRleHRwcHNxAH4ADAEAAAA0cQB-AA5xAH4AZ3EAfgBkdAAOcnVuV2l0aENvbnRleHRwcHNxAH4ADAEAAAAtcQB-AA50ADxvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGVxAH4AYHEAfgBhcHBzcQB-AAwBAAACWnEAfgAOcQB-AFtxAH4AXHEAfgBhcHBzcQB-AAwCAAACA3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5FeGVjdXRvcnMkUnVubmFibGVBZGFwdGVydAAORXhlY3V0b3JzLmphdmFxAH4AZXEAfgAhcQB-ACJzcQB-AAwCAAABCHB0AB9qYXZhLnV0aWwuY29uY3VycmVudC5GdXR1cmVUYXNrdAAPRnV0dXJlVGFzay5qYXZhcQB-AGFxAH4AIXEAfgAic3EAfgAMAgAABGhwdAAnamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9ydAAXVGhyZWFkUG9vbEV4ZWN1dG9yLmphdmF0AAlydW5Xb3JrZXJxAH4AIXEAfgAic3EAfgAMAgAAAnRwdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuVGhyZWFkUG9vbEV4ZWN1dG9yJFdvcmtlcnEAfgB2cQB-AGFxAH4AIXEAfgAic3EAfgAMAgAAAz1wdAAQamF2YS5sYW5nLlRocmVhZHQAC1RocmVhZC5qYXZhcQB-AGFxAH4AIXEAfgAic3IAH2phdmEudXRpbC5Db2xsZWN0aW9ucyRFbXB0eUxpc3R6uBe0PKee3gIAAHhweAAAEJp3CAAAAAAAAAAAeA
2024-09-26 16:58:47,905 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Publish async job-72455 complete on message bus
2024-09-26 16:58:47,905 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Wake up jobs related to job-72455
2024-09-26 16:58:47,905 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Update db status for job-72455
2024-09-26 16:58:47,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Wake up jobs joined with job-72455 and disjoin all subjobs created from job- 72455
2024-09-26 16:58:47,914 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Done executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-72455
2024-09-26 16:58:47,916 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-148:ctx-ef42787d job-72454/job-72455) (logid:f365dd96) Remove job-72455 from job monitoring
2024-09-26 16:58:47,930 ERROR [o.a.c.a.c.u.s.CreateSnapshotCmd] (API-Job-Executor-58:ctx-c9d433a7 job-72454 ctx-829ed64e) (logid:f365dd96) Failed to create snapshot due to an internal error creating snapshot for volume da420806-0ff3-43b8-9ee0-4aa2adfd9b99
2024-09-26 16:58:47,935 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Complete async job-72454, 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 da420806-0ff3-43b8-9ee0-4aa2adfd9b99"}
2024-09-26 16:58:47,936 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Publish async job-72454 complete on message bus
2024-09-26 16:58:47,936 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Wake up jobs related to job-72454
2024-09-26 16:58:47,936 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Update db status for job-72454
2024-09-26 16:58:47,937 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Wake up jobs joined with job-72454 and disjoin all subjobs created from job- 72454
2024-09-26 16:58:47,941 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Done executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-72454
2024-09-26 16:58:47,941 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-58:ctx-c9d433a7 job-72454) (logid:f365dd96) Remove job-72454 from job monitoring
2024-09-26 16:58:50,891 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824742:ctx-04767efc) (logid:00d3b60a) ===START===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json
2024-09-26 16:58:50,913 DEBUG [c.c.a.ApiServlet] (qtp501107890-4824742:ctx-04767efc ctx-ff2eca28) (logid:00d3b60a) ===END===  172.16.11.61 -- GET  jobId=f365dd96-c018-454a-874c-37dce9396d96&command=queryAsyncJobResult&response=json

Regarding the first issue of all/most snapshots going to one store, it would be helpful knowing the following:

Are the 2 secondary stores of same or similar capacity?
What is the value set for the global setting: image.store.allocation.algorithm ?

@Pearl1594

@Pearl1594 1. the same capacity. Second is a copy of first
2. firstfitleastconsumed

@Pearl1594

@Pearl1594 if I set first secstore Read-Only, snapshots are copied to the second secstore. But after I unset Read-Only all snapshots are copied to the first secstore again

when creating the volume snaphots, were they are initiated at the same time i.e, either via API or through recurring snapshot schedule. If that was the case, this could possible happen because the stats collector would not have run to has updated the stats of the secondary store(s) to make the decision that store1 has capacity < than store2. Marking store1 to read only excludes it from the list of stores to which snapshot would be backed up to - expected behaviour.

Navigation Menu

Repository navigation

Multiple secondary storage in one zone; problem with volume snapshots #9734

ISSUE TYPE

CLOUDSTACK VERSION

SUMMARY

STEPS TO REPRODUCE

EXPECTED RESULTS

ACTUAL RESULTS

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Multiple secondary storage in one zone; problem with volume snapshots #9734

Description

ISSUE TYPE

CLOUDSTACK VERSION

SUMMARY

STEPS TO REPRODUCE

EXPECTED RESULTS

ACTUAL RESULTS

Activity

top-secrett commented on Sep 26, 2024

top-secrett commented on Sep 26, 2024

Pearl1594 commented on Sep 26, 2024

top-secrett commented on Sep 27, 2024

top-secrett commented on Sep 27, 2024

Pearl1594 commented on Sep 27, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions