Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Unexpected difference in fileset" test case and code clue #3800

Closed
ts678 opened this issue Jun 19, 2019 · 18 comments

Comments

@ts678
Copy link
Contributor

commented Jun 19, 2019

  • I have searched open and closed issues for duplicates.

Environment info

  • Duplicati version: 2.0.4.5 beta
  • Operating system: Windows 10
  • Backend: Local folder

Description

"Unexpected difference in fileset version 0...". I investigated, found seeming cause, then built steps. Current test case does not perfectly reproduce my actual failure, but it's easy to run, and it's a start.

The initial debug was basically a profiling log with --profile-all-database-queries, and a --run-script-before to keep a trail of DB copies. After trials showing compact seemed essential, I held off on that until the usual (small) number of backups-to-failure, ran compact, got issue, checked logs and DBs.

One basic problem is that the wasted space calculator ignores blocks that been deleted, even if the block gets used again in a different file (or a reapparance of the same file), so I found that a dblock containing a file data block got deleted as empty. Here's an example test that checks hash and size:

var usedBlocks = @"SELECT SUM(""Block"".""Size"") AS ""ActiveSize"", ""Block"".""VolumeID"" AS ""VolumeID"" FROM ""Block"", ""Remotevolume"" WHERE ""Block"".""VolumeID"" = ""Remotevolume"".""ID"" AND ""Block"".""ID"" NOT IN (SELECT ""Block"".""ID"" FROM ""Block"",""DeletedBlock"" WHERE ""Block"".""Hash"" = ""DeletedBlock"".""Hash"" AND ""Block"".""Size"" = ""DeletedBlock"".""Size"") GROUP BY ""Block"".""VolumeID"" ";

Maybe the above decision to ignore a block's existence needs another qualifier (not fully tested) like

AND ""Block"".""VolumeID"" = ""DeletedBlock"".""VolumeID""

A second suspect problem is described in Consistent Unexpected difference in fileset version where most of the tables get cleanup based on BlocksetID, but in addition to that, File cleans up based on MetadatasetID without mapping it to BlocksetID. This seems able to do random additional File table deletions compared to the other tables, causing "Unexpected difference" in the differently built lists. There's no test case yet for that variant of the issue, but below are tech notes behind the listed case:

save file A
backup to VolumeID 3 with file A data and metadata, folder metadata
delete file A
backup to VolumeID 6 with folder metadata
(delete version 1 loads DeletedBlock table including file A data)
save file A
backup to VolumeID 9 with file A data and metadata, folder metadata
(delete version 1 just deletes older metadata row in Block table)
delete file A
save file A
backup to VolumeID 12 with new metadata. The old blockset is reused
(delete version 1 leaves file A data as the only block in VolumeID 9)
storedlist is 2
expandedlist is 2
		SELECT SUM("Block"."Size") AS "ActiveSize"
			,"Block"."VolumeID" AS "VolumeID"
		FROM "Block"
			,"Remotevolume"
		WHERE "Block"."VolumeID" = "Remotevolume"."ID"
			AND "Block"."ID" NOT IN (
				SELECT "Block"."ID"
				FROM "Block"
					,"DeletedBlock"
				WHERE "Block"."Hash" = "DeletedBlock"."Hash"
					AND "Block"."Size" = "DeletedBlock"."Size"
				)
		GROUP BY "Block"."VolumeID"
doesn't think there's anything in VolumeID 9 because its block is in DeletedBlock
compact
Listing remote folder ...
  Deleting file duplicati-b43d3cd3fa25c474d9a96ad3091ffafe9.dblock.zip (951 bytes) ...
  Deleting file duplicati-ie9f790e188524212b3c208020aa7e14e.dindex.zip (650 bytes) ...
  Deleting file duplicati-be935f3b31c534486bc4dfe07e0d058fb.dblock.zip (508 bytes) ...
  Deleting file duplicati-i8f5533b052f541d097c4f7582c1d8959.dindex.zip (567 bytes) ...
  Deleting file duplicati-b812fe935651447358db569cbceae734d.dblock.zip (945 bytes) ...
  Deleting file duplicati-ife46ef7d950a479591f720d0777c62fd.dindex.zip (650 bytes) ...
  Uploading file (1.97 KB) ...
storedlist is 2
expandedlist is 0
backup
Unexpected difference in fileset version 0: 6/19/2019 2:33:25 PM (database id: 4), found 0 entries, but expected 2

Steps to reproduce

  1. Configure a backup. Tested with local folder and no encryption, but I don't think this matters.
  2. Make empty folder to be the backup source. Use --no-auto-compact and --keep-versions=1.
  3. open notepad and type a word
  4. save file
  5. backup
  6. delete file
  7. backup
  8. save file
  9. backup
  10. delete file
  11. save file
  12. backup
  13. compact
  14. backup
  • Actual result:
    Unexpected difference in fileset version 0: 6/19/2019 3:18:06 PM (database id: 4), found 0 entries, but expected 2

  • Expected result:
    Backup works without failure

Screenshots

