Snapshots GC from DB and XenServer Primary Storage garbage

[andrijapanicsb]

snapshot housekeeping needs
[ ] refractoring AND
[ ] fixing snapshot_store_ref garbage AND
[ ] XenServer garbage on Prim Stor.

For details please see my comment: #3969 (comment)

Problem 1

• When snapshots are deleted and the GC runs, the PRIMARY references (role_type=rpimary) are left in snapshot_store_ref table forever - when we successfully create a snapshot, we remove it from the Primary storage (we copy/export full snapshot to Secondary Storage and it's removed from Primary immediately) - so we also then need to remove the PRIMARY reference at the same time (like it's done for i.e. XenServer - but has XS has other issues, read below)

Reproduce the issue:

• set storage.cleanup.interval=60 (seconds),
• keep the defaults snapshot.backup.to.secondary=TRUE,
• spin a VM (1 or more volumes), VMware or KVM
• create snapshots
• delete snapshots
• wait for GC to kicks in: tail -f /var/log/cloudstack/management/management-server.log | grep "StorageManager-Scavenger"
• check the snapshot_store_ref table - rows are left where role_type=primary

Problem 2

• XenServer snapshots are chained (each new snap is a child of the previous parent snapshot) - this is NOT how it works for KVM/VMware, thus a bit different flow needed for XS
• As it seems, we always export the "full" snapshots to the Secondary STorage (see below steps to reproduce) so the parent/child relation in DB becomes nonsense (should we remove it?)
• Due to the parent/child relation, previous snaps can not be removed (the code and how it's implemented, not really on XS side - on XS side you can simply delete any snap and the XS will do it's coalescing in the background i.e. not immediately)
• The current code (as of PR 3969) will actually remove all parents post-mortem after all the child snaps are removed - i.e. it will remove all IMAGE reference records from the snapshots_store_ref gable when the last (child) is deleted: the last snap is deleted on Primary Storage (older/parent snaps are NOT, since their PRIMARY references is missing at that moment, read below...) and all snaps in the chain (all parents of that last child snap) are removed successfully also on the Secondary storage 👍 - so here there is garbage left on Primary Storage (even though ACS DB tells otherwise) 👎
• How code currently works (observed by testing!): Currently, when a new snap is created for XS volume, the previous snap is deleted - that is, the snap itself on Primary is not deleted (and as it seems it should be) but the PRIMARY reference in snap_store_ref table is removed for the previous snap, so later GC doesn't find it and it never gets deleted from the Primary storage.
• How it should work (as it seems?): when the previous snap is deleted (after new one is created and backed to the Secondary Storage successfully) - then ACS should really delete it on the Primary Storage (ignore the nonsense parent/child in code, as it CAN be deleted in i.e. XenCenter) - and continue (as before) to remove the PRIMARY reference in snap_store_ref table - this is how it works with KVM/VMware (once we move the template to Sec Stor, we delete it on Primary Storage)
  -- Idea: why not delete even the last snap from the Primary Storage - any "create template, create volume" operations work by reading the snap from the Secondary Storage - never from Primary - so we do NOT need it - same as with KVM and VMware) - this all assuming we are backing up the snap to Secondary Storage

Reproduce the issue:

• Spin XenServer VM - same behaviour for ROOT/DATA volume - but easier to observe things on DATA - so have 1 DATA volume attached to a VM
• write 10MB of data to volume (dd... bs=10M count=1), create "snap1" (use that name), write a total of 20MB (dd... bs=20M count=1), create "snap2", write a total of 30MB (dd... bs=30M count=1), create "snap3"
• We now have snap1 (parent to) snap2 (parent to) snap3 (last child) - before and after each snap creation, observe the snapshot_store_ref records and observe how the PRIMARY reference is deleted for the previous snap when a new one is created - now we have PRIMARY ref only for "snap3"
• Delete snap1 - even though the API/deletion is successful, in the mgmt logs you'll see that it reports that this snap has children and you can observe nothing is deleted in Primary Storage (use XenCenter to confirm the existence of the "snap1" which is the name we have the snap during its creation) and also observe nothing is removed on the Secondary Storage - only the main snap records in the "snapshots" table is marked as DESTROYED and it's IMAGE references in snap_store_ref is also marked as DESTROYED
• Delete snap2 - identical thing happens as with snap1 - it has a child (snap3), so nothing is really deleted
• Delete snap3 - observe how it is deleted properly - all 3 images are immediately deleted on the Secondary Storage BUT only the snap3 is deleted on the Primary storage
• This leaves "snap1" and "snap2" left on the Primary STorage (confirm via XenCenter) - as a workaround we can now manually delete those 2 snaps via XenCenter (in any order) and they will be eventually removed in the VHD chain (takes some time)
  -- after 2 snaps are manually removed via XenCetner, internal coalescing of snaps can be monitored with: watch -n 10 vhd-util scan -f -a -c -m /run/sr-mount/ff774530-b9b0-776d-ab4c-2df83dee87e5/3421297d-8bf3-41bc-b87f-3757825b7ea7.vhd -p (sr-mount//.vhd - it takes a few minutes (or more if large volume?)

Some graphic (2 XS volumes and their snaps):
26 hourly snaps (even though max.delta.snaps=16) - results in the 26-snaps-long chain on XS side:

[andrijapanicsb]

Observation from logs:
XenServer removes previous snapshots from the "primary storage" when a new one is created - it does NOT delete it really, but deletes the PRIMARY row in the snap_store_ref table, thus the garbage is left on Primary Store while the reference is deleted from the snap_store_ref - and later GC is not picking it up as the row/reference is not there.... Stupid implementation by all means:

[root@ref-trl-774-k-M7-apanic-mgmt1 ~]# grep 301a4ad6 /var/log/cloudstack/management/management-server.log | grep -v "queryAsyncJobResult"
2020-04-09 16:29:45,717 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-12:ctx-56cd28cc job-592) (logid:301a4ad6) Executing AsyncJobVO {id:592, userId: 2, accountId: 2, instanceType: Snapshot, instanceId: 85, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo: {"quiescevm":"false","httpmethod":"GET","ctxAccountId":"2","uuid":"ba2df407-1772-4668-9327-026af717dbce","cmdEventType":"SNAPSHOT.CREATE","asyncBackup":"false","response":"json","ctxUserId":"2","volumeId":"05c88236-1aa6-44c3-9bf9-bad4edfc34e5","name":"snap4","ctxStartEventId":"1274","id":"85","ctxDetails":"{"interface com.cloud.storage.Snapshot":"ba2df407-1772-4668-9327-026af717dbce","interface com.cloud.storage.Volume":"05c88236-1aa6-44c3-9bf9-bad4edfc34e5"}","_":"1586449031328"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid:
32988805007466, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2020-04-09 16:29:45,743 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-12:ctx-56cd28cc job-592 ctx-eabcd3e5) (logid:301a4ad6) Sync job-593 execution on object VmWorkJobQueue.22
...
...
2020-04-09 16:29:50,328 DEBUG [c.c.a.t.Request] (Work-Job-Executor-8:ctx-b9c690a2 job-592/job-593 ctx-34f207e8) (logid:301a4ad6) Seq 2-5707749577738682461: Executing: { Cmd , MgmtId: 32988805007466, via: 2(ref-trl-774-k-M7-apanic-xs1), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"ec235cfb-3e6e-40aa-9515-e6943b8e2241","volume":{"uuid":"05c88236-1aa6-44c3-9bf9-bad4edfc34e5","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"39bf30d6-f959-359d-b974-b8ebd2d8727f","id":5,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1/?ROLE=Primary&STOREUUID=39bf30d6-f959-359d-b974-b8ebd2d8727f","isManaged":false}},"name":"xen-data-1","size":1073741824,"path":"dd772879-f006-41ec-b09e-db5699f7a7fb","volumeId":54,"vmName":"i-2-22-VM","accountId":2,"format":"VHD","provisioningType":"THIN","id":54,"deviceId":1,"hypervisorType":"XenServer"},"parentSnapshotPath":"ffda9432-b5c2-41db-ac36-2321b8ed92b3","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"39bf30d6-f959-359d-b974-b8ebd2d8727f","id":5,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1/?ROLE=Primary&STOREUUID=39bf30d6-f959-359d-b974-b8ebd2d8727f","isManaged":false}},"vmName":"i-2-22-VM","name":"snap4","hypervisorType":"XenServer","id":85,"quiescevm":false,"parents":["ffda9432-b5c2-41db-ac36-2321b8ed92b3"],"physicalSize":0}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/54","volume":{"uuid":"05c88236-1aa6-44c3-9bf9-bad4edfc34e5","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"39bf30d6-f959-359d-b974-b8ebd2d8727f","id":5,"poolType":"NetworkFilesystem","host":"10.2.0.16","path":"/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1","port":2049,"url":"NetworkFilesystem://10.2.0.16/acs/primary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-xs-pri1/?ROLE=Primary&STOREUUID=39bf30d6-f959-359d-b974-b8ebd2d8727f","isManaged":false}}"name":"xen-data-1","size":1073741824,"path":"dd772879-f006-41ec-b09e-db5699f7a7fb","volumeId":54,"vmName":"i-2-22-VM","accountId":2,"format":"VHD","provisioningType":"THIN","id":54,"deviceId":1,"hypervisorType":"XenServer"},"parentSnapshotPath":"snapshots/2/54/a585fa13-201e-40ef-b586-11822133287e.vhd","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"NFS://10.2.0.16/acs/secondary/ref-trl-774-k-M7-apanic/ref-trl-774-k-M7-apanic-sec1","_role":"Image"}},"vmName":"i-2-22-VM","name":"snap4","hypervisorType":"XenServer","id":85,"quiescevm":false,"parents":["snapshots/2/54/14c13d66-53f4-4003-a284-cf266fe1ee3c.vhd","snapshots/2/54/151ca037-2b00-44a3-abb2-b212962b51be.vhd","snapshots/2/54/a585fa13-201e-40ef-b586-11822133287e.vhd"],"physicalSize":0}},"executeInSequence":true,"options": ...
{"fullSnapshot":"true"},"options2":{},"wait":21600}}] }

