"Unexpected difference in fileset" errors [2.0.3.9]

#5

Thanks for the suggestion, I’ll give it a try. I’m pretty sure I tried it before to no effect, but will message had actually progressed (or been covered up) by Unexpected number of remote volumes marked as deleted. now so hopefully a rebuild will do the trick this time.

Out of curiosity, did you also is 7z at some point in the job history? Hopefully not as that would mean the issue isn’t (just) 7z related.

Edit: Unfortunately it didn’t work. I think I may have somehow resolved the issue (perhaps as you did) but then ran into the ““Unexpected number of remote volumes marked as deleted” error” errors. :frowning:

0 Likes

#6

I might have figured out why @JonMikelV and @mr-flibble had trouble getting the fileset number from their error message to match anything in the regular UI. See Backup failing due to unexpected difference in fileset.

By any chance do either of you have your broken database around? It might be useful to experiment with, but we’d probably want to keep testing from harming anything (including destination data) that’s now running well.

0 Likes

#7

Mine is still erroring out every day. It’s a secondary backup so I figured I’d let it sit until somebody had an idea. :slight_smile:

What do you need from me?

0 Likes

#8

See what you think of this idea, suggest any changes, prepare as needed, try it, and tell everyone if it works. Although this backup doesn’t sound too important, you could try to preserve it in case a next-idea is needed. Maybe it could even be used someday to try new Duplicati code to fix this so such manual work isn’t needed.
EDIT: or is it too late, i.e. has the database with “Unexpected difference in fileset” moved to a different error?

Thanks!

0 Likes

#9

Shoot, you’re right - it has moved on to the unexpected number of remote volumes marked as deleted error. :frowning:

I may have backed up the version that failed with the fileset error. I’ll try to check, but it may take me a while to get to it (just had a drive report read errors on my array).

0 Likes

#10

I just ran into the “unexpected difference in fileset” error today - i’m on the latest canary and have made no upgrades since the last working backup ran. The backup job’s destination in this case is Google Drive, and it started with an error message that I couldn’t make much sense of, which suggested running “repair”, then after I ran “repair” (successfully) I now get the “unexpected difference” error message every time I try to run the backup job. I haven’t tried a Recreate yet, but will probably try that next. First I’m trying to run “list broken files” which has been running for 20 minutes now and doesn’t seem to be doing anything (no new entries in the Profiling log in that timespan).

0 Likes

#11

Before you go for recreate, maybe make a backup copy of the database, show us the exact (likely new) fileset message, and perhaps you can try doing a fileset deletion. The error message changed and should be easier.

0 Likes

#12

I’m a little bad at making commandline type stuff work in Duplicati, so I request somewhat verbose directions if you’re willing :stuck_out_tongue:
image

0 Likes

#13

This one looks like the most recent backup developed a problem. You can check that against the “Restore from” dropdown in the GUI for that job, to see if 0: and date match. If so, then backup the database (if you haven’t already), finding it by “Local database path” under the job Backup option. This copy is just-in-case.

Next step is The DELETE command which is probably most easily done using the job Commandline option. Change the command dropdown at screen top to delete, delete all the source paths from Commandline arguments box, Near bottom, Add advanced option of version, find it, set it to 0, then at bottom Run "delete" command now. This should delete your most recent backup. I’m assuming the database is still seemingly good except for the fileset error. If you know of other issues, then the plan should be rethought.

Being extra careful would have you first do a run using the –dry-run and review the output for any worries. Ordinarily, deletes occur all the time unless you’ve got Backup retention at Keep all backup. I guess might as well be cautious and at least see that delete wants to take out only a dlist of the right time along with whatever dblock and dindex files it might have added. That should take only a quick look at its output.

Using the Command line tools from within the Graphical User Interface gives further info on Commandline.

0 Likes

Can't complete backup due to unexpected difference in fileset
#14

I’m currently trying this, and it’s doing nothing (with no output in the profiling-level log either). Did I do something wrong?
This is my second time trying. The first time, it stayed like this for around an hour with no changes. Pressing “stop now” didn’t work either; I eventually had to force quit Duplicati and manually re-launch it.
image

0 Likes

#15

I was expecting some more action. Not sure why it’s not moving. Output when I delete version 0 looks like:

(below with no special logging settings)
  Listing remote folder ...
The following filesets would be deleted:
0: 11/22/2018 4:02:18 PM
Return code: 0

(below after adding --console-log-level=Information)
The operation Delete has started
Backend event: List - Started:  ()
  Listing remote folder ...
