Continually needing repair

Support
1

I have a backup host using WebDAV that I commonly get a time out verifying the files. However the backup completes without error. Yesterday I was greeted with the message that 31 files are missing from remote store, please run repair. I ran repair without error. I manually started a backup, it finished and had a time out verifying files. This morning I got the message that 23 files were missing from remote storage. I ran repair. I manually ran a backup, got the time out on verify again. Then I get a message that 1 file is missing from remote storage.

I have another WebDAV host that I don’t get any verify time outs to and haven’t seen that backup job complain about missing files.

In the past I’ve tried rebuilding the database and that never finishes. I’ve left it running for over a week. So I really don’t want to do that and I’d rather not delete my backups again and start over.

What is going on here? Is my data really backed up? Can I trust duplicati? I’m running version 2.0.4.5_beta_2018-11-28.

2

I’d suggest you start but getting a few of the missing file names from the error message then manually checking whether or not they’re ACTUALLY missing from the destination.

It’s possible the response from the destination of what files are actually listed is incomplete or corrupted somehow causing Duplicati to THINK the files are missing when really they aren’t.

If you find the files really are NOT there then we can look into how they disappeared (did Duplicati delete them then forget about it or did something outside of Duplicati make them go away).

If they files ARE there, then we can look at what’s causing Duplicati to incorrectly think they’re not there.

The BEST way to check if your data is backed up is to restore it, but I know that’s not an option for many people due to space, time, bandwidth, etc.

As for whether or not you can trust Duplicati, that’s a bit of a loaded question to ask on the support forum… :slight_smile:

But what I can say is that in my experience when it works, it works quite well and when it has issues it’s pretty good at alerting about them (such as is happening with you).

When issues are found they’re usually either easily resolved or a HUGE pain in the butt to deal with. Hopefully what you’re experiencing doesn’t fall into that last scenario. :crossed_fingers:

3

Where are the missing files listed? I just checked the last error message and this is all that I see.

