"missing files" error after switching to custom retention policy

Support
1

I’ve been running Duplicati on one of my machines for about 6 months now starting with 2.0.2.1 beta and upgrading (one over-install, the rest in-place) through 2.0.2.20 canary doing a single daily backup (if the machine is powered on for that day).

The destination is an in-house SFTP server used by a few other machines as well (each with their own folder).

Yesterday I switched from “Keep all backups” to --retention-policy=7D:U,4W:1W,12M:1M,U:1Y and with today’s backup run I suddenly got the dreaded “Found 1937 files that are missing from the remote storage, please run repair” error. A quick spot-check of a few of the reported missing files confirms they are indeed missing.

Looking at what’s available for restore I’m now seeing:

  • 7 versions (one per day) from Feb. 21 to Feb. 27
  • 4 versions (sort-of one per week) for Jan. 28 to Feb. 15
  • 5 versions (one per month) from Aug. 22 to Dec. 27

My guess is that after 6 months of keeping all backups the sudden introduction of the retention policy caused a bunch of files to be CORRECTLY deleted, however something went wrong when recording the deleted files into the database.

I’ve disabled the scheduled run (there’s nothing currently needing to be backed up) in case there is some post-failure testing that somebody might suggest I do to try and figure out what went wrong.

Any suggestions on what I might look at to help decipher the issue?

2

That are a lot of files. I suggest to backup your db and do a repair…

I would believe the retention will (to summarize) only delete dlist files and compacting will do the rest. So unless you have a fast changing source, this many files would be strange.

3

First of all I’d make sure you can do a restore from of some files to make sure it seems intact.

After that I think you may be able to get it running using repair, however my experience is that, if the files are missing from the remote target, you can’t get the backup database to repair properly.

I think this issue has something to do with information stored in the main Duplicati server database not being updated in rare cases. And since that database isn’t repaired during the repair it may still find those files to be missing.

If I’m right in that assertion, then you should be able to get the error to go away by export your config and reimporting it, because that will give it a new ID in the Duplicati server database.

Of course if that makes the issue go away, it doesn’t explain why files deleted during compacting weren’t deleted properly from the database.

It also seems Duplicati should be better at handling missing remote files. E.g. show the user the missing file versions and give them the option to “accept” the loss of data so they can continue backing up.

5

I’m pretty sure that DB only holds configuration/logs, nothing about the files.

So this would be equal to a DB repair/recreate.

6

Well that depends on whether or not the main Duplicati server DB is involved in the issue. A recreate only impacts the jobs own database.

But maybe it’s just the remote dlist files. In that case you would need to use the purge broken files command

7

As long as I add --no-backend-verification=true to the global OR job settings (to get around the “missing files” error) I’m able to do a GUI based restore of files and versions as expected.

That will be my ultimate step, which I believe will resolve the issue. I agree with Pectojin that the main DB isn’t touched (much) in a repair, but I also agree with Wim_Jansen that job specific file lists and such aren’t stored in it so that shouldn’t be a problem.

Since this is a personal machine and Duplicati isn’t my only backup tool at the moment (figured I’d keep CrashPlan around until they turned me off) I thought it might be worth trying to figure out what caused the issue in the first place.

Just to be clear, I suspect this is not a problem with the destination as the Duplicati logs show the files being targeted for deletion then actually being deleted.

