Unexpected difference in fileset version 4: ...found 6180 entries, but expected 6181

I have been getting this fatal error for weeks. I started getting this error on one my backup sets. I’ve not changed anything on that configuration AFAIK.

2.0.4.5 (2.0.4.5_beta_2018-11-28)

There are 16 versions of this backup set.
It runs daily.
The most recent successful run was on March 2nd.
The fileset from version 4 (2/24) has the unexpected difference in the number of entries.

Given that this is a moderately large fileset (57GB), I’d love to know what you’d suggest doing to repair it.

 Failed: Unexpected difference in fileset version 4: 2/24/2019 4:03:11 AM (database id: 100), found 6180 entries, but expected 6181
    Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 4: 2/24/2019 4:03:11 AM (database id: 100), found 6180 entries, but expected 6181
      at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency (System.Int64 blocksize, System.Int64 hashsize, System.Boolean verifyfilelists, System.Data.IDbTransaction transaction) [0x00370] in <c6c6871f516b48f59d88f9d731c3ea4d>:0

I’m now getting this error on 3 jobs. One of them has logging enabled and I will look over the logs today to see if anything jumps out. It’s a backup of large (multi-GB) tarred gzip files. First it was failing to Dropbox, and now it’s failing to an attached USB drive (same source).

ETA; so far, I have been able to delete the offending backups, but the error has always returned on subsequent job runs eventually.

Same here… there is one backup job on one machine that has this issue every week or so. It’s always the same machine and same backup job. Not sure why. I’m running the latest “beta” version on probably 10 machines.

Almost the same experience here. I have 26 jobs running on one machine. One job started with this failure (I’m pretty sure after I upgraded to 2.0.4.5 but I don’t have details on that), so I copied the job, which ran successfully for a couple of months before it failed, and this morning the same job with the USB drive as a destination failed for the first time.

I will admit his issue has really shaken my confidence in Duplicati because so far the only way to truly recover from it (even temporarily) has been to essentially delete all the backups and start over.

I scanned the information-level logs of the two failing jobs and nothing unusual appears on the days that failed vs any other days.

I went back to the “Restore” option on one job for the failed day in question. This job backs up 6 files every day. On the failed day, one of the files is missing from the “restore” file list (I expand the source folder and the file isn’t there).

So I have two issues:

  1. why is the file missing (maybe an issue with the source, etc. - I can live with this since I run backups every day and I retain a handful)

  2. why doesn’t Duplicati warn of the failure and then keep backing up? I’d rather have a backup set with one missing file that eventually gets deleted based on my retention settings than the situation I have now, which is that a backup hasn’t been run for more than 2 weeks because some random failure happened on February 26.

The only frequently-successful repair that I know of is to delete the fileset version, which is probably what @haus was suggesting (unless somehow it now requires deleting all the versions). What’s your history with the error? That might hold you for awhile if it’s rare. It’s too frequent for the two who have just posted.

Is there any way to fix an “unexpected difference in fileset” error other than deleting? is @drwtsn32 post although the original poster was also trying to avoid doing this, but troubleshooting there didn’t get very far.

The easiest way to delete a fileset is probably using the job’s GUI Commandline and adjusting the screen.

The BACKUP command syntax gets turned into The DELETE command by deleting the source files from Commandline arguments and adding --version=4. Change Command at top to delete, then Run at bottom.

Getting the error to stay away has been a problem for some people, but I hope we can use their results to try to figure out why it only seems to affect certain backups. There has definitely been a network-problem cause identified by me here, reproduced by @warwickmm here, leading to possible code fixes at below:

Ensure that failed put operations throw exception #3697

The problem is that this is not the only cause. People have seen it on backups to local disk. What’s yours?

Manual compact ran, now unexpected difference in fileset is @haus finding that compact without enough temporary file space can cause this. There have also been theories involving things like retention deletions.

I’m open to all kinds of theories, but rely on people who can see it to try to guess what encourages it and to consider adding logging, consider posting logs, and consider even posting database bug reports which are sanitized versions of the database, e.g. with source pathnames and other data removed to protect privacy. Posting big files here is not possible, so you’d post a link to a cloud storage share, Firefox Send, or similar.