Duplicati.Library.Interface.UserInformationException:
Found 1 files that are missing from the remote storage, please run repair
at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList (Duplicati.Library.Main.BackendManager backend, Duplicati.Library.Main.Options options, Duplicati.Library.Main.Database.LocalDatabase database, Duplicati.Library.Main.IBackendWriter log, System.String protectedfile) [0x00203] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Library.Main.Operation.BackupHandler.PreBackupVerify (Duplicati.Library.Main.BackendManager backend, System.String protectedfile) [0x0010d] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Library.Main.Operation.BackupHandler+<RunAsync>d__19.MoveNext () [0x01031] in <c6c6871f516b48f59d88f9d731c3ea4d>:0 --- End of stack trace from previous location where exception was thrown ---
at CoCoL.ChannelExtensions.WaitForTaskOrThrow (System.Threading.Tasks.Task task) [0x00050] in <6973ce2780de4b28aaa2c5ffc59993b1>:0
at Duplicati.Library.Main.Operation.BackupHandler.Run (System.String[] sources, Duplicati.Library.Utility.IFilter filter) [0x00008] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Library.Main.Controller+<>c__DisplayClass13_0.<Backup>b__0 (Duplicati.Library.Main.BackupResults result) [0x00035] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Library.Main.Controller.RunAction[T] (T result, System.String[]& paths, Duplicati.Library.Utility.IFilter& filter, System.Action`1[T] method) [0x00271] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Library.Main.Controller.Backup (System.String[] inputsources, Duplicati.Library.Utility.IFilter filter) [0x00068] in <c6c6871f516b48f59d88f9d731c3ea4d>:0
at Duplicati.Server.Runner.Run (Duplicati.Server.Runner+IRunnerData data, System.Boolean fromQueue) [0x00307] in <fe28905ee30b422e8d475f1cfdb85515>:0
4

Something possibly related. When I get these error messages, there is nothing in the log for the job. I need to goto About->Show Log to see the log messages.
This last run I set the log level in the job to profiling and I still don’t see which files are missing. I’m going to try logging to a file with level verbose this time.

5

Do you have a separate destination directory for each job? I had a lot of aggravation and errors like this when I didn’t know I had to give a separate destination directory.

I was putting multiple jobs into one shared directory and the indexes kept on getting corrupted but there were no signs of error on the initial run when the directory was blank.

6

Yes, I have a separate directory for each job.

Using a log file with verbose got me some more information. It reports 3 files missing. When I goto the destination location I see that the 3 files are indeed missing. I’m using NextCloud as my WebDAV store, so there is a trash bin. The 3 files are in the trash bin. This suggests to me that Duplicati decided to delete the files. I’m using “Smart Backup Retention”.

7

Good catch! It’s possible the retention cleanup step got interrupted between the “delete these files” step and the “record that these files have been deleted” step.

I’m not deep in the database structure but my guess is the missing files would normally be included in the “to be deleted” list for the smart retention, but after a database recreate I think that table is reset.

So easy “fix” should be to restore those files. They’ll probably be deleted again by retention cleanup, but that’s ok as long as the deletion it’s recorded.

If that doesn’t work…

Does a backup run at all now or does it error out early on?

If it errors out, we should be able to disable the backed verification step which should allow a backup to continue through to the retention cleanup stage.

Once we get that far we can review the retention log to verify the missing files are supposed to have been deleted.

8

The next backup ran ok.

9

My backups have been OK so far after this. Now why did duplicati decide to delete files that it still wanted?

10

Good question. If it happens again we can do some log digging to research that. The problem is the “why this was deleted” gets logged in the job BEFORE the error.

11

Is there some logging that I need turned on to catch this? When it happens again where should I start looking?

12

Well, it depends on where the error is actually happening.

My guess is that for this error there’s a problem with the retention policy code such that it does the delete then either doesn’t record that it was deleted or records it then something else overwrites that (like it re-flags it as needing to be deleted).

So if the error happens again, you should be able to get the name of the missing file from the current run logs, then you can look at the previous run log and search for that file name.

You could also search the log for “DeleteRemoteFileset” or “RetentionPolicy” and you should see lines something like these:

"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / Keep all, 31.00:00:00 / 1.00:00:00, 365.00:00:00 / 7.00:00:00, Unlimited / 31.00:00:00",
"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 02/11/2019 00:03:04, 02/04/2019 03:22:28, 01/31/2019 00:03:04, 01/19/2019 00:03:04, 01/14/2019 03:23:17, 01/07/2019 03:21:25, 12/30/2018 00:00:05, 12/23/2018 00:00:03, 12/15/2018 00:00:06, 12/05/2018 00:00:06, 11/26/2018 00:00:03, 11/14/2018 00:00:01, 11/03/2018 01:00:01, 10/26/2018 15:54:50, 10/16/2018 01:00:02, 10/08/2018 01:00:01, 09/28/2018 01:00:02, 09/21/2018 01:00:01, 09/14/2018 01:00:00, 09/07/2018 01:00:00, 08/31/2018 01:00:00, 08/23/2018 01:00:00, 08/15/2018 01:00:00, 08/01/2018 11:49:15, 07/23/2018 20:04:09, 07/01/2018 22:37:09, 06/17/2018 21:35:05",
"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 01/19/2019 00:03:04",
"2019-02-19 00:08:25 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...",
"2019-02-19 00:11:39 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20190119T060304Z.dlist.zip.aes (882.28 KB)",
"2019-02-19 00:11:40 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20190119T060304Z.dlist.zip.aes (882.28 KB)",
"2019-02-19 00:11:56 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 1 remote fileset(s)",
"2019-02-19 00:12:52 -06 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required",

In the above case, it’s the “Backend event: Delete - Started: duplicati-20190119T060304Z.dlist.zip.aes (882.28 KB)”, and following line that show a file was deleted.

13

So if I set my console log level to Information and then wait for this to happen, I should able to see these messages. Correct? I ask because I had my console log level at Verbose and also writing to a log file with Verbose and there is more information in the file than in the console.

14

I don’t think console logging settings will affect what goes into the web GUI logs (which is where my stuff above came from). However it will affect command line runs (including from the GUI).

Personally, I use the log file with standard logging and a log-file-filter to include the “extra” stuff only got what I care about.

So I’d do something like filter for *BackendEvent which would include things like GET, PUT, and DELETE.

The thing it too me a bit to figure out is that the filter parameter can filter IN as well as OUT. So you can have a low level of logging but use a filter to include details on only the functions you care about.

This helps avoid giant log files that can be a pain to sift through.

15

I think something is wrong with the smart retention strategy. I have another machine using a local disk for backup, so there’s no chance of network issues. This machine has been backing up just fine, no errors, no warnings. This morning I get “Unexpected difference in fileset version 4: 3/11/2019 10:00:00 AM (database id: 18), found 5675838 entries, but expected 5675839”. Database repair doesn’t fix it.

16

I had another machine show that it’s missing 11 files. I just looked for them and again duplicati deleted them. It looks like there is a real problem with the smart retention strategy.

17

On the system that I’ve been testing I have had the logging on long enough to catch the delete event.

Delete events:

2019-03-23 20:07:19 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed
2019-03-23 20:07:19 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00
2019-03-23 20:07:19 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 3/22/2019 7:00:00 PM, 3/21/2019 7:13:53 PM, 3/19/2019 8:14:29 PM, 3/18/2019 8:12:58 PM, 3/17/2019 7:27:47 PM, 3/15/2019 8:55:48 PM, 3/12/2019 7:16:04 PM, 3/4/2019 6:36:15 PM, 2/24/2019 9:55:06 AM, 2/15/2019 6:26:26 PM, 1/14/2019 6:23:53 PM, 12/6/2018 7:31:18 PM, 10/11/2018 7:51:40 PM, 9/9/2018 9:46:01 PM, 8/9/2018 7:22:39 PM, 7/8/2018 8:21:36 PM
2019-03-23 20:07:19 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: 
2019-03-23 20:07:19 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: 3/22/2019 7:00:00 PM, 3/15/2019 8:55:48 PM

...

2019-03-23 20:09:06 -05 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there are 51.84 MB in small volumes and the volume size is 50.00 MB
...

2019-03-24 03:01:39 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-id194d476d9c041b0a43dd0221ee249e3.dindex.zip.aes (133.26 KB)
2019-03-24 03:01:41 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-id194d476d9c041b0a43dd0221ee249e3.dindex.zip.aes (133.26 KB)

2019-03-24 03:01:35 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-i8046624c02fa40889cf63b96b0c76660.dindex.zip.aes (80.58 KB)
2019-03-24 03:01:37 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i8046624c02fa40889cf63b96b0c76660.dindex.zip.aes (80.58 KB)

Missing file reports

2019-03-24 19:28:53 -05 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-id194d476d9c041b0a43dd0221ee249e3.dindex.zip.aes
2019-03-24 19:28:53 -05 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-i8046624c02fa40889cf63b96b0c76660.dindex.zip.aes

It looks to me like whatever logic is compacting small volumes is doing something wrong.

18

Looks like there is a bug report on GitHub for this at Found 1 files that are missing from the remote storage, please run repair · Issue #1706 · duplicati/duplicati · GitHub

19

I have the same experience. I first found your comment on the Github issue you mentioned. I’m also running compacting to maximize the amount of storage used. Good thing you mentioned to check the recycle bin on the remote storage. I’m using Stack (service from TransIP) which is based on OwnCloud or NextCloud. I found the files Duplicati reported as missing in the recycle bin. I added my 2 ct to the Github issue. One could say a workaround is to stop using compacting, but I use the remote storage for other family members as wel so I try to do that on a budget. Not all of the family members have frequently changing files or a large amount of files so those that don’t have that, can easily compact now and then.

20

403 error during compact forgot a dindex file deletion, getting Missing file error next run. #4129
is another GitHub issue that explains at least one way to get an error, and it sort of agrees with

and what it’s doing wrong (at least in my GitHub issue) appears to be it’s forgetting prior deletions, possibly due to database transaction rollback. If you look in the database with a database browser, there’s lots of stuff that should be there that isn’t, but the evidence it happened is in your own logs.

A difference from original post is that my problems, both from the test case and from usual backup, repaired so far, only needing a few dblock downloads. There’s another backup I haven’t fixed yet…

Anyway, I thought I’d throw that out in case someone wants to take a closer look to see if they hit it.
Easiest way is to keep a –log-file at at least –log-file-log-level=Information, but Retry level is better.

DB Browser for SQLite or similar can be used if you really want to view DB. If Delete is in the log (or Recycle Bin) but RemoteOperation doesn’t show it, you might have hit the mentioned GitHub issue.

I kind of invited my issue (while trying to reproduce it) by setting –number-of-retries=1, but to avoid getting error-handling issues, you can crank yours higher than the default 10. Sometimes, one also needs –http-operation-timeout raised, if timeouts are happening. Basically, avoid errors in compact.

Errors in backup were an earlier fix phase (got many fixes in 2.0.5.1), but compact is more obscure.