Backend event: List - Completed:  (20 bytes)
Deleting 1 remote fileset(s) ...
[Dryrun]: Would delete remote fileset: duplicati-20181122T210218Z.dlist.zip
[Dryrun]: 1 remote fileset(s) would be deleted
[Dryrun]: Remove --dry-run to actually delete files
Compacting because there are 1 fully deletable volume(s)
[Dryrun]: Would delete remote file: duplicati-b2f1fccd564444563b5e07efdfbeefcc6.dblock.zip, size: 699 bytes
[Dryrun]: Would delete remote file: duplicati-i18e930cc658e4935b2842d3f4fae2b75.dindex.zip, size: 607 bytes
[Dryrun]: Would delete 2 files, which would reduce storage by 1.28 KB
The following filesets would be deleted:
0: 11/22/2018 4:02:18 PM
Return code: 0

MENU --> About --> Show log --> Live --> Profiling set up in advance had a lot of output data written to it.
I’m not certain how good it is at picking up after the fact, but I’d hope any new operations would be there. Adding --console-log-level=Profiling right in the Commandline options would show you something I hope.
.
If you tire of this effort, you could go back to your original recreate plan, and see if that solves the issue, however recreates can be slow. If this backup is hundreds of GB (or more), maybe we can try more here.

0 Likes

#16

It appears to be hanging. I have no idea why. It does the same thing if I try running the delete with or without dry-run, and it did it to me before when i tried the list-broken-files commandline. Pressing “stop now” does nothing, and if I exit Duplicati from the systray icon, it goes away but stays active in my task manager (until I forcefully close it from there and re-launch).

Luckily this backup set is only ~6 GB so recreate may be a reasonable plan of action from here. It’s a little frustrating that Duplicati isn’t better at error handling with this sort of stuff - I hate to imagine what would happen with my main PC’s backup (at ~800gb backed up to B2) if this sort of error crept in.

0 Likes

#17

Fortunately this seems to have worked. The recreate only took a few minutes (i didn’t time it but it was on the order of 5 minutes overall), and afterwards a routine backup was run successfully.

1 Like

#18

I also hit this problem on the one machine I upgraded so far from 2.0.3.3 to 2.0.4.5.

Failed: Unexpected difference in fileset version 67: 10/8/2018 3:00:00 PM (database id: 2348), found 2725 entries, but expected 2726

Will read through this thread more closely to see best way to fix…

0 Likes

#19

My turn to stumble upon this. It’s just a tiny test backup, so the only support asked is if anybody can take my analysis and use it to either come up with an easier test case, or fix the code so we can have fewer of these.

Summary is that I ran my 1-file SFTP backup for some reason which I forget, while having another SFTP login from Linux which caused the Duplicati connection to be rejected due to the small server connection limit. This stopped upload of the dblock, even after 5 tries. The dindex wasn’t tried. I fixed SFTP overload, and the dlist made it, but from a destination file point of view a dlist with no dblock or dindex is bad news. From a database point of view, having an entry in the FilesetEntry table without a corresponding one in the File table might get:

2018-11-29 15:34:45 -05 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 0: 11/28/2018 12:04:56 PM (database id: 42), found 0 entries, but expected 1
   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 Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__19.MoveNext()

Everything seemed fine after the 12/28 12:04 backup, but a latent defect was created that caused the above. Looking more closely at the 12:04, one can see some smaller oddities like duplicati-verification.json uploaded before the database deletions to clean up from the failed uploads were done. Unfortunately FilesetEntry table changes appear to need --profile-all-database-queries (added in 2.0.3.10 canary) to log, so I didn’t get them.

This chronological log excerpt is from the glogg log explorer, which includes a regular expression filter. I used:

