Many "Unexpected difference in fileset" errors (worked-around)

Support
1

I’ve been running Duplicati v2.0.5.1_beta_2020-01-18 for several months. I have Duplicati installed on two Windows machines, and one Linux box, and all back up, daily, to (separate) folders in Google Drive. This has worked smoothly for several months, at least.

I recently got a spate of “Unexpected difference in fileset” errors on one Windows box, and I had to manually delete several backup “versions” (as covered elsewhere in the Forum) before backups started working again. I thought I should at least report this in case there are useful hints about how so many versions got corrupted. I have saved the emails sent by each step if there are more details I can include from those.

There wasn’t much changing on this Windows machine during the window of problems. However, I was messing with the firewall between this machine and the internet and could have disconnected/prevented network connections while I (badly) changed the firewall.

Here was the last successful backup before backups went bad:

MainOperation: Backup
ParsedResult: Success
Version: 2.0.5.1 (2.0.5.1_beta_2020-01-18)
EndTime: 3/17/2021 1:16:22 PM (1616012182)
BeginTime: 3/17/2021 9:00:00 AM (1615996800)

Here is the first error I encountered. Notice that the detected version is from January, so there have been many weeks of daily backups in the meantime.

Failed: Unexpected difference in fileset version 8: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 8: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass34_0.<VerifyConsistencyAsync>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.<RunOnMain>b__0()
   at Duplicati.Library.Main.Operation.Common.SingleRunner.<DoRunOnMain>d__2`1.MoveNext()

A “repair” opertion succeeded, but did not fix anything:

MainOperation: Repair
ParsedResult: Success
Version: 2.0.5.1 (2.0.5.1_beta_2020-01-18)
EndTime: 3/17/2021 10:52:19 PM (1616046739)
BeginTime: 3/17/2021 10:40:48 PM (1616046048)
Duration: 00:11:30.8967807

Following the instructinons on various forum posts, I deleted the problematic version, and started a new backup. Then a different version had a problem:

Failed: Unexpected difference in fileset version 7: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 7: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)

Deleted this version, then got the same failure on versions 6, 5, 4, 3, 2, 1, and 0. Each time I’d start a backup, it would fail due to an unexpected difference, I would delete that version manually and retry. Each time gap between the “found” vs “expected” number of entries got smaller and smaller.

This basically deleted all of my recent backups (older backups from Nov and Dec survived). I eventually got a backup to complete:

MainOperation: Backup
ParsedResult: Success
Version: 2.0.5.1 (2.0.5.1_beta_2020-01-18)
EndTime: 3/19/2021 1:08:04 PM (1616184484)
BeginTime: 3/19/2021 11:39:14 AM (1616179154)
Duration: 01:28:50.3593233

I’ve been manually triggering backups a lot since, and they all seem to be working fine. My other machines also backing up daily without problems. If there are additional details that might be useful, I have the full set of emails sent from each operation and I’m happy to dig into databases or logs that might contain useful information.

2

It could be that they have some sort of issue with automatic and remote connection failure causing an issue. I can see that being a thing especially with Drive. Could be it just doesn’t happen when you manually do it.

Drive has this really crappy thing on connection issues where file query can mess everything up. I had this situation with my own application where a rare test - the only one I found to trigger it - would cause major issues with file syncing. It all depends on Duplicati’s Drive code and what’s happening.

But, I’m sure other reasons exist such as automatic is something you won’t know that’s happening and if you eg reboot the computer while its running, that’s another potential problem.

Drive is a major pain in the butt to code truly successfully. Google of course caused me to do it twice and I learned a lot about it as well as learned to hate it. But if its not that then it would be probably an issue with Duplicati itself as found 236931 entries, but expected 237443.

I really don’t think its through any fault of your own.

Just to add to that, you should hopefully find better success through some other means. I feel its not for you to fix this. Duplicati should be doing better validation or whatever. Its obviously failing bad.

My suggestion if you can is to do local backups and less remote backups. At the very least it should be extremely rare that you ever need a backup that’s not local eg house should burn down no more than once in your lifetime. This will avoid more problems.

But you can try a newer coded version of Duplicati. Its possible that they have already improved it. That comes with possible other problems but could be worth it.

That’s all I have to say about it.

3

I stopped seeing this error on later canary versions. Hopefully a new beta will be released soon!

4

It’s only a different version in the 0-based numbering where 0 is the newest. Note version dates:

version 8: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
version 7: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443

Somehow it looks like you deleted a more recent version, so the failing version got closer to 0…
There has been at least one report of numbers being inconsistent between different operations.

It didn’t on the two posted. I wonder if the others were truly different, meaning per the date and id?

Perhaps in some of those (check server log too, at About → Show log → Stored as well as job log), something interesting will turn up. Even though there’s a mystery behind the version numbering, the primary question would be how things went bad. Logs just before and at that time might be the best.

Default logging is not enough to see all the details though. Ideally one has a huge profiling log with a database bug report to look at together. Even better and rarer is if you copied off your old databases, allowing one to more easily see when an issue got in. This is what I run in a debugging environment.

Interesting. 2.0.4.5/23 were awful for me. 2.0.5.1 was orders of magnitude better, but you still saw it?
Have any logs that may be compared against the change logs to try to spot what made these better?

5

Oh odd. Dunno what happened to make my version number change without changing the … oh, just looked more closely at the logs. I deleted version 4 for some reason, not version 8. I’m not sure if I was confused when deleting that version or mis-typed or what, but the logs show I deleted #4. I’d assumed that progressing to “version 7” meant it worked, but as you point out, version 8 just got relabeled. I didn’t make that mistake in the later delete steps, so they do show the pattern I claimed, and show lots of broken versions.

Here are some of the later “difference in fileset version X” error messages:

Failed: Unexpected difference in fileset version 7: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443
Failed: Unexpected difference in fileset version 6: 2/18/2021 5:12:28 PM (database id: 835), found 241671 entries, but expected 242086
Failed: Unexpected difference in fileset version 5: 2/25/2021 6:46:52 PM (database id: 842), found 241992 entries, but expected 242357
Failed: Unexpected difference in fileset version 4: 3/4/2021 9:03:19 PM (database id: 849), found 243099 entries, but expected 243424
Failed: Unexpected difference in fileset version 3: 3/13/2021 8:00:02 AM (database id: 858), found 245425 entries, but expected 245719
Failed: Unexpected difference in fileset version 2: 3/14/2021 10:14:29 AM (database id: 859), found 245349 entries, but expected 245642
Failed: Unexpected difference in fileset version 1: 3/16/2021 9:00:02 AM (database id: 861), found 245403 entries, but expected 245695
Failed: Unexpected difference in fileset version 0: 3/17/2021 9:00:02 AM (database id: 862), found 247300 entries, but expected 247599

(To be clear, I’m gluing together these lines from different backup reports — I didn’t get this all at once.) The number of “found” entries generally goes up, except from #3 to #2 … not sure that means too much.

The server logs (About → Show Log → Stored) have basically the same content as my emails. There is an error a couple days before this problem, but a repair succeeded and a backup succeeded after that error, so I think it is unrelated? For completeness, here are the details on that error and the repair/backup afterwards:

2021-03-16 10:30:07 -07 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.ArgumentNullException: Path cannot be null.
Parameter name: path
   at Duplicati.Library.Main.BackendManager.WaitForEmpty(LocalDatabase db, IDbTransaction transation)
   at Duplicati.Library.Main.Operation.CompactHandler.DoDelete(LocalDeleteDatabase db, BackendManager backend, IEnumerable`1 deleteableVolumes, IDbTransaction& transaction)
   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 I got a

