Backup valid, but still unrestorable?

tarianjed · March 30, 2022, 6:41am

Oh, ya I was just referring to this work I have been doing:

Database recreate desperately needs improvement

opened 06:17PM - 05 Jan 20 UTC

performance issue local database issue

- [x] I have searched open and closed issues for duplicates. ----------------…------------------------ ## Environment info - **Duplicati version**: 2.0.4.21_experimental - **Operating system**: LInux - **Backend**: B2 ## Description Unacceptably poor performance of database recreate. And I have to trigger it way more often than I've wanted over the course of a year of running Duplicati. Is this fundamental usability issue getting prioritized? (A similar complaint #2889 is now over 2 years old.) ## Steps to reproduce 1. Create a reasonably big backup to a backend like B2 2. Trigger a database recreate, and compare the time it takes with the time it originally takes to create the first backup (recreate is considerably slower) To corrupt the sqlite database on demand, simply do this: 1. Start a backup 2. Force a crash of the server running duplicati (reboot it or otherwise prevent it from completing) 3. Confirm that your sqlite database is corrupted 4. May have to repeat a couple times to get it corrupted (doesn't take much effort, at least under linux) - **Actual result**: Database recreate takes longer than initial backup - **Expected result**: The recreate should take considerably less time, should never fail, and should inform the user what it's doing at each step. If the fundamental problem cannot be fixed because there are other higher-priority issues (for a backup tool, I cannot imagine anything higher priority than robustness of the metadata), then at least I would like to see a warning message if there are more than perhaps 10,000 metadata records to the effect that "Hey, this is going to be really, really slow and might not work; you might rather throw away all your savesets and start over instead." ## Screenshots ## Debug log I captured some info on the problem this most recent time, running the re-create for 10 days. It never finished so I hit the stop button. After a few minutes I got this: ``` Error while running main-b2 Missing block for blocklisthash: AfsxZ3bG4EUxcT6Ig751uWz350M ``` Then I could get the following log: ``` { "MainOperation": "Repair", "RecreateDatabaseResults": { "MainOperation": "Repair", "ParsedResult": "Success", "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)", "EndTime": "2020-01-02T19:31:57.298724Z", "BeginTime": "2019-12-22T20:02:38.73636Z", "Duration": "10.23:29:18.5623640", "MessagesActualLength": 0, "WarningsActualLength": 0, "ErrorsActualLength": 0, "Messages": null, "Warnings": null, "Errors": null, "BackendStatistics": { "RemoteCalls": 1493, "BytesUploaded": 0, "BytesDownloaded": 287066911076, "FilesUploaded": 0, "FilesDownloaded": 1492, "FilesDeleted": 0, "FoldersCreated": 0, "RetryAttempts": 0, "UnknownFileSize": 0, "UnknownFileCount": 0, "KnownFileCount": 0, "KnownFileSize": 0, "LastBackupDate": "0001-01-01T00:00:00", "BackupListCount": 0, "TotalQuotaSpace": 0, "FreeQuotaSpace": 0, "AssignedQuotaSpace": 0, "ReportedQuotaError": false, "ReportedQuotaWarning": false, "MainOperation": "Repair", "ParsedResult": "Success", "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)", "EndTime": "0001-01-01T00:00:00", "BeginTime": "2019-12-22T20:02:38.455934Z", "Duration": "00:00:00", "MessagesActualLength": 0, "WarningsActualLength": 0, "ErrorsActualLength": 0, "Messages": null, "Warnings": null, "Errors": null } }, "ParsedResult": "Warning", "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)", "EndTime": "2020-01-02T19:32:26.2636Z", "BeginTime": "2019-12-22T20:02:38.455929Z", "Duration": "10.23:29:47.8076710", "MessagesActualLength": 2990, "WarningsActualLength": 1, "ErrorsActualLength": 0, "Messages": [ "2019-12-22 12:02:38 -08 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started", "2019-12-22 12:02:38 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()", "2019-12-22 12:02:40 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (1.80 KB)", "2019-12-22 12:02:44 -08 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-RebuildStarted]: Rebuild database started, downloading 5 filelists", "2019-12-22 12:02:44 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180131T060331Z.dlist.zip.aes (653 bytes)", "2019-12-22 12:02:45 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20180131T060331Z.dlist.zip.aes (653 bytes)", "2019-12-22 12:02:45 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20180907T182059Z.dlist.zip.aes (4.80 MB)", "2019-12-22 12:02:57 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20180907T182059Z.dlist.zip.aes (4.80 MB)", "2019-12-22 12:02:57 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190403T134113Z.dlist.zip.aes (19.63 MB)", "2019-12-22 12:03:38 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20190403T134113Z.dlist.zip.aes (19.63 MB)", "2019-12-22 12:05:21 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190619T110106Z.dlist.zip.aes (29.37 MB)", "2019-12-22 12:06:21 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20190619T110106Z.dlist.zip.aes (29.37 MB)", "2019-12-22 12:13:13 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20190727T082143Z.dlist.zip.aes (29.38 MB)", "2019-12-22 12:14:14 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20190727T082143Z.dlist.zip.aes (29.38 MB)", "2019-12-22 12:29:53 -08 - [Information-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FilelistsRestored]: Filelists restored, downloading 930 index files", "2019-12-22 12:29:53 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i002f3cff8cab4468abf275a59cf31ffc.dindex.zip.aes (348.15 KB)", "2019-12-22 12:29:54 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i002f3cff8cab4468abf275a59cf31ffc.dindex.zip.aes (348.15 KB)", "2019-12-22 12:29:54 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i00d869e9950d419686e2c2e2cc53b035.dindex.zip.aes (272.01 KB)", "2019-12-22 12:29:55 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i00d869e9950d419686e2c2e2cc53b035.dindex.zip.aes (272.01 KB)", "2019-12-22 12:29:56 -08 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i01ae1ede7d2d40f290dfec3fa84d4511.dindex.zip.aes (377.72 KB)" ], "Warnings": [ "2019-12-30 03:49:00 -08 - [Warning-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-FailedRebuildingWithFile]: Failed to use information from duplicati-b6a5683cc5f6249e29886c5618b2e5878.dblock.zip.aes to rebuild database: Object reference not set to an instance of an object" ], "Errors": [], "BackendStatistics": { "RemoteCalls": 1493, "BytesUploaded": 0, "BytesDownloaded": 287066911076, "FilesUploaded": 0, "FilesDownloaded": 1492, "FilesDeleted": 0, "FoldersCreated": 0, "RetryAttempts": 0, "UnknownFileSize": 0, "UnknownFileCount": 0, "KnownFileCount": 0, "KnownFileSize": 0, "LastBackupDate": "0001-01-01T00:00:00", "BackupListCount": 0, "TotalQuotaSpace": 0, "FreeQuotaSpace": 0, "AssignedQuotaSpace": 0, "ReportedQuotaError": false, "ReportedQuotaWarning": false, "MainOperation": "Repair", "ParsedResult": "Success", "Version": "2.0.4.21 (2.0.4.21_experimental_2019-06-28)", "EndTime": "0001-01-01T00:00:00", "BeginTime": "2019-12-22T20:02:38.455934Z", "Duration": "00:00:00", "MessagesActualLength": 0, "WarningsActualLength": 0, "ErrorsActualLength": 0, "Messages": null, "Warnings": null, "Errors": null } } ```

If you could post more info about that registering missing blocks and maybe track down the exact message and post it there that would be great.