BackupMainOperation|VerifyConsistency|Backend event: Put|RemoteOperationPut|RetryPut|RemoteUnwantedMissingFile
2018-11-28 12:04:56 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: Starting - BackupMainOperation
2018-11-28 12:04:56 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-BackupMainOperation]: BackupMainOperation took 0:00:00:00.050
2018-11-28 12:04:56 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: Starting - VerifyConsistency
2018-11-28 12:04:56 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Operation.BackupHandler-VerifyConsistency]: VerifyConsistency took 0:00:00:00.000
2018-11-28 12:04:56 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:04:57 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:04:57 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:08 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:20 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip attempt 3 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:20 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:33 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip attempt 4 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:33 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:43 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:47 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip attempt 5 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip (700 bytes)
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:05:47 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:05:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:05:52 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170456Z.dlist.zip attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:05:58 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:10.949
2018-11-28 12:05:58 -05 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-verification.json attempt 1 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:05:58 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170456Z.dlist.zip (538 bytes)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:08 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:06:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:09 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170457Z.dlist.zip attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:06:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:17 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:08.835
2018-11-28 12:06:17 -05 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-verification.json attempt 2 of 5 failed with message: An established connection was aborted by the server.
2018-11-28 12:06:17 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170457Z.dlist.zip (538 bytes)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:19 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:27 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: Starting - RemoteOperationPut
2018-11-28 12:06:27 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:28 -05 - [Retry-Duplicati.Library.Main.Operation.Common.BackendHandler-RetryPut]: Operation Put with file duplicati-20181128T170458Z.dlist.zip attempt 3 of 5 failed with message: Object reference not set to an instance of an object.
2018-11-28 12:06:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-20181128T170458Z.dlist.zip (538 bytes)
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-verification.json (30.70 KB)
2018-11-28 12:06:29 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.186
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-20181128T170456Z.dlist.zip
2018-11-28 12:06:29 -05 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-20181128T170457Z.dlist.zip

which is pretty close to the database view except RemoteOperation table seems to show duplicati-verification.json uploading after the dlist file, instead of at the same time as the log seems to show.
Log has Object reference not set to an instance of an object. but the file uploaded.

From Operation table
Description     Timestamp
Backup          1543424696 November 28, 2018 12:04:56 PM
Backup          1543523685 November 29, 2018 3:34:45 PM

From RemoteOperation table
ID      Operation       Path                                                    Timestamp
390     put             duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip  1543424696 November 28, 2018 12:06:29 PM
391     put             duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip  1543424707 November 28, 2018 12:05:07 PM
392     put             duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip  1543424718 November 28, 2018 12:05:18 PM
393     put             duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip  1543424730 November 28, 2018 12:05:30 PM
394     put             duplicati-b95388eb788f34b97a9ea8589a7f5a227.dblock.zip  1543424743 November 28, 2018 12:05:43 PM
395     put             duplicati-20181128T170456Z.dlist.zip                    1543424747 November 28, 2018 12:05:47 PM
396     put             duplicati-20181128T170457Z.dlist.zip                    1543424762 November 28, 2018 12:06:02 PM
397     put             duplicati-20181128T170458Z.dlist.zip                    1543424779 November 28, 2018 12:06:19 PM
398     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM
399     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM
400     put             duplicati-verification.json                             1543424789 November 28, 2018 12:06:29 PM

From RemoteVolume table
ID      Name
187     duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip
188     duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip
189     duplicati-20181128T170458Z.dlist.zip

From Fileset table
ID      VolumeID        Timestamp
40      182             1539037173 October 8, 2018 6:19:33 PM
41      183             1543423077 November 28, 2018 11:37:57 AM
42      189             1543424696 November 28, 2018 12:04:56 PM

From FilesetEntry table
FilesetID       FileID
40              12074
41              12075
42              12076

From File table
ID
12074
12075
12076 does not exist

I mentioned a premature duplicati-verification.json upload earlier. As expected it’s very confused about things:

PS C:\Program Files\Duplicati 2\utility-scripts> .\DuplicatiVerify.ps1 "C:\zFTPServer\SFTP test 1"
Verifying file: duplicati-verification.json
Verifying file duplicati-20180829T163417Z.dlist.zip
Verifying file duplicati-20180906T152449Z.dlist.zip
Verifying file duplicati-20180909T125449Z.dlist.zip
Verifying file duplicati-20180912T222326Z.dlist.zip
Verifying file duplicati-20180912T222514Z.dlist.zip
Verifying file duplicati-20180913T174743Z.dlist.zip
Verifying file duplicati-20180913T184645Z.dlist.zip
Verifying file duplicati-20180917T135817Z.dlist.zip
Verifying file duplicati-20180924T194939Z.dlist.zip
Verifying file duplicati-20180926T180231Z.dlist.zip
Verifying file duplicati-20180926T182557Z.dlist.zip
Verifying file duplicati-20180926T190447Z.dlist.zip
Verifying file duplicati-20180926T190938Z.dlist.zip
Verifying file duplicati-20180930T182333Z.dlist.zip
Verifying file duplicati-20181008T221933Z.dlist.zip
Verifying file duplicati-20181128T163757Z.dlist.zip
File missing: duplicati-20181128T170456Z.dlist.zip
File missing: duplicati-b1eef7da95a104c56a6d0b96d26e0e28a.dblock.zip
Verifying file duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip
File missing: duplicati-b2ff738d7306d4756aa060a212354ad0a.dblock.zip
File missing: duplicati-bb910ba99254041d2ae3ab2732448340b.dblock.zip
File missing: duplicati-bfd1d745ec2734aa89652f200fd105e4b.dblock.zip
Verifying file duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip
Found extra file which is not in verification file: duplicati-20181128T170458Z.dlist.zip

