Verify that snapshots, recovery from snapshots works

[djmitche]

In working on #3185, I noticed that snapshots are very small. Do they contain all of the required data?

Let's also verify that setting up a new replica from a snapshot works, and that it fails as expected if there is no snapshot or versions are missing.

[ryneeverett]

By "verify" do you mean writing automated tests? Would be very nice if practical.

[djmitche]

I want to verify it manually. I think there are automated tests for this, so if manual verification fails, then I'll need to see why those didn't catch it.

[djmitche]

I set up the sync server (since local sync does not use snapshots) with --snapshot-versions=2 and ran a bunch of task sync against it. A .dump on the server's DB shows a snapshot from a few versions ago, and a lot of versions.

Then I removed the local SQLite DB and ran task sync again. I've changed all of the logging in sync.rs to use println! so I can see it.

⸩ task sync
storage is empty; attempting to apply a snapshot
applied snapshot for version 89290176-4393-4cac-81c2-e61faad6c140
beginning sync outer loop
beginning sync inner loop
applying version 20c91c79-6e5c-48b0-86cb-17f7e9c05a92 from server
rebasing local operations onto server operation Create { uuid: 36096103-44f7-41b4-ac3a-a925ef5338a6 }
rebasing local operations onto server operation Update { uuid: 36096103-44f7-41b4-ac3a-a925ef5338a6, property: "description", value: Some("foo Tue 26 Dec 2023 10:40:58 AM EST"), timestamp: 2023-12-26T15:40:58.416615255Z }
rebasing local operations onto server operation Update { uuid: 36096103-44f7-41b4-ac3a-a925ef5338a6, property: "entry", value: Some("1703605258"), timestamp: 2023-12-26T15:40:58.419205080Z }
rebasing local operations onto server operation Update { uuid: 36096103-44f7-41b4-ac3a-a925ef5338a6, property: "modified", value: Some("1703605258"), timestamp: 2023-12-26T15:40:58.421698422Z }
rebasing local operations onto server operation Update { uuid: 36096103-44f7-41b4-ac3a-a925ef5338a6, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:40:58.426246100Z }
beginning sync inner loop
applying version cae96027-54ad-4a48-a2b6-4e0d6607e55d from server
rebasing local operations onto server operation Create { uuid: d39a217a-02f2-4de2-82eb-f270b5045a7c }
rebasing local operations onto server operation Update { uuid: d39a217a-02f2-4de2-82eb-f270b5045a7c, property: "description", value: Some("foo Tue 26 Dec 2023 10:40:59 AM EST"), timestamp: 2023-12-26T15:40:59.601333635Z }
rebasing local operations onto server operation Update { uuid: d39a217a-02f2-4de2-82eb-f270b5045a7c, property: "entry", value: Some("1703605259"), timestamp: 2023-12-26T15:40:59.604706883Z }
rebasing local operations onto server operation Update { uuid: d39a217a-02f2-4de2-82eb-f270b5045a7c, property: "modified", value: Some("1703605259"), timestamp: 2023-12-26T15:40:59.607761733Z }
rebasing local operations onto server operation Update { uuid: d39a217a-02f2-4de2-82eb-f270b5045a7c, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:40:59.612435959Z }
beginning sync inner loop
applying version 2b5db2b8-b0a8-434c-9a4b-c7567ccf9593 from server
rebasing local operations onto server operation Create { uuid: 6efb6435-1d2b-4cdb-852d-3aee9477694f }
rebasing local operations onto server operation Update { uuid: 6efb6435-1d2b-4cdb-852d-3aee9477694f, property: "description", value: Some("foo Tue 26 Dec 2023 10:41:00 AM EST"), timestamp: 2023-12-26T15:41:00.784011659Z }
rebasing local operations onto server operation Update { uuid: 6efb6435-1d2b-4cdb-852d-3aee9477694f, property: "entry", value: Some("1703605260"), timestamp: 2023-12-26T15:41:00.786964026Z }
rebasing local operations onto server operation Update { uuid: 6efb6435-1d2b-4cdb-852d-3aee9477694f, property: "modified", value: Some("1703605260"), timestamp: 2023-12-26T15:41:00.789715816Z }
rebasing local operations onto server operation Update { uuid: 6efb6435-1d2b-4cdb-852d-3aee9477694f, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:41:00.794051961Z }
beginning sync inner loop
applying version 66418e14-3371-452f-8e6e-6b29571d7f9f from server
rebasing local operations onto server operation Create { uuid: 14102e79-00d5-409f-a9b0-15c41a95986e }
rebasing local operations onto server operation Update { uuid: 14102e79-00d5-409f-a9b0-15c41a95986e, property: "description", value: Some("foo Tue 26 Dec 2023 10:41:01 AM EST"), timestamp: 2023-12-26T15:41:01.965560259Z }
rebasing local operations onto server operation Update { uuid: 14102e79-00d5-409f-a9b0-15c41a95986e, property: "entry", value: Some("1703605261"), timestamp: 2023-12-26T15:41:01.969364848Z }
rebasing local operations onto server operation Update { uuid: 14102e79-00d5-409f-a9b0-15c41a95986e, property: "modified", value: Some("1703605261"), timestamp: 2023-12-26T15:41:01.972776752Z }
rebasing local operations onto server operation Update { uuid: 14102e79-00d5-409f-a9b0-15c41a95986e, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:41:01.977058663Z }
beginning sync inner loop
applying version d2167d50-b6f9-4106-bea5-e5a0004a9b26 from server
rebasing local operations onto server operation Create { uuid: 102e799d-2835-4db8-8d8b-4a4dd8175585 }
rebasing local operations onto server operation Update { uuid: 102e799d-2835-4db8-8d8b-4a4dd8175585, property: "description", value: Some("foo Tue 26 Dec 2023 10:41:03 AM EST"), timestamp: 2023-12-26T15:41:03.149653727Z }
rebasing local operations onto server operation Update { uuid: 102e799d-2835-4db8-8d8b-4a4dd8175585, property: "entry", value: Some("1703605263"), timestamp: 2023-12-26T15:41:03.153265916Z }
rebasing local operations onto server operation Update { uuid: 102e799d-2835-4db8-8d8b-4a4dd8175585, property: "modified", value: Some("1703605263"), timestamp: 2023-12-26T15:41:03.157034033Z }
rebasing local operations onto server operation Update { uuid: 102e799d-2835-4db8-8d8b-4a4dd8175585, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:41:03.160662354Z }
beginning sync inner loop
applying version 40696202-85cc-4729-9539-55faf1453276 from server
rebasing local operations onto server operation Create { uuid: 2defe258-06da-417e-a7c4-79771f7c6d65 }
rebasing local operations onto server operation Update { uuid: 2defe258-06da-417e-a7c4-79771f7c6d65, property: "description", value: Some("foo Tue 26 Dec 2023 10:41:04 AM EST"), timestamp: 2023-12-26T15:41:04.333355715Z }
rebasing local operations onto server operation Update { uuid: 2defe258-06da-417e-a7c4-79771f7c6d65, property: "entry", value: Some("1703605264"), timestamp: 2023-12-26T15:41:04.336990509Z }
rebasing local operations onto server operation Update { uuid: 2defe258-06da-417e-a7c4-79771f7c6d65, property: "modified", value: Some("1703605264"), timestamp: 2023-12-26T15:41:04.340307293Z }
rebasing local operations onto server operation Update { uuid: 2defe258-06da-417e-a7c4-79771f7c6d65, property: "status", value: Some("pending"), timestamp: 2023-12-26T15:41:04.344344071Z }
beginning sync inner loop
no child versions of 40696202-85cc-4729-9539-55faf1453276