2021-03-16 11:09:50 -07 - [Error-Duplicati.Library.Main.Operation.FilelistProcessor-ExtraRemoteFiles]: Found 1 remote files that are not recorded in local storage, please run repair

Then a repair succeeded:

MainOperation: Repair
ParsedResult: Success
Version: 2.0.5.1 (2.0.5.1_beta_2020-01-18)
EndTime: 3/16/2021 11:28:24 AM (1615919304)
BeginTime: 3/16/2021 11:27:14 AM (1615919234)
Duration: 00:01:09.5277898

And then a backup succeeded:

MainOperation: Backup
ParsedResult: Success
Version: 2.0.5.1 (2.0.5.1_beta_2020-01-18)
EndTime: 3/17/2021 1:16:22 PM (1616012182)
BeginTime: 3/17/2021 9:00:00 AM (1615996800)
Duration: 04:16:21.7882408

(Side-note: this backup took more than 4 hours … my backups generally take less than an hour. AFAICT, the number of files deleted/modified/opened/added wasn’t dramatically different from other backups, so this backup could have run into the networking issues I mentioned up top. Not that I can tell …)

The next backup after the above success is when I got the first “unexpected difference in fileset” error:

2021-03-17 13:16:58 -07 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 8: 1/19/2021 9:34:49 AM (database id: 804), found 236931 entries, but expected 237443

Digging into the four-hour successful backup some more, the front-end logs show it was the “Delete phase” that took 3h40m:
image

Maybe that is a clue?

If I see this problem in the future, I can grab a bug-report snapshot before repairing/deleting anything. But I really hope I don’t see it again. :slight_smile:

6

A Google search for “ArgumentNullException” “CompactHandler” “Unexpected difference” led me to

Value can not be null during compress of backup dir #4252 which was a bit uncertain, but pointed to
Ideas about “System.ArgumentNullException: Value cannot be null.”, “Parameter name: path”

Revert incorrect disposal of IndexVolumeWriter #4137 might be fix on Mar 21, 2020, so should be in
2.0.5.104_canary_2020-03-25, even if I can’t specifically find a mention of the fix in that release note.