False positive missing chunks when running check and backup concurrently

Bug
,
#1

Please describe what you are doing to trigger the bug:
Running duplicacy backup concurrently with duplicacy check

Please describe what you expect to happen (but doesn’t):
I expect the check to ignore backup in progress and not report that some chunks are missing.

Please describe what actually happens (the wrong behaviour):
check command reports a lot of chunks missing, from the currently running backup. Obviously.

Running check after the backup completed yields “all tip-top” result, as expected.

In other words, check command must ignore snapshots that have not been finalized. Otherwise this creates a lot of noise in the logs and unnecessary stomach drops in admins when they run check while somebody else is running backup.

As a side note, new schedule for check and backup in web ui perhaps should not default to the same time. That’s how I found this issue.

To reproduce, run concurrently:

Terminal one

alexmbp:~ alex$ duplicacy backup
Running script /Users/alex/.duplicacy/scripts/pre-backup
Storage set to sftp://alex@tuchka.home.saspus.com//Backups/duplicacy
Last backup at revision 485 found
Indexing /Users/alex
Loaded 50 include/exclude pattern(s)
[very busy backing up tons of files to revision 486]

Terminal two:

alexmbp:~ alex$ duplicacy check
Storage set to sftp://alex@tuchka.home.saspus.com//Backups/duplicacy
Listing all chunks
All chunks referenced by snapshot alexmbp at revision 1 exist
All chunks referenced by snapshot alexmbp at revision 81 exist
All chunks referenced by snapshot alexmbp at revision 105 exist
...
All chunks referenced by snapshot alexmbp at revision 485 exist
Chunk e55b80c00c929ff3b98234daac95e85179b91ccd6f539a621200bbc43a27a5e2 referenced by snapshot alexmbp at revision 486 does not exist
Chunk eee9e3b98ceb0afa327c03055d6799d033370dc02b7d829e48ffbb1785e44371 referenced by snapshot alexmbp at revision 486 does not exist
Chunk e526717a4ec58dcb31415b6de75a1517be0ddcc422979155c823a9b17e9baec9 referenced by snapshot alexmbp at revision 486 does not exist
Chunk e0356ef3ca0510b46a7a0aa05761a9a5bc652eecff496e0ccb00a4c218be2ceb referenced by snapshot alexmbp at revision 486 does not exist
Chunk d7837cb4cf54ea33bf59645d0e311032ba5fff709c2cb4ef1882ed9d955cb21e referenced by snapshot alexmbp at revision 486 does not exist
Chunk e7814a79ab82eadb9342953be68a5b1f245abb30183727e3c6eb4e93a899f9fc referenced by snapshot alexmbp at revision 486 does not exist
Some chunks referenced by snapshot alexmbp at revision 486 are missing
Some chunks referenced by some snapshots do not exist in the storage
[Aborts the check because apparently revision 486 is screwed up. Admin panics and rushes to check raid array status and prepares to restore from offsite backup before discovering this this is bogus error message]
2 Likes
#3

It also produces visually scary effect on Web UI dashboard - your storage size curve goes down to zero. I would say even really missing chunks in some snapshots should not cause “the whole storage failed” kind of display.

1 Like
#4

I don’t know how the check command could see the the snapshot file 486 but not the chunks. A snapsot file is always uploaded after all chunks have been uploaded.

#5

You are correct of course. Here’s some logs below. Apparently backup was completed 2 minutes before check command. Clocks are in sync. It may be latency in OneDrive - between chunks are uploaded and become “visible”. Snapshot file became “visible” before the chunks despite the fact it was uploaded after them (small vs bigger file size?). I cannot offer another explanation. You?

Machine 2 - WindowsUI
2019-03-21 02:29:16.581 DEBUG CHUNK_UPLOAD Chunk f4ea29edbda5082c1e5d3931150dc70407db203405a92f050bd86db0558ad9e8 has been uploaded
2019-03-21 02:29:17.194 DEBUG CHUNK_UPLOAD Chunk 923c7294054236cce137bbc31da4ef1ebe500088fc8bf7cd92716944fd0d204c has been uploaded
2019-03-21 02:29:17.257 DEBUG UPLOAD_FILE_CACHE Saved file snapshots/Machine2-Thunderbird/594 to the snapshot cache
2019-03-21 02:29:17.257 DEBUG ONEDRIVE_CALL PUT https://api.onedrive.com/v1.0/drive/root:/z-duplicacy-backups/snapshots/Machine2-Thunderbird/594:/content
2019-03-21 02:29:17.557 DEBUG UPLOAD_FILE Uploaded file snapshots/Machine2-Thunderbird/594
2019-03-21 02:29:17.558 INFO BACKUP_END Backup for C:\Users\Dima\AppData\Roaming\Thunderbird at revision 594 completed

Machine 1 - WebUI
2019-03-21 02:31:31.256 INFO SNAPSHOT_CHECK All chunks referenced by snapshot Machine2-Thunderbird at revision 593 exist
2019-03-21 02:31:32.355 WARN SNAPSHOT_VALIDATE Chunk f4ea29edbda5082c1e5d3931150dc70407db203405a92f050bd86db0558ad9e8 referenced by snapshot Machine2-Thunderbird at revision 594 does not exist
2019-03-21 02:31:32.355 WARN SNAPSHOT_VALIDATE Chunk 86b5bdfeb4db39ebc8fd3b134b6dc900a219e880466270192391388cecca69c7 referenced by snapshot Machine2-Thunderbird at revision 594 does not exist