Errors were found

STATISTICS:
        Temporary - Count 0, Size 0.0 GB
        Uploading - Count 0, Size 0.0 GB
        Uploaded - Count 0, Size 0.0 GB
        Verified - Count 18, Size 0.0 GB
        Deleting - Count 0, Size 0.0 GB
        Deleted - Count 167, Size 0.0 GB

        Blocks - Count 72, Size 0.0 GB
        Files - Count 41, Size 0.0 GB
        Index - Count 72, Size 0.0 GB

PS C:\Program Files\Duplicati 2\utility-scripts>

EDIT: 2.0.4.5 beta on Windows
EDIT 2: duplicati-b2dc362dd4f62431391091a117256c441.dblock.zip and duplicati-i257753298c614dfcb86a5cade4a7ecff.dindex.zip went up at 11:38:04 in the previous backup which I thought about showing further, but didn’t…
EDIT 3: Reproduced this again with FTP and Filezilla server, turning off Write permission to make the dblock upload fail, then turning it on again to let the dlist and duplicati-verification.json file uploads through. I’ve not been able to reproduce this when the dlist also fails, which means the test case may be awkward for awhile… Here is me doing a test on that broken backup to see if the improved error message aimed correctly at which version to delete, and in this test it did, however the version was 0 (but perhaps it always is for this problem). Although I haven’t written up a full test case procedure yet, if anyone is eager to try, set --retry-delay to some human-friendly value (e.g. 60 seconds) and you don’t need to keep --number-of-retries at its default value 5.

1 Like

Mismatching number of blocklist hashes detected on blockset
Error Unexpected difference in fileset version
File length is invalid?
Recovery not listing new backups
Reproducible: Unexpected difference in fileset version X: found Y entries, but expected Z
Error Unexpected difference in fileset version
Is there any way to fix an "unexpected difference in fileset" error other than deleting?
Unexpected difference in fileset version 4: ...found 6180 entries, but expected 6181
#20

I suspect it’s not always the case, such as during retention cleanup (which is where I think I bumped into mine).

Awesome work tracking stuff down!

So does Duplicati know when the dblock upload fails or does it think it succeeded and continues sending files?

I’m guessing the former as otherwise we could replicate the issue with a simple dblock deletion…

0 Likes

#21

Yes it’s not always 0, although the new message seemed to be right on target to delete the very-old-version.

I’m not sure if my little test would have had more than one dblock to send, and I don’t know what it’s thinking.

This report got this error with a 5GB dblock-size and involved trying to get the backup stopped. I don’t know whether there’s also a test case that could be made on that. Throttling might allow test with a smaller dblock.

0 Likes

#22

Duplicati on my PC generated the “Unexpected difference in fileset” error a few days after updating from a previous beta (non-canary) version to 2.0.4.5, after which I adjusted the “Excludes” as “default windows files” was no longer valid option - these were adjusted to exclude Hidden, System, and Temporary files.

My version of the error: Dec 16, 2018 9:55 AM: The operation Backup has failed with error: Unexpected difference in fileset version 0: 12/15/2018 3:55:00 PM (database id: 105), found 45015 entries, but expected 45016

I am no longer receiving the “Unexpected difference in fileset” error/warnings after deleting the related backup using the --version=0 qualifier as suggested in this or another post on the same topic. I did not run any database repair or re-create. @JonMikeIV - I made a copy of my local database before the repair and would be willing to provide it for use in troubleshooting the error.

AB

0 Likes

#23

Hello @Ambo_Bartok, welcome to the forum - and thanks for letting us know what resolved the issue for you!

I’m going to defer to @kenkendk on how useful the database copy could be for troubleshooting.

1 Like

#24

I finally got around to trying to fix this. The delete command to remove the offending version worked fine for me. Backups now working properly on 2.0.4.5.

Thanks everyone!

0 Likes

Backups fail with error: Object reference not set to an instance of an object