So deleting versions stopped helping even temporarily? I believe deletion can also cause auto-compact, so using --no-auto-compact on the delete command might see whether delete itself moves the problem into a different fileset, or if it’s one of the follow-on operations (such as possible) automatic compact that did that. Ultimately this is the kind of thing that database dumps and the right expert (maybe not me?) can help with.

The “unusual” is sometimes the run before, at least it is in the case where network errors on a put upload causes Duplicati to bail. It does this same sanity test twice, once before a backup, and again after (but if it gets an exception of some sort, that might prevent the post-backup sanity test – so it hits that on next run).

This is actually a nice simple backup in a way. Did it say it found 5 entries, but expected 6? If so, then the display might be going by the left number, which I think is more realistic in terms of what can be restored.

We’re not likely to hear from the original designer, however this is one of the self-checks Duplicati does to make sure its various database records are in order. Programs are typically written to rely on things being the way they should be. If things look wrong, sometimes it’s better to stop than to spread the mess further.

Technical details of this internal check are found here. Count from those SQL queries should be the same. With such a small list, you could even humanly compare the file lists with an SQLite browser such as this.

For those of you who are seeing the error too much, I’d suggest looking in logs for compact operations just before it. Here is an example of how it looks in job logs. You can also see if using –no-auto-compact helps, change Backup retention to Keep all backups, and (if network backup) set –number-of-retries higher.

Fileset 0 is the newest, so damage to an older fileset such as 4 (with 16 versions total) seems like it might be some sort of non-backup maintenance work such as a compact coming through, doing wider changes.

Though there are reports of this happening on systems that are always on, it’d still be a good idea to see if that happens to you, or if things like sleep or restart tend to encourage this problem to show up sometime.

1 Like

Thank you for that info. Another version of this same backup job (this time to another local USB drive) failed this morning at ~4am. The error is:

Failed: Unexpected difference in fileset version 6: 3/18/2019 3:43:02 AM (database id: 53), found 11 entries, but expected 12

Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 6: 3/18/2019 3:43:02 AM (database id: 53), found 11 entries, but expected 12

When I look in the logs for this job, it runs a compact operation every single night except 3/17, the night before, which seemed like it might be significant, but then I went back to another version of this job which backs up to dropbox and failed March 7, but it ran a compact on March 6. So maybe nothing useful there.

So now 4 separate versions of this backup job have all failed in the last few weeks. Two backing up to dropbox, and two backing up to local USB drives. If I start logging these jobs to a file, which log level do you suggest I use to get the most info? I tried “verbose” but it doesn’t seem to add much. Is “profiling” a better choice?

I don’t recall all the details of deleting versions (I will see if I posted it anywhere here), but I think I remember one time deleting the offending fileset only to find out that the next one had failed as well, and so on until I ended up deleting all of them. My solution to this unexpected fileset difference issue right now is to delete the database for the job, then delete all files on the remote side, and start the backup as if it was a new job.

If you want a huge amount of output, use --log-file-log-level=profiling and --profile-all-database-queries which isn’t yet in the manual, but was added in Release: 2.0.3.10 (canary) 2018-08-30 as a log option:

Removed some logging details in core performance areas (can be re-enabled with --profile-all-database-queries )

So “better” depends on your goal, but the above is as much logging as I think there is. Rotating or deleting logs would probably be good, and maybe install a large-log-file viewer like glogg, if your editor isn’t enough.

As a side note, I cranked up my scheduled backup frequency here, and also threw in some other suspect things such as smart retention. I managed to get this problem in the 6:45 run detected in the 6:55 run. The difference was fileset 0 so it may or may not be like the non-0 cases. Nevertheless I’m trying to look at it…

Exactly what inspired it isn’t clear because there are many things going on, including compact and deletion which are at least expected (whether they’re perfect isn’t known) and also some other oddball errors below:



Failed: Unexpected difference in fileset version 0: 3/25/2019 6:45:00 PM (database id: 99), found 432 entries, but expected 433
Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 0: 3/25/2019 6:45:00 PM (database id: 99), found 432 entries, but expected 433
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass32_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()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.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.Operation.BackupHandler.Run(String[] sources, IFilter filter)
   at Duplicati.Library.Main.Controller.<>c__DisplayClass13_0.<Backup>b__0(BackupResults result)
   at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)

Log data:
2019-03-25 18:55:50 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\PortableApps\Notepad++Portable\App\Notepad++\Notepad++Portable\
System.UnauthorizedAccessException: (5) Access is denied: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy68\PortableApps\Notepad++Portable\App\Notepad++\Notepad++Portable\]
   at Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   at Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetFileAttributes(String path)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__23.MoveNext()
2019-03-25 18:55:53 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\PortableApps\Notepad++Portable\App\Notepad++\plugins\
Alphaleonis.Win32.Filesystem.DeviceNotReadyException: (21) The device is not ready: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy68\PortableApps\Notepad++Portable\App\Notepad++\plugins\]
   at Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   at Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetFileAttributes(String path)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__23.MoveNext()
2019-03-25 18:55:53 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\PortableApps\Notepad++Portable\App\Notepad++\themes\
Alphaleonis.Win32.Filesystem.DeviceNotReadyException: (21) The device is not ready: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy68\PortableApps\Notepad++Portable\App\Notepad++\themes\]
   at Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   at Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetFileAttributes(String path)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__23.MoveNext()
2019-03-25 18:55:53 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\PortableApps\Notepad++Portable\App\Notepad++\updater\
Alphaleonis.Win32.Filesystem.DeviceNotReadyException: (21) The device is not ready: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy68\PortableApps\Notepad++Portable\App\Notepad++\updater\]
   at Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   at Alphaleonis.Win32.Filesystem.File.GetAttributesExCore[T](KernelTransaction transaction, String path, PathFormat pathFormat, Boolean returnErrorOnNotFound)
   at Duplicati.Library.Snapshots.SystemIOWindows.GetFileAttributes(String path)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__23.MoveNext()
2019-03-25 18:55:53 -04 - [Warning-Duplicati.Library.Main.Operation.Backup.FileEnumerationProcess-FileAccessError]: Error reported while accessing file: C:\PortableApps\Notepad++Portable\App\Notepad++\
Alphaleonis.Win32.Filesystem.DeviceNotReadyException: (21) The device is not ready: [\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy68\PortableApps\Notepad++Portable\App\Notepad++\*]
   at Alphaleonis.Win32.NativeError.ThrowException(UInt32 errorCode, String readPath, String writePath)
   at Alphaleonis.Win32.Filesystem.FindFileSystemEntryInfo.FindFirstFile(String pathLp, WIN32_FIND_DATA& win32FindData)
   at Alphaleonis.Win32.Filesystem.FindFileSystemEntryInfo.<Enumerate>d__3`1.MoveNext()
   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
   at Duplicati.Library.Snapshots.WindowsSnapshot.ListFiles(String localFolderPath)
   at Duplicati.Library.Utility.Utility.<EnumerateFileSystemEntries>d__23.MoveNext()
2019-03-25 18:55:54 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 0: 3/25/2019 6:45:00 PM (database id: 99), found 432 entries, but expected 433
   at Duplicati.Library.Main.Database.LocalDatabase.VerifyConsistency(Int64 blocksize, Int64 hashsize, Boolean verifyfilelists, IDbTransaction transaction)
   at Duplicati.Library.Main.Operation.Backup.BackupDatabase.<>c__DisplayClass32_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()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()

Above is the contents of the email reporting the error. It’s picked out some things from 6:55 log, but to see 6:45 I have to use the log files that I set myself (mainly so analysis of problems that spring up is possible).

@ts678 - thank you so much for the detailed response. It’s good to know that folks are tracking the issue.

In my case, this backup is run by an always-on machine targeting a remote destination (Backblaze B2).

I just ran the delete operation on the offending version which has let the backup start running again normally.

For now, I’m not going to make any of the suggested changes because this is the first time I’ve hit this issue. I’ll keep things running as-is and report back if I hit the issue again.