So, that all looks good!

[djmitche]

Dumping the snapshot after it's downloaded from the server shows the expected:

[/home/dustin/p/taskwarrior/taskchampion/taskchampion/src/taskdb/snapshot.rs:90] &all_tasks = SnapshotTasks(
    [                                                                
        (                                
            b22dc22d-80ee-4a25-9e79-5ec1d4ff2c5f,                    
            {                       
                "status": "pending",     
                "modified": "1703604674",        
                "description": "foo Tue 26 Dec 2023 10:31:14 AM EST",
                "entry": "1703604674",                               
            },                                   
        ),                                                           
        (                                
            773f3e3d-4681-4e9a-b246-6a00b5b29fd0,
            {                                                        
                "status": "pending",     
                "description": "foo Tue 26 Dec 2023 10:32:05 AM EST",
                "entry": "1703604725",   
                "modified": "1703604725",                            
            },                                   
        ),                                                           

That's stored with flate2 which is probably why it was so small.

[djmitche]

If I delete the snapshot on the server:

⸩ task sync
storage is empty; attempting to apply a snapshot
beginning sync outer loop
beginning sync inner loop
no child versions of 00000000-0000-0000-0000-000000000000
no changes to push to server

but

⸩ echo $?
0

I think that makes sense -- it looks like an empty server. We could probably do better here (#3233), but this is operating as designed. A subsequent task sync that tries to add new operations will fail:

⸩ task sync
beginning sync outer loop
beginning sync inner loop
no child versions of cae96027-54ad-4a48-a2b6-4e0d6607e55d
sending 5 operations to the server
sending new version to server
new version rejected; must be based on 40696202-85cc-4729-9539-55faf1453276
beginning sync outer loop
beginning sync inner loop
no child versions of cae96027-54ad-4a48-a2b6-4e0d6607e55d
sending 5 operations to the server
sending new version to server
new version rejected; must be based on 40696202-85cc-4729-9539-55faf1453276
TASKRC override: /home/dustin/p/taskwarrior/.taskrc
Failed to synchronize with server
⸩ echo $?
2

A similar thing happens if I delete a version from the server that is newer than the latest snapshot.

I think this is all operating as designed.