2020-04-09 16:29:52,641 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) No file SR found for path: /var/cloud_mount/569d499d-d7f7-31d4-b124-baf0ad97e161/snapshots/2/54
2020-04-09 16:29:52,641 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) Creating file SR for path [/var/cloud_mount/569d499d-d7f7-31d4-b124-baf0ad97e161/snapshots/2/54] on host [fb4b5939-8702-46b7-bb02-7f43ab6bb9b8]
2020-04-09 16:30:04,285 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) Host 10.2.3.240 OpaqueRef:3d230637-af2f-e354-2db8-e0fccbe62d2b: Removing SR
2020-04-09 16:30:04,325 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) Host 10.2.3.240 OpaqueRef:d3f62ef8-cbbf-3d41-f4bd-c8fb4252adaa: Unplugging pbd
2020-04-09 16:30:04,651 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) Host 10.2.3.240 OpaqueRef:3d230637-af2f-e354-2db8-e0fccbe62d2b: Forgetting

2020-04-09 16:30:04,667 DEBUG [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) Successfully destroyed snapshot on volume: dd772879-f006-41ec-b09e-db5699f7a7fb execept this current snapshot ec235cfb-3e6e-40aa-9515-e6943b8e2241
2020-04-09 16:30:04,667 INFO [c.c.h.x.r.XenServerStorageProcessor] (DirectAgent-78:ctx-24a25b86) (logid:301a4ad6) New snapshot details: SnapshotTO[datastore=null|volume=null|pathsnapshots/2/54/d4e824b5-f9ac-469f-b94f-dbdf39e8b682.vhd]
...
...

From XS snapshots, we can create template/volume:

