Hi,
Thanks for that information and pointers on where to look, I have checked
it out and the data was also on the secondary storage and the storage VM is
mounting the NFS servers etc. (I have redeployed it just incase)
I have gone through some of the older snapshots that are not getting
removed, and they do have that reference in the Ready Status:
MariaDB [cloud]> select
id,store_id,snapshot_id,state,store_role,install_path from
snapshot_store_ref where install_path like
'%8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07';
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
| id | store_id | snapshot_id | state | store_role | install_path
|
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
| 1554 | 7 | 852 | Destroyed | Primary |
cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
|
| 1555 | 1 | 852 | Ready | Image |
snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
|
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)
MariaDB [cloud]> select * from snapshots where id=852;
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
| id | data_center_id | account_id | domain_id | volume_id |
disk_offering_id | status | path | name
| uuid | snapshot_type |
type_description | size | created | removed |
backup_snap_id | swift_id | sechost_id | prev_snap_id | hypervisor_type |
version | s3_id | min_iops | max_iops | location_ type |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
| 852 | 1 | 2 | 1 | 146 |
6 | Destroyed | NULL | vxtr-ln1-box01_DATA-86_20210226010342 |
10ece2f5-39cf-4afe-9894-48c7c47e1463 | 4 |
DAILY | 214748364800 | 2021-02-26 01:03:42 | NULL | NULL
| NULL | NULL | NULL | KVM | 2.2 |
NULL | NULL | NULL | NULL |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
I also cannot see any errors when it is created:
2021-02-26 01:03:42,019 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Got 1 snapshots to be
executed at 2021-02-26 01:03:42 GMT
2021-02-26 01:03:42,023 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Scheduling 1 snapshot for
volume id 146 (volume name:DATA-86) for schedule id: 7 at 2021-02-26
01:00:00 GMT
2021-02-26 01:03:42,064 DEBUG [c.c.r.ResourceLimitManagerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Updating resource Type =
snapshot count for Account = 2 Operation = increasing Amount = 1
2021-02-26 01:03:42,083 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) submit async job-6123,
details: AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType:
Snapshot, instanceId: 852, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2021-02-26 01:03:42,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Executing
AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType: Snapshot,
instanceId: 852, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2021-02-26 01:03:43,284 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Execute VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
2021-02-26 01:03:45,111 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Seq 10-5259641414815547085: Sending { Cmd , MgmtId:
345050527765, via: 10(chst01.vxtream.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
GB)
214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
GB)
214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
10.100.7.51/export/secondary","_role":"Image"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
}
2021-02-26 01:22:17,334 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 10-5259641414815547085:
Processing: { Ans: , MgmtId: 345050527765, via: 10, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","id":"0","quiescevm":"false","physicalSize":"112297967616"}},"result":"true","wait":"0"}}]
}
2021-02-26 01:22:17,355 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Max snaps: 3 exceeded for snapshot policy with Id: 7.
Deleting oldest snapshot: 849
2021-02-26 01:22:18,473 DEBUG [c.c.r.ResourceLimitManagerImpl]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Updating resource Type = snapshot count for Account = 2
Operation = decreasing Amount = 1
2021-02-26 01:22:18,499 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Done executing VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
2021-02-26 01:22:18,565 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123 ctx-1be547c7) (logid:7c83430b)
Complete async job-6123, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"10ece2f5-39cf-4afe-9894-48c7c47e1463","account":"admin","domainid":"1e48287f-ee6a-11e9-8f54-0050569d3815","domain":"ROOT","snapshottype":"DAILY","volumeid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumename":"DATA-86","volumetype":"DATADISK","created":"2021-02-26T01:03:42+0000","name":"vxtr-ln1-box01_DATA-86_20210226010342","intervaltype":"DAILY","state":"BackedUp","physicalsize":"112297967616","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","virtualsize":"214748364800","tags":[]}
2021-02-26 01:22:18,592 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Done executing
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
job-6123
This log indicates when it is set to be removed:
2021-03-01 01:22:13,750 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
(logid:503cabb8) Max snaps: 3 exceeded for snapshot policy with Id: 7.
Deleting olest snapshot: 852
2021-03-01 01:22:13,797 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
(logid:503cabb8) getCommandHostDelegation: class
org.apache.cloudstack.storage.comand.DeleteCommand
Any indication on what I should look for in the logs for regarding the
'secondary storage "garbage" should be cleaned up'?
Many thanks for your help.
Ed
On Fri, 5 Mar 2021 at 15:12, Gabriel Bräscher <gabrasc...@gmail.com> wrote:
> Before seeing the last reply I had just tested on CloudStack 4.15 + Ceph +
> KVM, and it worked fine; however, I did the test with one snapshot of the
> volume.
> Maybe the scheduled/incremental snapshotting adds a different variable to
> the equation.
>
> From my tests, the DB holds one reference as Ready on the secondary
> storage, and one as Destroyed (on primary storage). I think that it is the
> expected behavior and the secondary storage "garbage" should be cleaned up
> on a window of 24-48 hours (by default, as the cleanup thread runs each 24
> hours and it checks for a timestamp of 24 hours as well, on the worst case
> it can take up to 48 hours, on the best 24 hours).
>
> I find it quite weird the fact that it has been thrown a null pointer
> before; as if the volume has been deleted and the Snapshot already exists.
>
> Your log presents the following ERROR:
> 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> inspecting dest type SNAPSHOT
> 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> dest=861
>
> It indicates an issue when copying the snapshot from primary to secondary
> storage; I would look closely at the secondary storage pool and check the
> SSVM (secondary storage system VM).
>
> For reference,here follows an example from the deleted backed-up snapshot
> from my test:
>
> > select id,store_id,snapshot_id,state,store_role,install_path from
> snapshot_store_ref where snapshot_id=759;
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
> | id | store_id | snapshot_id | state | store_role | install_path
> |
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
> | 838 | 21 | 759 | Destroyed | Primary |
>
> rbd/8e918c48-f32a-4c4e-81b2-0ba374d705dc/b41ba753-afad-42b5-849f-839736cb3a77
> |
> | 839 | 1 | 759 | Ready | Image |
> snapshots/6/12872/b41ba753-afad-42b5-849f-839736cb3a77
> |
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
>
>
>
>
> Em sex., 5 de mar. de 2021 às 07:59, Edward St Pierre <
> edward.stpie...@gmail.com> escreveu:
>
> > Hi
> >
> > The issue happens multiple snapshots, I have run a test with
> > scheduled hourly volume snapshots for a test, here are the logs:
> >
> > 2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Execute VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > 2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
> > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > }
> > 2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
> > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
> > }
> > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > inspecting dest type SNAPSHOT
> > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> > dest=861
> > 2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
> > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > apache.cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> > 10.100.7.51/export/secondary
> >
> ","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> > }
> > 2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot scheduler.poll
> is
> > being called at 2021-03-05 10:08:42 GMT
> > 2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to be
> > executed at 2021-03-05 10:08:42 GMT
> > 2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
> > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
> > }
> > 2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id: 8.
> > Deleting oldest snapshot: 860
> > 2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Access to
> > com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f granted
> > to
> > Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
> > 2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
> > 345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags:
> > 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > apache.cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > }
> > 2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
> > Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags: 10,
> > [{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
> > 3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > removed successfully.","wait":"0"}}] }
> > 2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Updating resource Type = snapshot count for Account = 9
> > Operation = decreasing Amount = 1
> > 2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Done executing VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > 2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> Done
> > with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM
> 156,
> > job origin: 6141
> > 2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> Done
> > executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
> > 2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d) (logid:fc7d7320)
> > Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
> >
> >
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
> > 7","virtualsize":"107374182400","tags":[]}
> > 2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done
> executing
> > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> > job-6141
> >
> > Here are the actual snapshots on secondary storage:
> >
> > -rw-r--r--. 1 root root 16888233984 Mar 5 10:09
> > a00ba130-19f0-454c-9b74-55f95a64bfb5
> > -rw-r--r--. 1 root root 16888233984 Mar 5 09:09
> > b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> >
> > Here are the entries in the DB relating to the snapshots:
> >
> > select * from snapshots order by created desc limit 2;
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > | id | data_center_id | account_id | domain_id | volume_id |
> > disk_offering_id | status | path | name
> > | uuid | snapshot_type |
> type_description
> > | size | created | removed | backup_snap_id |
> swift_id
> > | sechost_id | prev_snap_id | hypervisor_type | version | s3_id |
> min_iops
> > | max_iops | location_type |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > | 861 | 1 | 9 | 6 | 225 |
> > 5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
> > 076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY |
> > 107374182400 | 2021-03-05 10:03:42 | NULL | NULL | NULL
> |
> > NULL | NULL | KVM | 2.2 | NULL | NULL
> |
> > NULL | NULL |
> > | 860 | 1 | 9 | 6 | 225 |
> > 5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
> > 2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY |
> > 107374182400 | 2021-03-05 09:03:42 | NULL | NULL | NULL
> |
> > NULL | NULL | KVM | 2.2 | NULL | NULL
> |
> > NULL | NULL |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> >
> >
> >
> > Regards
> >
> > Ed
> >
> > On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <gabrasc...@gmail.com>
> > wrote:
> >
> > > There was an open issue indeed but a PR solved it for 4.15. The issue
> > > reported on this email looks a bit different than the ones I have seen.
> > >
> > > Background on a recent issue:
> > > - Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary:
> > true"
> > > has been fixed by PR #4568 "kvm: Fix double-escape issue while creating
> > rbd
> > > disk options"
> > >
> > > Reading the log:
> > > - In order for such a null pointer to happen the volume from the
> snapshot
> > > has been deleted on DB. Thus, it is either a bug or an inconsistency on
> > the
> > > DB; e.g.: deleting the volume prior to its Snapshots.
> > >
> > > Is this occurrence an isolated one or does it happen with multiple
> > > snapshots that have been deleted?
> > >
> > > #4498: https://github.com/apache/cloudstack/issues/4498
> > > #4568: https://github.com/apache/cloudstack/pull/4568
> > >
> > > Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <
> www.rakeshv....@gmail.com
> > >
> > > escreveu:
> > >
> > > > If I remember properly there is already an issue raised for it in
> > github
> > > >
> > > > Sent from my iPhone
> > > >
> > > > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <andrija.pa...@gmail.com
> >
> > > > wrote:
> > > > >
> > > > > @Gabriel Beims Bräscher <gabrasc...@gmail.com> does this rings
> any
> > > > bells
> > > > > for you? I haven't played with Ceph / snap clean-up issue on 4.15
> > > myself.
> > > > >
> > > > > Best,
> > > > >
> > > > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > > > edward.stpie...@gmail.com>
> > > > >> wrote:
> > > > >>
> > > > >> Hi All,
> > > > >>
> > > > >> I Wonder if someone could help me.
> > > > >>
> > > > >> Currently using ceph for primary storage and have
> > > > >> 'snapshot.backup.to.secondary' enabled.
> > > > >>
> > > > >> Since upgrading to 4.15 the volume snapshots do not seem to be
> > getting
> > > > >> deleted from the secondary storage. Could this be a bug?
> > > > >>
> > > > >> Also when logged in as the main admin account when navigating to
> > > > 'Storage /
> > > > >> Snapshots' an Error 500 is returned with the following error in
> the
> > > > logs:
> > > > >>
> > > > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > > > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> > > unhandled
> > > > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > > > >> java.lang.NullPointerException
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > > > >> at
> > com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > > > >> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > > > >> at
> com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > > > >> at
> > > > >>
> > com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > > > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > > > >> at
> > com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > > > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > > > >> at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > > > >> at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > > > >> at
> > > > >>
> > org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > > > >> at
> > > > >>
> > > >
> > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > >> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > > > >> at
> > > > >>
> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > > > >> at
> > > > >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > > > >> at
> > > > >> org.eclipse.jetty.io
> > > > >>
> > > .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > > > >> at org.eclipse.jetty.io
> > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > > > >> at
> > > > >>
> > > >
> > org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > > > >> at org.eclipse.jetty.io
> > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > >> at
> > > > >> org.eclipse.jetty.io
> > .ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > > > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > > > >>
> > > > >
> > > > >
> > > > > --
> > > > >
> > > > > Andrija Panić
> > > >
> > >
> >
>