Debug log

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 20, 2019

Testing with the fix has already completed an order of magnitude more backups than it would before the fix.

I had to use "Edit IL Instructions..." in dnSpy because C#-level editing chokes a lot, and it did here. Here's the IL instruction behind the SELECT that I've been running:

26 0049 ldstr "SELECT SUM("Block"."Size") AS "ActiveSize", "Block"."VolumeID" AS "VolumeID" FROM "Block", "Remotevolume" WHERE "Block"."VolumeID" = "Remotevolume"."ID" AND "Block"."ID" NOT IN (SELECT "Block"."ID" FROM "Block","DeletedBlock" WHERE "Block"."Hash" = "DeletedBlock"."Hash" AND "Block"."Size" = "DeletedBlock"."Size" AND "Block"."VolumeID" = "DeletedBlock"."VolumeID") GROUP BY "Block"."VolumeID" "

What would be helpful would be if someone else could reproduce the failure (should be easy but TBD), and its fix (harder unless one builds or uses dnSpy). Hardest of all might be for an expert to review logic behind it, or maybe that's what happens when someone puts out a Pull request for review? Then how to release it? Consistent Unexpected difference in fileset version has an update with test results and beta timing worries.

@drwtsn32x

This comment has been minimized.

Copy link
Contributor

commented Jun 20, 2019

This is an excellent writeup! I will spend some time to see if I can reproduce the problem using your listed steps.

I'm not understanding what you mean by

C#-level editing chokes a lot

You were not able to edit the source and recompile?

@drwtsn32x

This comment has been minimized.

Copy link
Contributor

commented Jun 20, 2019

Just followed your recipe with 2.0.4.5 and was not able to reproduce the error yet.

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 21, 2019

not able to reproduce the error yet

I caused it several times while watching the DB using DB Browser for SQLite, however I do have some extra settings (such as mail sending) floating in from my default settings, but none look suspicious. Regardless, I can also test on a different 2.0.4.5 than my "production" system, now at 237 backups without the problem.

If you look in the DB, the key two spots to look hard are before and after the compact, but the tech notes explain what should be happening at every step. If reading those, note "(delete" is from --keep-versions=1.

@warwickmm warwickmm added the bug label Jun 21, 2019

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 21, 2019

Thanks for your efforts in investigating this. Unfortunately, I am unable to reproduce the error using your instructions with 2.0.4.5 on Linux.

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 21, 2019

Not sure what's up. I just reproduced it again on a new 2.0.4.5 install with no special settings beyond those mentioned. I did use no encryption. Filename of test file was A.txt, contents was letter A. Save is with Ctrl-S. Have some other things to do, but I took DB snapshots after every backup, forecast the failure, then hit it...

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 21, 2019

I just tried again with the same filename (A.txt) and contents (A), and still couldn't reproduce. I don't think my compact step is doing anything (the logs show "Compacting not required"). Is the compact step actually doing something for you?

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 21, 2019

Is the compact step actually doing something for you?