• In both cases (creating a template of a volume) - the existing folder holding the snaphosts on the Secondary Storage is mounted as a new SRs on XS host and template is created (again inside a new SR from a new folder where the template is put - previously created on the Sec Stor). For creating a volume out of a snap, just the existing Secondary Storage snap folder is mounted and whole image copied back to Primary Storage
• i.e. we NEVER read original snap from the PRIMARY storage - confirmed by manually deleting all snaps of a volume and being able to create tempalte/volume from some snap.
• i.e. we should really delete all older snaps (as it seems) when we create a new one, from the Primary Storage - and keep all snaps on Secondary Storage (like so far)

[andrijapanicsb]

Thinking aloud about the correct workflow for different hypervisors, after being busy with the snapshots issues on PR #3969 for 40+h...

XS

• XS snap issues: although we "try", we don't really delete older snaps when the current/new one when it's created - we should fix this, and then all older snaps are deleted from Primary and so are their references PRIMARY in snap_store_ref.
• We are chaining/making parent-child relation in snap_store_ref table ... Remove the relation? we are copying over FULL snaps from Primary to Secondary always and the snap is NEVER used from Primary storage in order to create new volume or new template.
• Implement the same logic as for KVM/VMware - once the snap is Backed Up to Secondary Storage - remove it completely from the Primary Storage (this assumes snapshot.backup.to.secondary=FALSE continues to be NOT supported)

VMware (current state)

• VMware - when snapshots is created on Secondary Storage, nothing is left on Primary, although we leave the PRIMARY row in snap_Store_ref (i.e. should be removed)
• Deleting the template will delete it on Secondary Storage immediately, and mark all snap_stor_ref -rows as DESTROYED, and same happens for snap row in the main snapshots table.
• GC seems to be looking ONLY for IMAGE references rows in snap_store_ref table - it's looking only for those in the DESTROYED state where the corresponding row in the main snapshots table does NOT have a "removed" date set. It seems (conclusion by testing...) that it does NOT look for (was not designed for?) to even look for PRIMARY references in snap_store_ref table, as the identical behaviour is observed for KVM - so GC does remove the snap from Secondary Storage if not already removed (should be, unless SSVM was down when we deleted the snap via API/UI) and remove the IMAGE row from snap_store_ref
• ^^^ One more reason that we "copy" the logic from XS, to remove the PRIMARY row when the new snap is created (copied to Secondary Storage) - so we only keep IMAGE rows when a new snap is created in snap_store_ref table

KVM (current state)

• KVM - identical stuff happens as with VMware ( i.e. PRIMARY row is left for whatever reason when snap is created, while there is NO snap on QCOW2 file - but keep in mind that when NOT backing up to Sec Storage (works with KVM+Ceph only), then we do need/have the PRIMARY row
• as GC seems not designed to remove PRIMARY ref rows???, it's never removed... (GC does remove image from Secondary Storage if not deleted previously as it should (i.e. SSVM was down during snap deletion) and only removes the IMAGE ref row)

We still do have a special case of "snapshot.backup.to.secondary=FALSE" which works for KVM+Ceph only and there we have only the PRIMARY row created in the first place... that seems to be working fine? (GC stuff, deletion in both cases when we backup or not to Secondary Storage

[nvazquez]

Problem 1 is fixes by PR 4188

Problem 2 is only a problem on certain XenServer versions, confirmed on 7.0 and 7.1, but not an issue on XCPng 7.4 and 7.6 (under the same CloudStack version)

Tests:

• Created an hourly backup snapshot for a ROOT volume on two 4.13.0.0 environments. Env1 with a XenServer 7.0 host and Env2 with an XCPng7.6.

Results after 20+ hours of scheduled snapshots:

• Env1: Output of: vhd-util scan -f -a -c -m 0a597747-62eb-4adc-be1f-0c210b153194.vhd -p
  

• Env2: Output of: vhd-util scan -f -a -c -m e893b000-a72c-45ee-8047-40ea3a6b55e6.vhd -p
  

[yadvr]

Is this still a blocker or was a fix merged @andrijapanicsb @nvazquez ?

[nvazquez]

Fixed on PR #4188, closing this issue