General Remote
Mar 1, 2018 8:21 AM: Result
Mar 1, 2018 8:05 AM: Result
Feb 28, 2018 2:00 PM: Message
Fatal error
Duplicati.Library.Interface.UserInformationException: Found 1937 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.Run(String[] sources, IFilter filter)
Feb 28, 2018 2:00 PM: Message
Found 1937 files that are missing from the remote storage, please run repair
Feb 28, 2018 2:00 PM: Message
Missing file: duplicati-ia00312535a174edbb6ec08c25f7786dd.dindex.7z.aes
Feb 28, 2018 2:00 PM: Message
...
Feb 28, 2018 1:52 PM: Message
Missing file: duplicati-ic0f964d9c6cf434f99c97b1c06cfc542.dindex.zip.aes
Feb 28, 2018 1:52 PM: Message
Missing file: duplicati-i07b4e403f27f4fbfad6335f8ddfc5478.dindex.zip.aes
           *** What (didn't?) happen during this 3 minute log gap? ***
Feb 28, 2018 1:49 PM: Message
removing file listed as Temporary: duplicati-i0e1558f3c2a54f9694b4b59d1583bc79.dindex.7z.aes
Feb 28, 2018 1:49 PM: Message
removing file listed as Temporary: duplicati-b4bed0436a81d4c5c820d1db22163453c.dblock.7z.aes
Feb 28, 2018 1:49 PM: Message
removing file listed as Deleting: duplicati-bac08102d4c82443e88d88f6d6cdc897e.dblock.7z.aes
Feb 28, 2018 1:49 PM: Message
removing file listed as Deleting: duplicati-b3b1233e94f2b41218b9c4b12b37040ec.dblock.7z.aes
Feb 28, 2018 1:49 PM: Message
...
Feb 28, 2018 1:41 PM: Message
removing file listed as Deleting: duplicati-b13ad78fdd30e492a8706e30156a1b365.dblock.zip.aes
Feb 28, 2018 1:41 PM: Message
removing file listed as Deleting: duplicati-b48fb570899404ca4af18bcee968fa028.dblock.zip.aes
Feb 28, 2018 12:15 AM: Message
Compacting because there are 1937 fully deletable volume(s)
Feb 28, 2018 12:09 AM: Message
Deleted 150 remote fileset(s)
Feb 27, 2018 11:34 PM: Message
Deleting 150 remote fileset(s) ...
Feb 27, 2018 11:34 PM: Message
[Retention Policy]: All backups to delete: 2/20/2018 10:10:48 PM, 2/19/2018 6:44:01 PM, 2/18/2018 1:39:12 PM, 2/17/2018 11:00:02 AM, 2/16/2018 11:00:30 AM, 2/14/2018 5:31:16 PM, 2/12/2018 11:00:01 AM, 2/11/2018 11:40:06 AM, 2/10/2018 11:00:06 AM, 2/9/2018 11:00:03 AM, 2/8/2018 11:00:01 AM, 2/6/2018 7:12:52 PM, 2/5/2018 12:14:59 PM, 2/4/2018 12:57:28 PM, 2/4/2018 8:06:24 AM, 2/3/2018 11:35:01 AM, 2/2/2018 5:49:14 PM, 2/1/2018 11:09:14 AM, 1/30/2018 9:04:07 PM, 1/29/2018 7:04:45 PM, 1/27/2018 11:00:05 AM, 1/26/2018 10:47:13 PM, 1/24/2018 11:00:00 AM, 1/23/2018 11:18:55 AM, 1/22/2018 11:00:07 AM, 1/21/2018 11:00:01 AM, 1/21/2018 12:59:21 AM, 1/20/2018 12:14:26 PM, 1/19/2018 6:57:07 AM, 1/17/2018 11:00:05 AM, 1/16/2018 5:18:56 PM, 1/15/2018 11:00:18 AM, 1/14/2018 11:20:35 AM, 1/13/2018 11:00:04 AM, 1/12/2018 5:36:07 PM, 1/11/2018 2:40:23 PM, 1/10/2018 11:00:01 AM, 1/9/2018 8:52:14 PM, 1/8/2018 11:00:01 AM, 1/7/2018 9:35:49 PM, 1/6/2018 11:00:02 AM, 1/5/2018 11:00:02 AM, 1/4/2018 1:59:37 PM, 1/3/2018 4:47:52 PM, 1/2/2018 12:59:30 PM, 1/1/2018 12:01:59 PM, 12/31/2017 11:03:39 AM, 12/30/2017 12:08:39 PM, 12/30/2017 11:25:20 AM, 12/30/2017 10:16:19 AM, 12/28/2017 3:53:25 PM, 12/26/2017 11:00:04 AM, 12/25/2017 11:00:04 AM, 12/24/2017 11:00:01 AM, 12/23/2017 11:00:01 AM, 12/22/2017 11:00:33 AM, 12/21/2017 11:00:03 AM, 12/20/2017 2:16:39 PM, 12/19/2017 11:00:06 AM, 12/18/2017 11:00:05 AM, 12/17/2017 11:00:01 AM, 12/9/2017 12:00:12 PM, 12/8/2017 11:59:55 PM, 12/7/2017 8:55:55 PM, 12/5/2017 2:35:08 PM, 12/2/2017 12:00:01 PM, 12/2/2017 9:42:16 AM, 11/30/2017 9:20:18 PM, 11/28/2017 8:59:20 PM, 11/27/2017 12:00:01 PM, 11/26/2017 8:20:58 PM, 11/24/2017 8:17:44 PM, 11/22/2017 10:27:53 PM, 11/21/2017 12:00:05 PM, 11/20/2017 10:57:00 PM, 11/19/2017 6:57:51 PM, 11/17/2017 9:54:56 PM, 11/16/2017 4:14:19 PM, 11/14/2017 9:51:50 PM, 11/13/2017 2:29:48 PM, 11/12/2017 5:40:40 PM, 11/11/2017 2:08:28 PM, 11/8/2017 6:39:46 PM, 11/7/2017 7:23:56 PM, 11/6/2017 10:29:48 PM, 11/5/2017 6:17:20 PM, 11/4/2017 7:13:01 PM, 11/3/2017 1:00:00 PM, 11/2/2017 11:21:10 PM, 11/1/2017 10:18:48 PM, 10/31/2017 6:06:48 PM, 10/30/2017 8:28:09 PM, 10/29/2017 10:13:16 PM, 10/27/2017 1:00:00 PM, 10/26/2017 10:21:57 PM, 10/26/2017 9:43:36 PM, 10/26/2017 6:27:54 PM, 10/25/2017 8:32:11 PM, 10/23/2017 1:00:01 PM, 10/22/2017 7:40:59 PM, 10/22/2017 10:06:49 AM, 10/21/2017 10:04:56 PM, 10/18/2017 11:10:22 PM, 10/18/2017 8:58:56 PM, 10/16/2017 1:00:04 PM, 10/15/2017 10:06:05 PM, 10/14/2017 1:00:02 PM, 10/14/2017 10:13:01 AM, 10/13/2017 8:56:59 AM, 10/12/2017 11:22:25 PM, 10/12/2017 1:00:02 PM, 10/11/2017 6:41:59 PM, 10/10/2017 8:24:31 PM, 10/10/2017 7:34:52 PM, 10/9/2017 2:47:18 PM, 10/8/2017 6:37:17 AM, 10/6/2017 1:00:05 PM, 10/5/2017 8:11:44 PM, 10/4/2017 10:03:27 PM, 10/4/2017 9:18:29 PM, 10/4/2017 8:23:00 PM, 10/1/2017 3:18:56 PM, 9/29/2017 1:00:03 PM, 9/28/2017 9:39:38 PM, 9/27/2017 1:16:21 PM, 9/26/2017 10:36:54 PM, 9/24/2017 1:59:17 PM, 9/23/2017 1:00:02 PM, 9/21/2017 7:20:25 PM, 9/18/2017 9:48:23 PM, 9/17/2017 8:17:36 PM, 9/16/2017 10:30:32 AM, 9/15/2017 11:19:12 PM, 9/15/2017 9:40:44 PM, 9/12/2017 8:56:08 PM, 9/11/2017 2:01:26 PM, 9/9/2017 11:04:30 PM, 9/9/2017 9:48:19 PM, 9/6/2017 8:56:13 PM, 9/4/2017 9:47:47 PM, 9/4/2017 7:48:36 PM, 9/2/2017 9:52:11 PM, 9/2/2017 3:35:02 PM, 8/30/2017 8:03:24 PM, 8/30/2017 7:49:25 AM, 8/29/2017 10:33:49 PM, 8/29/2017 5:12:41 PM, 8/22/2017 11:05:18 PM, 8/22/2017 10:45:34 PM, 8/22/2017 10:44:16 PM
Feb 27, 2018 11:34 PM: Message
[Retention Policy]: Backups outside of all time frames and thus getting deleted: 
Feb 27, 2018 11:34 PM: Message
[Retention Policy]: Backups to consider: 2/26/2018 3:27:07 PM, 2/25/2018 1:00:55 PM, 2/24/2018 3:55:59 PM, 2/23/2018 7:06:41 PM, 2/22/2018 7:57:36 PM, 2/21/2018 7:23:38 PM, 2/20/2018 10:10:48 PM, 2/19/2018 6:44:01 PM, 2/18/2018 1:39:12 PM, 2/17/2018 11:00:02 AM, 2/16/2018 11:00:30 AM, 2/15/2018 11:43:25 PM, 2/14/2018 5:31:16 PM, 2/12/2018 11:00:01 AM, 2/11/2018 11:40:06 AM, 2/10/2018 11:00:06 AM, 2/9/2018 11:00:03 AM, 2/8/2018 11:00:01 AM, 2/7/2018 9:26:04 PM, 2/6/2018 7:12:52 PM, 2/5/2018 12:14:59 PM, 2/4/2018 12:57:28 PM, 2/4/2018 8:06:24 AM, 2/3/2018 11:35:01 AM, 2/2/2018 5:49:14 PM, 2/1/2018 11:09:14 AM, 1/31/2018 11:00:00 AM, 1/30/2018 9:04:07 PM, 1/29/2018 7:04:45 PM, 1/28/2018 11:00:01 AM, 1/27/2018 11:00:05 AM, 1/26/2018 10:47:13 PM, 1/24/2018 11:00:00 AM, 1/23/2018 11:18:55 AM, 1/22/2018 11:00:07 AM, 1/21/2018 11:00:01 AM, 1/21/2018 12:59:21 AM, 1/20/2018 12:14:26 PM, 1/19/2018 6:57:07 AM, 1/17/2018 11:00:05 AM, 1/16/2018 5:18:56 PM, 1/15/2018 11:00:18 AM, 1/14/2018 11:20:35 AM, 1/13/2018 11:00:04 AM, 1/12/2018 5:36:07 PM, 1/11/2018 2:40:23 PM, 1/10/2018 11:00:01 AM, 1/9/2018 8:52:14 PM, 1/8/2018 11:00:01 AM, 1/7/2018 9:35:49 PM, 1/6/2018 11:00:02 AM, 1/5/2018 11:00:02 AM, 1/4/2018 1:59:37 PM, 1/3/2018 4:47:52 PM, 1/2/2018 12:59:30 PM, 1/1/2018 12:01:59 PM, 12/31/2017 11:03:39 AM, 12/30/2017 12:08:39 PM, 12/30/2017 11:25:20 AM, 12/30/2017 10:16:19 AM, 12/28/2017 3:53:25 PM, 12/27/2017 9:15:22 PM, 12/26/2017 11:00:04 AM, 12/25/2017 11:00:04 AM, 12/24/2017 11:00:01 AM, 12/23/2017 11:00:01 AM, 12/22/2017 11:00:33 AM, 12/21/2017 11:00:03 AM, 12/20/2017 2:16:39 PM, 12/19/2017 11:00:06 AM, 12/18/2017 11:00:05 AM, 12/17/2017 11:00:01 AM, 12/9/2017 12:00:12 PM, 12/8/2017 11:59:55 PM, 12/7/2017 8:55:55 PM, 12/5/2017 2:35:08 PM, 12/2/2017 12:00:01 PM, 12/2/2017 9:42:16 AM, 11/30/2017 9:20:18 PM, 11/28/2017 8:59:20 PM, 11/27/2017 12:00:01 PM, 11/26/2017 8:20:58 PM, 11/25/2017 3:54:26 PM, 11/24/2017 8:17:44 PM, 11/22/2017 10:27:53 PM, 11/21/2017 12:00:05 PM, 11/20/2017 10:57:00 PM, 11/19/2017 6:57:51 PM, 11/17/2017 9:54:56 PM, 11/16/2017 4:14:19 PM, 11/14/2017 9:51:50 PM, 11/13/2017 2:29:48 PM, 11/12/2017 5:40:40 PM, 11/11/2017 2:08:28 PM, 11/8/2017 6:39:46 PM, 11/7/2017 7:23:56 PM, 11/6/2017 10:29:48 PM, 11/5/2017 6:17:20 PM, 11/4/2017 7:13:01 PM, 11/3/2017 1:00:00 PM, 11/2/2017 11:21:10 PM, 11/1/2017 10:18:48 PM, 10/31/2017 6:06:48 PM, 10/30/2017 8:28:09 PM, 10/29/2017 10:13:16 PM, 10/27/2017 1:00:00 PM, 10/26/2017 10:21:57 PM, 10/26/2017 9:43:36 PM, 10/26/2017 6:27:54 PM, 10/25/2017 8:32:11 PM, 10/24/2017 10:35:38 PM, 10/23/2017 1:00:01 PM, 10/22/2017 7:40:59 PM, 10/22/2017 10:06:49 AM, 10/21/2017 10:04:56 PM, 10/18/2017 11:10:22 PM, 10/18/2017 8:58:56 PM, 10/16/2017 1:00:04 PM, 10/15/2017 10:06:05 PM, 10/14/2017 1:00:02 PM, 10/14/2017 10:13:01 AM, 10/13/2017 8:56:59 AM, 10/12/2017 11:22:25 PM, 10/12/2017 1:00:02 PM, 10/11/2017 6:41:59 PM, 10/10/2017 8:24:31 PM, 10/10/2017 7:34:52 PM, 10/9/2017 2:47:18 PM, 10/8/2017 6:37:17 AM, 10/6/2017 1:00:05 PM, 10/5/2017 8:11:44 PM, 10/4/2017 10:03:27 PM, 10/4/2017 9:18:29 PM, 10/4/2017 8:23:00 PM, 10/1/2017 3:18:56 PM, 9/29/2017 1:00:03 PM, 9/28/2017 9:39:38 PM, 9/27/2017 1:16:21 PM, 9/26/2017 10:36:54 PM, 9/24/2017 1:59:17 PM, 9/23/2017 1:00:02 PM, 9/23/2017 9:05:36 AM, 9/21/2017 7:20:25 PM, 9/18/2017 9:48:23 PM, 9/17/2017 8:17:36 PM, 9/16/2017 10:30:32 AM, 9/15/2017 11:19:12 PM, 9/15/2017 9:40:44 PM, 9/12/2017 8:56:08 PM, 9/11/2017 2:01:26 PM, 9/9/2017 11:04:30 PM, 9/9/2017 9:48:19 PM, 9/6/2017 8:56:13 PM, 9/4/2017 9:47:47 PM, 9/4/2017 7:48:36 PM, 9/2/2017 9:52:11 PM, 9/2/2017 3:35:02 PM, 8/30/2017 8:03:24 PM, 8/30/2017 7:49:25 AM, 8/29/2017 10:33:49 PM, 8/29/2017 5:12:41 PM, 8/22/2017 11:05:18 PM, 8/22/2017 10:45:34 PM, 8/22/2017 10:44:16 PM, 8/22/2017 9:41:01 PM
Feb 27, 2018 11:34 PM: Message
[Retention Policy]: Time frames and intervals pairs: 7.00:00:00 / Keep all, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00, Unlimited / 365.00:00:00
Feb 27, 2018 11:34 PM: Message
[Retention Policy]: Start checking if backups can be removed
Feb 26, 2018 11:53 PM: Result
Feb 26, 2018 11:50 PM: Message
Feb 26, 2018 4:17 PM: Message
Feb 25, 2018 1:55 PM: Result
Feb 24, 2018 5:00 PM: Result
...
8

Is there some history on this backup? I have had similar behaviour in the past, but the backup has had several changes:

  • path changes of all files (moved my source location)
  • split the backup in several backup sets (one fast moving, one slow moving)

Duplicati also complained about missing remotes files, but that was after a repair. In this case, it could have been the compacting that noticed this.

I’m now doing a recreate of a db that has the other parts of the split backup. I expect similar remarks. But the repair is ongoing for almost 2 days now… Will let you know once the repair is done if similar issues will appear.

9

Not really. It was created about 6 months with a small test folder, then about 5.5 months ago expanded to it’s current source folder.

There has been some adjusting of filter rules, but nothing has been changed there in at least 2 months.

Yep - that slow repairs issue is going to have to be address at some point.

10

Any luck over there? My repair failed due to temp folder issues (I think). Had to restart :frowning:

11

Actually, I haven’t gotten back to it yet. :blush:

My plan du jour is to back up the current database, try a repair and see what happens. I expect it will work, but I’ll still have the “bad” version available for any research I might want to try in the future.

12

So I backed up my database just in case I wanted to do some more testing then went ahead and ran another backup WITHOUT doing a repair first, but WITH the --no-backend-verification=true parameter added.

As expected, the backup ran just fine - though it did complain (warnings, not errors) about not being able to delete files that were already deleted.

Removing the --no-backend-verification parameter puts me back in the “Found n files that are missing from the remote storage” failure scenario.

Guess I’m off to do a database repair. :slight_smile:

13

Well, 42 minutes and one 853MB sqlite file repair later and my backup seems to be fully working again. Thanks!

Note that this seems be a much faster repair experience than others have reported so I’m going to make note of my system specs:

  • Older ASUS laptop
  • 1.7GHz AMD E2-1800 (2 cores)
  • 4G memory
  • Windows 10 (64 bit)
  • SFTP destination accessed via wifi (~10Mbps)
  • 100G source size across 34k files
  • default 50MB block & 100KB dblock sizes (so assuming ~1 mill block related hash rows in the db)
14

In my case I went from a “Keep everything” retention policy (daily backups for over 6 months) to a Custom backup retention of 7D:U,4W:1D,12M:1W,U:1Y. So I suspect the initial dlist delete happened as you suggested but it was immediately followed up with many files needing to be compacted due to the cleaning of a lot of “very” old versions.

15

Did your repair download dblock files? Still unclear to me why that would be needed on a bsckup that was 100% working fine… But this caused my repair to take ~1 day.

16

I’ll have to check the log but I don’t think so. In my case what needed to be “repaired” was just getting the local database list of destination files in sync with the ACTUAL destination files. So my guess is only dlist files were downloaded, if that - it’s possible a simple file list could have been enough (though in that case 42 min. seems a bit excessive).

I’ll stop guessing now and try to update when I’m back at that machine.

17

I’m not positive, but I’m not finding and dblock downloads in my logs for these time frames.

But the errors have gone away so I must have accidentally done something right.