FTP delete not atomic / verified / transactional (?)

Sami_Lehtinen · June 13, 2023, 7:50am

So this is finally getting fixed? Great (!) - Please check all cases when stuff is getting deleted.

Error during compact forgot a dindex file deletion, getting Missing file error next run.

opened 01:08AM - 07 Mar 20 UTC

bug backup corruption local database issue

- [x] I have searched open and closed issues for duplicates. ----------------…------------------------ ## Environment info - **Duplicati version**: 2.0.5.1 Beta - **Operating system**: Windows 10 Version 1909 - **Backend**: Google Drive ## Description Fatal error "Found 1 files that are missing from the remote storage, please run repair" at start of regular hourly backup after previous backup failed with "The remote server returned an error: (403) Forbidden." Looking into the databases (I keep a DB history via --run-script-before), the 403 left the DB corrupted. Remote data and profiling log indicate that compact deleted a dblock file and its dindex, however the DB RemoteOperation table lacks those rows (and everything after) for this backup, and Remotevolume table wrongly says that dindex should still be there, yet somehow rightly says that dblock should not... Emails on these were: ``` Failed: The remote server returned an error: (403) Forbidden. Details: System.Net.WebException: The remote server returned an error: (403) Forbidden. at Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile() at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend) at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager) at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task) at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result) at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method) Log data: 2020-03-03 13:02:17 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error System.Net.WebException: The remote server returned an error: (403) Forbidden. at Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile() at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend) at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager) at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() ``` then ``` Failed: Found 1 files that are missing from the remote storage, please run repair Details: Duplicati.Library.Interface.UserInformationException: Found 1 files that are missing from the remote storage, please run repair at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify(BackendManager backend, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task) at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result) at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method) Log data: 2020-03-03 13:40:30 -05 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes 2020-03-03 13:40:30 -05 - [Error-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteFiles]: Found 1 files that are missing from the remote storage, please run repair 2020-03-03 13:40:30 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error Duplicati.Library.Interface.UserInformationException: Found 1 files that are missing from the remote storage, please run repair at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify(BackendManager backend, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() ``` I'm not seeking to get this going soon, but will leave it alone for awhile for an analysis of the situation. This job was intentionally set with --number-of-retries=1 in the hope that a transient issue would error. I don't know where the 403 is from (possibly OAuth needing a token refresh?), but that seems to have done the breakage job. Possibly a compact operation is more sensitive than other spots in the backup? ## Steps to reproduce EDIT 1: See the Mar 14, 2020 "Developed steps to reproduce this issue well." [post below](https://github.com/duplicati/duplicati/issues/4129#issuecomment-599149786). Also note that this seems to be being reported in the forum more. See references from forum below [starting](https://github.com/duplicati/duplicati/issues/4129#issuecomment-1079014706) at Mar 25, 2022. Original Mar 6 2020 steps to reproduce were "Not really known" as noted below. 1. Not really known. You could try to arrange for a download error during second round of dblock downloads, to see if it will mess with the dblock+dindex delete that came after the first round of dblock downloads and the repackaged dblock+dindex uploads. 2. After above damage, run another backup. The one here was automatic by the same TrayIcon run. - **Actual result**: Failed: Found 1 files that are missing from the remote storage, please run repair - **Expected result**: Recovers and does backup. ## Screenshots ## Debug log Here are the bug report files for DB dated 12:56 PM (email was sent later at 13:02 though) and 13:40 PM. [bugreport.20190303_1256.zip](https://github.com/duplicati/duplicati/files/4301108/bugreport.20190303_1256.zip) [bugreport.20190303_1340.zip](https://github.com/duplicati/duplicati/files/4301112/bugreport.20190303_1340.zip) Here's the ending: ``` 2020-03-03 13:40:30 -05 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes 2020-03-03 13:40:30 -05 - [Error-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteFiles]: Found 1 files that are missing from the remote storage, please run repair 2020-03-03 13:40:30 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-PreBackupVerify]: PreBackupVerify took 0:00:00:08.333 2020-03-03 13:40:30 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error Duplicati.Library.Interface.UserInformationException: Found 1 files that are missing from the remote storage, please run repair at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify(BackendManager backend, String protectedfile) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() 2020-03-03 13:40:30 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize 2020-03-03 13:40:30 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000 2020-03-03 13:40:30 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:00:30.736 ``` Here's the compact and the 403: ``` 2020-03-03 12:42:05 -05 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there is 25.24% wasted space and the limit is 25% 2020-03-03 12:42:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-bbcbd4187d9cb48b0a22b0fe91722aa0b.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2020-03-03 12:42:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-bbcbd4187d9cb48b0a22b0fe91722aa0b.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000 2020-03-03 12:42:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-i15817fa246ab4f64b5e441d84bafcfe2.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2020-03-03 12:42:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-i15817fa246ab4f64b5e441d84bafcfe2.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000 2020-03-03 12:42:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationNothing]: Starting - RemoteOperationNothing 2020-03-03 12:42:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationNothing]: RemoteOperationNothing took 0:00:00:00.000 2020-03-03 12:42:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "C"."Name", "B"."Name", "B"."Hash", "B"."Size" FROM "IndexBlockLink" A, "RemoteVolume" B, "RemoteVolume" C WHERE "A"."IndexVolumeID" = "B"."ID" AND "A"."BlockVolumeID" = "C"."ID" AND "B"."Hash" IS NOT NULL AND "B"."Size" IS NOT NULL 2020-03-03 12:42:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "C"."Name", "B"."Name", "B"."Hash", "B"."Size" FROM "IndexBlockLink" A, "RemoteVolume" B, "RemoteVolume" C WHERE "A"."IndexVolumeID" = "B"."ID" AND "A"."BlockVolumeID" = "C"."ID" AND "B"."Hash" IS NOT NULL AND "B"."Size" IS NOT NULL took 0:00:00:00.000 2020-03-03 12:42:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:42:05 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes (50.05 MB) 2020-03-03 12:46:23 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 50.05 MB in 00:04:17.9420016, 198.67 KB/s 2020-03-03 12:46:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes (50.05 MB) 2020-03-03 12:46:23 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:04:17.942 2020-03-03 12:46:23 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:46:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b52e9039635314dfdb0cc00d7d38bff00.dblock.zip.aes (43.42 MB) 2020-03-03 12:50:08 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 43.42 MB in 00:03:44.8483951, 197.75 KB/s 2020-03-03 12:50:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b52e9039635314dfdb0cc00d7d38bff00.dblock.zip.aes (43.42 MB) 2020-03-03 12:50:08 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:03:44.848 2020-03-03 12:50:08 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:50:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b2a3eb954e16f422cae85fe3202b56fe2.dblock.zip.aes (20.94 MB) 2020-03-03 12:51:59 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 20.94 MB in 00:01:51.3706484, 192.54 KB/s 2020-03-03 12:51:59 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b2a3eb954e16f422cae85fe3202b56fe2.dblock.zip.aes (20.94 MB) 2020-03-03 12:51:59 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:01:51.370 2020-03-03 12:52:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut 2020-03-03 12:52:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-b44bbdf41c6c64fe8bd6c0cd52826827a.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2020-03-03 12:52:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-b44bbdf41c6c64fe8bd6c0cd52826827a.dblock.zip.aes", "Blocks", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000 2020-03-03 12:52:00 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-i3662fdc138524598acc0ac3e2e820378.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2020-03-03 12:52:00 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (881, "duplicati-i3662fdc138524598acc0ac3e2e820378.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); took 0:00:00:00.000 2020-03-03 12:52:00 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bbcbd4187d9cb48b0a22b0fe91722aa0b.dblock.zip.aes (50.00 MB) 2020-03-03 12:56:23 -05 - [Profiling-Duplicati.Library.Main.BackendManager-UploadSpeed]: Uploaded 50.00 MB in 00:04:22.6503624, 194.95 KB/s 2020-03-03 12:56:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bbcbd4187d9cb48b0a22b0fe91722aa0b.dblock.zip.aes (50.00 MB) 2020-03-03 12:56:23 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:04:22.665 2020-03-03 12:56:23 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut 2020-03-03 12:56:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i15817fa246ab4f64b5e441d84bafcfe2.dindex.zip.aes (39.56 KB) 2020-03-03 12:56:24 -05 - [Profiling-Duplicati.Library.Main.BackendManager-UploadSpeed]: Uploaded 39.56 KB in 00:00:01.1783834, 33.57 KB/s 2020-03-03 12:56:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i15817fa246ab4f64b5e441d84bafcfe2.dindex.zip.aes (39.56 KB) 2020-03-03 12:56:24 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.264 2020-03-03 12:56:24 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationNothing]: Starting - RemoteOperationNothing 2020-03-03 12:56:24 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationNothing]: RemoteOperationNothing took 0:00:00:00.000 2020-03-03 12:56:24 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: Starting - ExecuteReader: SELECT "C"."Name", "B"."Name", "B"."Hash", "B"."Size" FROM "IndexBlockLink" A, "RemoteVolume" B, "RemoteVolume" C WHERE "A"."IndexVolumeID" = "B"."ID" AND "A"."BlockVolumeID" = "C"."ID" AND "B"."Hash" IS NOT NULL AND "B"."Size" IS NOT NULL 2020-03-03 12:56:24 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteReader]: ExecuteReader: SELECT "C"."Name", "B"."Name", "B"."Hash", "B"."Size" FROM "IndexBlockLink" A, "RemoteVolume" B, "RemoteVolume" C WHERE "A"."IndexVolumeID" = "B"."ID" AND "A"."BlockVolumeID" = "C"."ID" AND "B"."Hash" IS NOT NULL AND "B"."Size" IS NOT NULL took 0:00:00:00.000 2020-03-03 12:56:24 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: Starting - RemoteOperationDelete 2020-03-03 12:56:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes (50.05 MB) 2020-03-03 12:56:26 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes (50.05 MB) 2020-03-03 12:56:26 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:01.461 2020-03-03 12:56:26 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: Starting - RemoteOperationDelete 2020-03-03 12:56:26 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes (27.45 KB) 2020-03-03 12:56:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes (27.45 KB) 2020-03-03 12:56:29 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:02.955 2020-03-03 12:56:29 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:56:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b3f9da65a8b8040df8cb634523018c2fa.dblock.zip.aes (21.13 MB) 2020-03-03 12:58:17 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 21.13 MB in 00:01:48.8213207, 198.86 KB/s 2020-03-03 12:58:17 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b3f9da65a8b8040df8cb634523018c2fa.dblock.zip.aes (21.13 MB) 2020-03-03 12:58:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:01:48.822 2020-03-03 12:58:17 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:58:17 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bad01a725864f499fa129271f01aa4bc1.dblock.zip.aes (16.13 MB) 2020-03-03 12:59:42 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 16.13 MB in 00:01:24.0692703, 196.49 KB/s 2020-03-03 12:59:42 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-bad01a725864f499fa129271f01aa4bc1.dblock.zip.aes (16.13 MB) 2020-03-03 12:59:42 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:01:24.070 2020-03-03 12:59:42 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 12:59:42 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-be375389d1eba43708f00bce8ba743ccf.dblock.zip.aes (28.48 MB) 2020-03-03 13:02:09 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 28.48 MB in 00:02:27.8752230, 197.18 KB/s 2020-03-03 13:02:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-be375389d1eba43708f00bce8ba743ccf.dblock.zip.aes (28.48 MB) 2020-03-03 13:02:09 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:02:27.876 2020-03-03 13:02:09 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 13:02:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b229fdb1d14f44ae98a22f3835f60848b.dblock.zip.aes (47.39 MB) 2020-03-03 13:02:10 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:00.075 2020-03-03 13:02:10 -05 - [Retry-Duplicati.Library.Main.BackendManager-RetryGet]: Operation Get with file duplicati-b229fdb1d14f44ae98a22f3835f60848b.dblock.zip.aes attempt 1 of 1 failed with message: The remote server returned an error: (403) Forbidden. System.Net.WebException: The remote server returned an error: (403) Forbidden. at Duplicati.Library.Utility.AsyncHttpRequest.AsyncWrapper.GetResponseOrStream() at Duplicati.Library.Utility.AsyncHttpRequest.GetResponse() at Duplicati.Library.Backend.GoogleDrive.GoogleDrive.Get(String remotename, Stream stream) at Duplicati.Library.Main.BackendManager.coreDoGetPiping(FileEntryItem item, IEncryption useDecrypter, Int64& retDownloadSize, String& retHashcode) at Duplicati.Library.Main.BackendManager.DoGet(FileEntryItem item) at Duplicati.Library.Main.BackendManager.ThreadRun() 2020-03-03 13:02:10 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Failed: duplicati-b229fdb1d14f44ae98a22f3835f60848b.dblock.zip.aes (47.39 MB) 2020-03-03 13:02:10 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet 2020-03-03 13:02:10 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b6e794e613caf4a409d2aaf90de1f31bc.dblock.zip.aes (705.39 KB) 2020-03-03 13:02:17 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded and decrypted 705.39 KB in 00:00:06.9219081, 101.91 KB/s 2020-03-03 13:02:17 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b6e794e613caf4a409d2aaf90de1f31bc.dblock.zip.aes (705.39 KB) 2020-03-03 13:02:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:06.922 2020-03-03 13:02:17 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error System.Net.WebException: The remote server returned an error: (403) Forbidden. at Duplicati.Library.Main.AsyncDownloader.AsyncDownloaderEnumerator.AsyncDownloadedFile.get_TempFile() at Duplicati.Library.Main.Operation.CompactHandler.DoCompact(LocalDeleteDatabase db, Boolean hasVerifiedBackend, IDbTransaction& transaction, BackendManager sharedBackend) at Duplicati.Library.Main.Operation.DeleteHandler.DoRun(LocalDeleteDatabase db, IDbTransaction& transaction, Boolean hasVerifiedBacked, Boolean forceCompact, BackendManager sharedManager) at Duplicati.Library.Main.Operation.BackupHandler.CompactIfRequired(BackendManager backend, Int64 lastVolumeSize) at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext() 2020-03-03 13:02:17 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize 2020-03-03 13:02:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.000 2020-03-03 13:02:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:22:16.948 ``` Notice how duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes then duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes were logged as deleted. In 12:56 DB: duplicati-b50fa9e71ec3c4a30a5cf1a769840259b.dblock.zip.aes Remotevolume table shows Deleting RemoteOperation table does not show delete duplicati-i3e3b4e6d1bda4b75bf950caec7755556.dindex.zip.aes Remotevolume table shows Verified RemoteOperation table does not show delete

Yet afaik, this still doesn’t fix the problem with database rebuilding. If there are some old junk files in the path, it shouldn’t completely prevent rebuild & restore. As far as I remember it’s also two tiered problem. A) First leave junk B) Get confused by the junk.

When those are fixed, then I would say that Duplicati is “ready”, because well known corruption flaws are fixed as far as I know.

I haven’t seen any other problems than those. And I see those repeatedly.

Just a minor wish. If a single file is added to backup set, instead of directory. The restore process gives Code: 2 always, because it created “a missing directory”. Well, I don’t see that as being a reason to change code or report “error” at all.