Consistent Unexpected difference in fileset version

Support
1

Running Duplicati 2.0.4.5_beta_2018-11-28

We’ve now had the same error within one particular backup job four times, each a number of weeks apart.

I always reports “found 64 entries, but expected 65”, and it always takes a full “Recreate (delete and repair)” operation to bring the job back to normal.

The full error is below. Can anyone offer why this keeps happening?

Failed: Unexpected difference in fileset version 6: 3/23/2019 4:00:00 AM (database id: 56), found 64 entries, but expected 65 Details: Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 6: 3/23/2019 4:00:00 AM (database id: 56), found 64 entries, but expected 65

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.b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.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.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.Controller.<>c__DisplayClass13_0.b__0(BackupResults result) at Duplicati.Library.Main.Controller.RunAction[T](T result, String& paths, IFilter& filter, Action`1 method)

Log data: 2019-04-01 10:11:49 +01 – [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error Duplicati.Library.Interface.UserInformationException: Unexpected difference in fileset version 6: 3/23/2019 4:00:00 AM (database id: 56), found 64 entries, but expected 65

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.b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.<>c__DisplayClass3_0.b__0() at Duplicati.Library.Main.Operation.Common.SingleRunner.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.d__19.MoveNext()

2

I too experience this problem every now and then, but only on one backup set on one PC. Very weird. Not sure what the root cause is.

That being said, you can “fix” this by just deleting the backup version that has the issue. It is faster than deleting/recreating the database.

So you could delete backup version 6 and then future backups should be fine (until it possibly happens again).

3

So I’ve waited until this recurred, which happened again last night (version 7, again found 64 entries, but expected 65).

I deleted version 7 using command line and tried to run the backup again, but now I get the same error but for a different version:

“Unexpected difference in fileset version 3: 6/12/2019 5:00:00 AM (database id: 30), found 64 entries, but expected 65”

Delete command reported removing backups from various dates, which I don’t like the sound of at all! I’d rather this just ran every night without hitting this issue, so could use a fix rather than a workaround.

Anyone?

4

I have seem a couple other posts where people had to repeat the delete X process a few times to clear up all the errors. I have never had to delete more than one myself (until the problem happened again weeks later).

I would not worry about the files with certain dates being deleted when you delete a specific backup version. Because of deduplication, the file dates corresponding to a particular backup version don’t necessarily match. If you delete a version and Duplicati realizes that particular backup file is no longer referenced by any remaining backup versions, it will be deleted.

I’m not sure if this problem has been truly fixed in the latest canary versions or not, I am still running beta 2.0.4.5.

5

So I worked through five deletes until the backup ran without error. I’ll monitor it and post back here if it runs into the problem again.

Might be a few weeks again though!

6

How many deletions did you need to do in total?

7

Could you look at your job logs at the last log before this failure, and see if it ran a compact? I’m currently looking at a problem where the newest fileset (0) gets this problem, but while looking I saw some suspect code that possibly could do damage to the File table which might cause a problem in some older filesets.

For any developers who know the database, does it seem right to delete a File row based on MetadataID? Maybe code meant to map MetadataID to a BlocksetID, then use BlocksetID for cleanup (like other lines)? Different handling of different table deletions might cause the unexpected difference (haven’t proven it yet).

Introduction of the MetadataID code was done here as part of a fix, but was it right? Note I’m not an expert.

8

Hi

I think it did run a compact. The last successful run was on the 15th June, and interestingly there are no logs for the failures inbetween. Anyway here is the log from the 15th.

DeletedFiles: 8
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 64
OpenedFiles: 8
AddedFiles: 8
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 896336816
SizeOfExaminedFiles: 7162879996
SizeOfOpenedFiles: 896336816
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
DeletedFileCount: 40
DownloadedFileCount: 0
UploadedFileCount: 0
DeletedFileSize: 998829304
DownloadedFileSize: 0
UploadedFileSize: 0
Dryrun: False
MainOperation: Compact
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 6/15/2019 5:03:28 AM (1560571408)
BeginTime: 6/15/2019 5:03:04 AM (1560571384)
Duration: 00:00:24.1405368
Messages: [
2019-06-15 05:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2019-06-15 05:00:04 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2019-06-15 05:00:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (592 bytes),
2019-06-15 05:00:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
2019-06-15 05:00:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
…
]
Warnings:
Errors:
BackendStatistics:
RemoteCalls: 83
BytesUploaded: 895830849
BytesDownloaded: 52446103
FilesUploaded: 37
FilesDownloaded: 3
FilesDeleted: 41
FoldersCreated: 0
RetryAttempts: 0
UnknownFileSize: 0
UnknownFileCount: 0
KnownFileCount: 588
KnownFileSize: 14723449852
LastBackupDate: 6/15/2019 5:00:00 AM (1560571200)
BackupListCount: 8
TotalQuotaSpace: 2199023255552
FreeQuotaSpace: 95101105886
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
Messages: [
2019-06-15 05:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2019-06-15 05:00:04 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2019-06-15 05:00:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (592 bytes),
2019-06-15 05:00:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
2019-06-15 05:00:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
…
]
Warnings:
Errors:
DeleteResults:
DeletedSets: [
Item1: 8
Item2: 6/7/2019 5:00:00 AM (1559880000)
]
Dryrun: False
MainOperation: Delete
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 6/15/2019 5:03:28 AM (1560571408)
BeginTime: 6/15/2019 5:03:00 AM (1560571380)
Duration: 00:00:28.1874909
Messages: [
2019-06-15 05:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2019-06-15 05:00:04 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2019-06-15 05:00:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (592 bytes),
2019-06-15 05:00:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
2019-06-15 05:00:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
…
]
Warnings:
Errors:
RepairResults: null
TestResults:
MainOperation: Test
Verifications: [
Key: duplicati-20190612T040000Z.dlist.zip.aes
Value: ,
Key: duplicati-ifd2a1aadf67449b894743bb14008c46e.dindex.zip.aes
Value: ,
Key: duplicati-b5f202fa5d547487f8db5162ed2d2a21d.dblock.zip.aes
Value:
]
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 6/15/2019 5:03:45 AM (1560571425)
BeginTime: 6/15/2019 5:03:34 AM (1560571414)
Duration: 00:00:10.8905985
Messages: [
2019-06-15 05:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2019-06-15 05:00:04 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2019-06-15 05:00:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (592 bytes),
2019-06-15 05:00:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
2019-06-15 05:00:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
…
]
Warnings:
Errors:
ParsedResult: Success
Version: 2.0.4.5 (2.0.4.5_beta_2018-11-28)
EndTime: 6/15/2019 5:03:45 AM (1560571425)
BeginTime: 6/15/2019 5:00:00 AM (1560571200)
Duration: 00:03:45.3544832
Messages: [
2019-06-15 05:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
2019-06-15 05:00:04 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: (),
2019-06-15 05:00:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (592 bytes),
2019-06-15 05:00:45 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
2019-06-15 05:00:56 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb0310265e9fa4be8873f2214ff375fe2.dblock.zip.aes (49.97 MB),
…
]
Warnings:
Errors:

9

Hi @drwtsn32 just noticed your question. I did four deletions to get it to work. Each time I tried to run another backup it told me about a different version problem. I can’t 100% remember the sequence but here’s the logs:

First Deletion:

DeletedSets: [
Item1: 4
Item2: 6/11/2019 5:00:00 AM (1560225600),
Item1: 5
Item2: 6/10/2019 5:00:00 AM (1560139200),
Item1: 6
Item2: 6/9/2019 5:00:00 AM (1560052800),
Item1: 7
Item2: 6/8/2019 5:00:00 AM (1559966400)
]

Second Deletion:

DeletedSets: [
Item1: 3
Item2: 6/12/2019 5:00:00 AM (1560312000)
]

Third Deletion

DeletedSets: [
Item1: 2
Item2: 6/13/2019 5:00:00 AM (1560398400)
]

Fourth Deletion

DeletedSets: [
Item1: 1
Item2: 6/14/2019 5:00:00 AM (1560484800)
]

10

“Unexpected difference in fileset” test case and code clue #3800 is my writeup of an investigation into a problem where fileset 0 was having trouble. The problem and code mentioned above (seeking developer comment) was mentioned as well, but my fix is in a different code area. I debugged the issue that I have.

For any who can help debug, there are some notes there.

For any who are willing to change/build code, that’s there.

Making a setup file from code
How to generate Installation File from github code
have gotten no replies yet, but one workaround is:

For any willing to patch a .dll at CIL level, that works and has made a huge difference in my testing so far.

If people can help, there might be a chance to squeeze this into upcoming beta, otherwise it’s a long wait.

1 Like
11

I would love to help you test this out - it’d be great if this problem were solved before the next beta!

If you have figured out a way to intentionally trigger the problem so we can test with and without the fix, that would be extremely helpful. (I need to read through your posts on the topic still…)

12

Agreed. This has been my own top backup-breaker. It took some time to track it down to the code though.

What you describe is exactly what #3800 has – steps to trigger (I hope you also can) derived from actual broken backup, then proposed fix, then testing fix using the same often-run backup that breaks without fix.

Wonderful to have your help. I think we’re both tired of guiding people through version deletes (better than nothing, but sometimes ineffective). Note the caveat on my fix though. It’s not in the code lines seen here. Possibly there are two problems, or maybe the theory in this post is wrong. The other is proven by testing.

13

When i made setup file it did not worked after i install on windows. The icon try do not appeared up as well as no output when i tried to open installed output.

I have served much time but did not got any feedback. If anyone could really assist on this would be great.

Thanks,

parwa

14

If you’re explaining the unrelated issue (which admittedly I mentioned, but had only a workaround for) I’d hope the discussion happens, but on the “Making a setup file from code” topic. I’d like some nice directions myself.

15

Do we have a rough ETA on when the proposed fixed might be merged and included in a future release? I was hoping it’d make it into the latest build or two. I got hit by this bug a couple weeks ago and have been holding off ditching the current multi TB backup and starting over.

BTW, great work @ts678 and team this one looked pretty tricky to nail down.

16

I see no recent note or progress on below. Disappointed because pull request was 3 days before canary.

Fix database issue where block was not recognized as being used #3801

There was a hot item to “ship”. The documented change in 2.0.4.20 is Amazon Cloud Drive loss warning. Experimental yesterday is basically that canary, so maybe we see Duplicati breaking for 9 more months?

This change could be considered a fix to core logic, and possibly people are cautious about putting it in… Things are definitely broken at the moment, but it’s important to be very sure the cure causes no troubles. Ordinarily that’s what canary is for, however canary during lead-up to a beta is probably treated cautiously.

If the fix is not allowed into the beta, my plan is to patch my installation so I can get some needed stability. This can be field-patched by anyone who dares do the same, as it’s just a string edit with a debugger tool. Because many people are not willing, I’m not sure what the future will hold for this issue. I guess we’ll see.

You actually might be a good candidate to run the fix through its paces, as a test. My backups are smaller. Experimental itself could probably benefit from a workout of that size, as I’m not sure if canary sees those.

17

I saw the PR and decided not to roll it into the experimental. It is quite possible that it will fix many issues (and yes there are some annoying ones) but I do not want to annoy people on the “mostly-stable” channel with something untested that might have unexpected quirks.

My plan is currently is to release a beta 2019-07-15 based on the current experimental.

There are no rules stating that we should wait that long between beta releases (we really should do more frequent releases).

18

I have put up a new canary with the fix included. If we do not hear any bad news from that, I will roll a new experimental with thte fixes. I think the fixes are important enough that we should consider delaying the next beta to get them included. But we cannot delay for too long, as the AmzCD is shutting down on a fixed date and I want the warning out before the shutdown happens.

19

Thanks for the quick turn around @kenkendk! I agree the message about AmzCD shutting down is pretty important.

I grabbed the latest 2.0.4.22 canary but it doesn’t seem to fix an already corrupted DB. I’ve tried deleting a couple more versions that report the missing entry but it just reports as missing in the next version.

Was I overly optimistic and the fix will only prevent future corruption and not salvage an existing DB?

Let me know if there is anything I could/should do or try if that is helpful.

20

Correct. I think the only sometimes-workaround has been version deletions, but the “prevent” idea isn’t completely proven either (need field experience over the long term). One cause is hopefully addressed.

If you want to get into manual database editing, coming up with a method might be a bit easier now that there’s a better understanding of one cause. It will still probably take some doing, and maybe a DB bug report with further manual sanitization due to some privacy flaws which have been added or discovered.