Very much so. Pairs of dblock/dindex shrank from 4 (from 4 backups) to 1 (should have been 2 because the dblock of file data from step 9 was still in use along with a dblock having file/folder metadata from step 12.

Compact delete of first two backup dblock/dindex is normal because they are "fully deletable volume(s)" in the Duplicati message written here. This last run kept no logs, because I was keeping it as plain as possible. Data preservation was manual, so here it comes, starting with the before and after compact, as mentioned.

Below is the Block table after step 12 backup:

image

Below is the DeletedBlock table where one can forecast the corruption because ID 3 in VolumeID 3 had the same hash and size as the currently-in-use Block table has as ID 6 in VolumeID 9, so SQL will conflate them.

image

Below is the Block table after step 13 compact:

image

Below is FilesetEntry table with entries for the sole (due to --keep-versions) remaining Fileset which is 4:

image

Below is the File table which got emptied inadvertently even though FilesetEntry table is still using files:

image

I'm not sure where things went different between my runs and yours (thank you both for the initial trials). Somewhat easier perhaps than the textual tech notes would be to compare Block tables after 5, 7, and 9.

Below is Block table after step 5 backup:

image

Below is Block table after step 7 backup:

image

Below is Block table after step 9 backup:

image

Some things such as metadata will be different for your run, but the 1-byte file and hash should match, as should the general state of the table in terms of number of rows. Does your DB look anything like above?

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 21, 2019

Fails on Linux on 2.0.4.5 beta, with "Unexpected difference in fileset version 0: 6/21/2019 7:33:02 PM (database id: 4), found 0 entries, but expected 2". Watching the DB found basically the usual pattern. VolumeID seems to move around a bit. even on a given OS. I'm not sure why, but it seems irrelevant.

File "save" was an "echo -n A > A.txt"

I installed sqlitebrowser using "sudo apt-get install sqlitebrowser".

One thing I didn't spell out clearly enough is that --no-auto-compact needs to be checked if in GUI.
I "think" on the CLI, it's enough to just mention it, at least according to option-setting info I've seen.
Probably would have been best for directions step 2 to specifically state "--no-auto-compact=true".

Still unknown what explains the difference in results. Still probably need you to look into databases.

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 22, 2019

Still probably need you to look into databases.

or the easier method to get a slight hint is is to watch the remote volume folder to see what the files do. That should show if, for example, autocompact was happening (so manual wasn't). Log might also show.

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 22, 2019

One thing I didn't spell out clearly enough is that --no-auto-compact needs to be checked if in GUI.

That was it. I can reproduce now with 2.0.4.5 and 2.0.4.19.

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 22, 2019

I can also confirm that your suggested fix appears to address the issue. I ran my suite of tests and everything still passed. Thanks again for the thorough investigation. Do you want to create a pull request so that we can get some more knowledgeable people to review this?

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 22, 2019

Do you want to create a pull request so that we can get some more knowledgeable people to review this?

Could you make that please? It will probably go better, especially because there might be time pressure.

I have not made one before, and actually am not clear on standard Duplicati process flow. Wiki says little, however I just found several posts in forum Developer category asking similar getting-started questions, including disk space needs for Windows build with VS, branch management, etc. I'm not sure if anybody asked about test expectations before pull request, but I feel like I tested this even though I didn't build it. Duplicati uses Travis CI, I think, but I suspect a developer build and test before pull request is "expected".

My earlier comment on "C#-level editing chokes a lot" referred to the dnSpy debugger which has "Edit Method" and "Edit Class" capabilities that sometimes fails, even though I think it's the Roslyn compiler underneath. There is no Duplicati original source code. It's just trying to recompile decompiled sources.

If compiling fails, "Edit IL Instructions" works OK for string edits (such as SQL) and has some advantages.

Until I find time to get further into Duplicati development, you may continue to see issues like this, and
Upload throttle corrupts backup, especially OneDrive. Analyzed, with code proposed. #3787, which I've proposed for inclusion in the next beta if someone can do the honors. I don't like backup corruptions...

Thanks for the help with "Unexpected difference in fileset" and all the other things you do for Duplicati.

warwickmm added a commit to warwickmm/duplicati that referenced this issue Jun 22, 2019
Ignore additional blocks in used block query.
This fixes an occurence of the "Unexpected difference in fileset
version" error due to a deleted block having the same hash as one that
is currently in-use.

This fixes issue duplicati#3800.
warwickmm added a commit to warwickmm/duplicati that referenced this issue Jun 22, 2019
Ignore additional blocks in used block query.
This fixes an occurrence of the "Unexpected difference in fileset
version" error due to a deleted block having the same hash as one that
is currently in-use.

This fixes issue duplicati#3800.
warwickmm added a commit to warwickmm/duplicati that referenced this issue Jun 22, 2019
Fix issue where block was not recognized as being used.
This fixes an occurrence of the "Unexpected difference in fileset
version" error due to a deleted block having the same hash as one that
is currently in-use.

This fixes issue duplicati#3800.
@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 22, 2019

Thanks again @ts678 for your hard work looking into this (as well as many other issues)!

Please do not be shy about submitting pull requests with proposed changes, even if you are uncertain of their validity or how well the changes have been tested. We welcome all proposed changes and contributions, no matter how trivial or incomplete they may be. A pull request is the best forum for other developers to review and test the changes, provide feedback, and iterate with the developer to improve Duplicati as best we can.

When you submit a pull request, the Travis (Linux) and Appveyor (Windows) tests will automatically be triggered. If our tests are decent (they certainly can use some improvement), then they should catch any egregious errors.

Modifying the IL in the assembly is very impressive, and is much more difficult than modifying the source and recompiling. If you want any help with this, please don't hesitate to ask in the forums (I'm sure many others have the same questions). If you have a C# IDE installed (Visual Studio or MonoDevelop, etc.), then the code should compile without any issues. Perhaps the biggest difficulty is becoming familiar with how to use git.

@drwtsn32x

This comment has been minimized.

Copy link
Contributor

commented Jun 24, 2019

@ts678 if you like I could submit a pull request on your behalf with the proposed change. Just the change in line 126 of LocalDeleteDatabase.cs, correct? Let me know.... thanks again for your hard work on this one.

@warwickmm

This comment has been minimized.

Copy link
Contributor

commented Jun 24, 2019

@ts678, @drwtsn32x. Pull request #3801 was already submitted.

@drwtsn32x

This comment has been minimized.

Copy link
Contributor

commented Jun 24, 2019

Thanks @warwickmm !

@ts678

This comment has been minimized.

Copy link
Contributor Author

commented Jun 24, 2019

Thanks @warwickmm from me too! I did do some reading in the forum and Internet, and the kind of little change this one is seemed feasible to do entirely through GitHub web UI, so I practiced some then did Fix ThrottledStream Read buffer overwrite #3802 which was another proven fix for a proven problem that was just awaiting a pull request. Doing heavier work seemed more complex, with more installs, disk usage, and syncing. Basic GitHub fork question from @drwtsn32x had thoughts about that. ;-) Thanks to you as well!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.