duplicati / duplicati

Store securely encrypted backups in the cloud!
Other
11.23k stars 902 forks source link

Remote file referenced ... but not found in list, registering a missing remote file #4586

Open ts678 opened 3 years ago

ts678 commented 3 years ago

Environment info

Description

During a test of Restore from configuration, I got two errors which I can't find in server log, but profiling log files has them as:

2021-07-22 09:33:46 -04 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b3ebac61adba1490095fbd609e488652b.dblock.zip.aes by duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes, but not found in list, registering a missing remote file

2021-07-22 09:33:46 -04 - [Error-Duplicati.Library.Main.Operation.RecreateDatabaseHandler-MissingFileDetected]: Remote file referenced as duplicati-b234322d05ba7458192d97c217b627031.dblock.zip.aes by duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes, but not found in list, registering a missing remote file

I think these are "extra" dindex files left over from a June 20 network glitch, which unfortunately means RemoteOperation table had purged the original time based on log-retention, but sometimes those are unreliable anyway due to transaction rollback. A profiling log is good though, and doesn't roll back. I also have information from the database, so here's an attempt to reconstruct the failure.

Remotevolume table has 386 Verified Blocks volumes and 388 Verified Index volumes now. IndexBlockLink table has 386 rows. They should all be the same number, I think, so this hints there are 2 extra dindex, but which ones? Rather than write SQL, I just searched Remotevolume table for the two dindex named in the errors, and found both ID absent from IndexVolumeID in IndexBlockLink table.

I could probably just delete these seemingly extra dindex manually, or maybe Repair would, but might as well keep looking for cause. Because the files still exist, the Data from any list Operation in RemoteOperation will show them. Here's their view seen in JSON:

{"Name":"duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes","LastAccess":"2021-06-20T13:34:53.293Z","LastModification":"2021-06-20T13:34:53.293Z","Size":1293,"IsFolder":false}, {"Name":"duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes","LastAccess":"2021-06-20T12:03:30.804Z","LastModification":"2021-06-20T12:03:30.804Z","Size":3309,"IsFolder":false},

and here is selected log history that might explain how two code paths led to two dindex files, or some similar sort of retry confusion. Both files will suffer a seeming network outage on upload (how does upload time out in 0 seconds?!), but actually make it up full size.

When this is eventually seen, the two files are promoted to Uploaded, however I don't think this records them in IndexBlockLink too. Instead, RecreateMissingIndexFile puts up some new ones. This is a known "feature" during manual Repair, and I'm not sure whether or not I had auto-cleanup on. Regardless, the two failed-then-found-uploaded files might be extra files whose dblocks are now gone.

Selected history of duplicati-b3ebac61adba1490095fbd609e488652b.dblock.zip.aes by duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes and duplicati-i772fbfd9d0844e7ab0705cc3cca29fea.dindex.zip.aes 2021-06-20 09:33:00 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started 2021-06-20 09:34:51 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b3ebac61adba1490095fbd609e488652b.dblock.zip.aes (952.45 KB) 2021-06-20 09:34:53 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes (1.26 KB) 2021-06-20 09:39:53 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes attempt 1 of 6 failed with message: GetResponse timed out 2021-06-20 09:39:53 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes (1.26 KB) 2021-06-20 09:40:05 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error 2021-06-20 09:40:05 -04 - [Warning-Duplicati.Library.Modules.Builtin.ReportHelper-ReportSubmitError]: Failed to send message: System.Net.Sockets.SocketException: No such host is known 2021-06-20 10:40:01 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started 2021-06-20 10:40:49 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-PromotingCompleteFile]: promoting uploaded complete file from Uploading to Uploaded: duplicati-i820c4edba8b541dabb56e5361bfadc66.dindex.zip.aes 2021-06-20 10:40:51 -04 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b3ebac61adba1490095fbd609e488652b.dblock.zip.aes 2021-06-20 10:40:51 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (478, "duplicati-i772fbfd9d0844e7ab0705cc3cca29fea.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2021-06-20 10:41:03 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i772fbfd9d0844e7ab0705cc3cca29fea.dindex.zip.aes (1.26 KB) 2021-06-20 10:44:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-b3ebac61adba1490095fbd609e488652b.dblock.zip.aes (952.45 KB) 2021-06-20 10:44:27 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i772fbfd9d0844e7ab0705cc3cca29fea.dindex.zip.aes (1.26 KB)

Selected history of duplicati-b234322d05ba7458192d97c217b627031.dblock.zip.aes by duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes and duplicati-i47f575ba3e094cb98ff086244d7a82d8.dindex.zip.aes 2021-06-20 08:02:18 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started 2021-06-20 08:03:29 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b234322d05ba7458192d97c217b627031.dblock.zip.aes (939.18 KB) 2021-06-20 08:03:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes (3.23 KB) 2021-06-20 08:08:30 -04 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes attempt 1 of 6 failed with message: GetResponse timed out 2021-06-20 08:08:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes (3.23 KB) 2021-06-20 08:08:42 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error 2021-06-20 08:08:42 -04 - [Warning-Duplicati.Library.Modules.Builtin.ReportHelper-ReportSubmitError]: Failed to send message: System.Net.Sockets.SocketException: No such host is known 2021-06-20 08:20:01 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started 2021-06-20 08:20:51 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-PromotingCompleteFile]: promoting uploaded complete file from Uploading to Uploaded: duplicati-ifea24c2c894b4b42890a69ab8f6f4765.dindex.zip.aes 2021-06-20 08:20:54 -04 - [Information-Duplicati.Library.Main.Operation.Backup.RecreateMissingIndexFiles-RecreateMissingIndexFile]: Re-creating missing index file for duplicati-b234322d05ba7458192d97c217b627031.dblock.zip.aes 2021-06-20 08:20:54 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteScalarInt64]: Starting - ExecuteScalarInt64: INSERT INTO "Remotevolume" ("OperationID", "Name", "Type", "State", "Size", "VerificationCount", "DeleteGraceTime") VALUES (475, "duplicati-i47f575ba3e094cb98ff086244d7a82d8.dindex.zip.aes", "Index", "Temporary", -1, 0, 0); SELECT last_insert_rowid(); 2021-06-20 08:21:06 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i47f575ba3e094cb98ff086244d7a82d8.dindex.zip.aes (3.23 KB) 2021-06-29 18:05:46 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-b234322d05ba7458192d97c217b627031.dblock.zip.aes (939.18 KB) 2021-06-29 18:05:47 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i47f575ba3e094cb98ff086244d7a82d8.dindex.zip.aes (3.23 KB)

Steps to reproduce

  1. Not available now, however it might be possible to set up someday using an rclone wrapper I once made that can forge errors...

There are lots of reported errors with the same general results, but none of them ever dug deep enough to say if it was this problem.

Some subtleties of how retries need to be handled are in the below issue and pull request. In current issue, its retries were exhausted.

dblock put retry corrupts dindex, using old dblock name for index -- canary regression #3932 Ensure that dindex references correct dblock file after renames #3938

Screenshots

Debug log

debug_log.zip

duplicatibot commented 3 years ago

This issue has been mentioned on Duplicati. There might be relevant details there:

https://forum.duplicati.com/t/ftp-delete-not-atomic-verified-transactional/12936/5

duplicatibot commented 3 years ago

This issue has been mentioned on Duplicati. There might be relevant details there:

https://forum.duplicati.com/t/restore-problem/12977/9

duplicatibot commented 2 years ago

This issue has been mentioned on Duplicati. There might be relevant details there:

https://forum.duplicati.com/t/restore-from-b2-with-no-local-database/15107/16