Purge-Broken-Files Doesn't

handyguy · April 13, 2020, 7:37pm

As many have in the past, A couple of weeks ago I started receiving the following error message:

remote file duplicati-baabee6e5aa244f2fbdad8e8479aaf7ac.dblock.zip.aes is listed as Verified with size 327155712 but should be 341073421, please verify the sha256 hash "FBLkzkp+klkoozUxGr7PHmHuw+2kVqASxkmXvdFfLI8="
remote file duplicati-ia5ba4b9e4e6840e4bb1fcca638b808fe.dindex.zip.aes is listed as Verified with size 0 but should be 94125, please verify the sha256 hash "L1mhfkXMCiKM1sMZrQR0x+OkOHEKay7lhtvZYOpCjls="

I searched the forum for a solution and found many suggestions but no sure-fire cure. I have subsequently tried many combinations and permutations of purge-broken-files, verify, database repair, purge, etc, but nothing seems to clean up the database. I’m not anxious to recreate a 300GB+ backup, so does anyone have any good ideas on how to get this backup error-free?

ts678 · April 13, 2020, 8:45pm

What size are the files on the destination, and what sort of storage is the destination?
File sizes are usually quite varied, but these two are now truncated to even boundary.
327155712 is 13800000 in hex, which makes me suspect remote filesystem problem.
0 is of course truncation to binary-even, and an impossible valid size for a dindex file.

If you have your old DB (i.e. didn’t destroy/recreate), an empty dindex is easily rebuilt.
Repair will do that if if finds dindex missing, e.g. change folder, or add hidden- prefix.

If your dblock got damaged, that’s an actual loss of data, but it only affects some files.
The AFFECTED command can show the files. Easiest way to run is by Commandline.
You need to change the Command from backup to affected and put the filenames in the
Commandline arguments box, and go to screen bottom to run the affected command.
Recovering by purging files is the plan, but note that first the damaged dblock must go
missing, e.g. move it to a parallel or higher folder, or rename with a prefix e.g. hidden-

Before doing any of this, look at sizes of those two files. Do they seem too even/short?
If your remote has timestamps, you might also be able to see when the file was written.

What Duplicati version is this, and what is the operating system?

handyguy · April 14, 2020, 12:03am

What size are the files on the destination,

The dblock file is smaller than most of the other dblock files (most of them are ~767mb). You can see that both files were written on 3/18, so this must have been going on for a while. I’ve been working on some other things for the past few weeks so it may have been that long that I’ve been getting the messages.

what sort of storage is the destination?

Raspberry Pi NAS running CIFS services. The Pi NAS serves CIFS (SMB) and NFS to a number of different Windows 10, Windows Server 2016, Debian 9, & Debian 10, all running Duplicati. This is the only one exhibiting this issue.

What Duplicati version is this, and what is the operating system?

Duplicati - 2.0.5.1_beta_2020-01-18 running on Windows 10 Pro.

The AFFECTED command results were interesting:

The following filesets are affected:
0	: 4/13/2020 1:40:29 PM
1	: 4/13/2020 1:30:01 AM
2	: 4/12/2020 1:30:00 AM
3	: 4/11/2020 1:30:00 AM
4	: 4/10/2020 1:30:00 AM
5	: 4/9/2020 1:30:00 AM
6	: 4/8/2020 1:30:00 AM
7	: 4/7/2020 1:30:00 AM
8	: 4/1/2020 1:30:00 AM
9	: 3/25/2020 1:30:00 AM
10	: 3/18/2020 1:30:00 AM

A total of 44 file(s) are affected:
D:\Development\program.HOLD\.git\objects\
D:\Development\program.HOLD\.git\objects\0d\
D:\Development\program.HOLD\.git\objects\0d\0108f5344cc0adc0080500ad85c23133717b9c
D:\Development\program.HOLD\.git\objects\24\
D:\Development\program.HOLD\.git\objects\24\5867cab718379a738667470b4548fb90194a9d
D:\Development\program.HOLD\.git\objects\46\
D:\Development\program.HOLD\.git\objects\46\18143e3348dd9a0a228e2a0d8196fc4e904431
D:\Development\program.HOLD\.git\objects\73\
D:\Development\program.HOLD\.git\objects\73\21ee0d457d842df8b3ae892137563fa9d6bfb7
D:\Development\program.HOLD\.git\objects\9e\
D:\Development\program.HOLD\.git\objects\9e\db4e325dea1163fb96a1fe1bb16a4e634433b4
D:\Development\program\
D:\Development\program\.git\
D:\Development\program\.git\COMMIT_EDITMSG
D:\Development\program\.git\index
D:\Development\program\.git\logs\HEAD
D:\Development\program\.git\logs\refs\heads\Version_3_0_0
D:\Development\program\.git\objects\
D:\Development\program\.git\objects\0d\
D:\Development\program\.git\objects\0d\0108f5344cc0adc0080500ad85c23133717b9c
D:\Development\program\.git\objects\24\
D:\Development\program\.git\objects\24\5867cab718379a738667470b4548fb90194a9d
D:\Development\program\.git\objects\46\
D:\Development\program\.git\objects\46\18143e3348dd9a0a228e2a0d8196fc4e904431
D:\Development\program\.git\objects\73\
D:\Development\program\.git\objects\73\21ee0d457d842df8b3ae892137563fa9d6bfb7
D:\Development\program\.git\objects\9e\
D:\Development\program\.git\objects\9e\db4e325dea1163fb96a1fe1bb16a4e634433b4
D:\Development\program\.git\refs\heads\
D:\Development\program\.git\refs\heads\Version_3_0_0
D:\Development\program\.git\sourcetreeconfig.json
D:\Development\program\.gitignore
D:\Development\program\.vs\report\v16\.suo
D:\Development\program\__pycache__\
D:\Development\program\__pycache__\report.cpython-37.pyc
D:\Development\program\report.db
D:\Development\program\report.log
D:\Development\program\report.py
D:\Development\program\report.pyproj
D:\Development\program\report.rc
D:\Development\program\output.html
D:\Development\program\report.py
D:\Users\parents\Downloads\
D:\Users\parents\Downloads\debian-10.3.0-amd64-netinst.iso

The following related log messages were found:
3/18/2020 6:30:58 AM: {"Size":341073421,"Hash":"FBLkzkp+klkoozUxGr7PHmHuw+2kVqASxkmXvdFfLI8="}
3/18/2020 6:31:22 AM: {"Size":94125,"Hash":"L1mhfkXMCiKM1sMZrQR0x+OkOHEKay7lhtvZYOpCjls="}
3/18/2020 6:52:53 AM: {"DeletedFiles":0,"DeletedFolders":0,"ModifiedFiles":16,"ExaminedFiles":91223,"OpenedFiles":22,"AddedFiles":6,"SizeOfModifiedFiles":537874,"SizeOfAddedFiles":351298697,"SizeOfExaminedFiles":352927289811,"SizeOfOpenedFiles":351836571,"NotProcessedFiles":0,"AddedFolders":1,"TooLargeFiles":0,"FilesWithError":0,"ModifiedFolders":0,"ModifiedSymlinks":0,"AddedSymlinks":0,"DeletedSymlinks":0,"PartialBackup":false,"Dryrun":false,"MainOperation":"Backup","CompactResults":null,"VacuumResults":null,"DeleteResults":{"DeletedSetsActualLength":0,"DeletedSets":[],"Dryrun":false,"MainOperation":"Delete","CompactResults":null,"ParsedResult":"Success","Version":"2.0.5.1 (2.0.5.1_beta_2020-01-18)","EndTime":"2020-03-18T06:31:26.4141481Z","BeginTime":"2020-03-18T06:31:22.6321392Z","Duration":"00:00:03.7820089","MessagesActualLength":0,"WarningsActualLength":0,"ErrorsActualLength":0,"Messages":null,"Warnings":null,"Errors":null,"BackendStatistics":{"RemoteCalls":12,"BytesUploaded":351754007,"BytesDownloaded":10838554,"FilesUploaded":3,"FilesDownloaded":2,"FilesDeleted":0,"FoldersCreated":0,"RetryAttempts":4,"UnknownFileSize":0,"UnknownFileCount":0,"KnownFileCount":740,"KnownFileSize":278276959956,"LastBackupDate":"2020-03-18T01:30:00-05:00","BackupListCount":10,"TotalQuotaSpace":1967925760000,"FreeQuotaSpace":1129191657472,"AssignedQuotaSpace":-1,"ReportedQuotaError":false,"ReportedQuotaWarning":false,"MainOperation":"Backup","ParsedResult":"Success","Version":"2.0.5.1 (2.0.5.1_beta_2020-01-18)","EndTime":"0001-01-01T00:00:00","BeginTime":"2020-03-18T06:30:00.1052866Z","Duration":"00:00:00","MessagesActualLength":0,"WarningsActualLength":0,"ErrorsActualLength":0,"Messages":null,"Warnings":null,"Errors":null}},"RepairResults":null,"TestResults":{"MainOperation":"Test","VerificationsActualLength":3,"Verifications":[{"Key":"duplicati-20200318T063000Z.dlist.zip.aes","Value":[]},{"Key":"duplicati-i8271a858f29c48238a472c2ec7edea79.dindex.zip.aes","Value":[]},{"Key":"duplicati-bc179226b1f7e46fb87361e792d71a53a.dblock.zip.aes","Value":[{"Key":"Error","Value":"An unexpected network error occurred.\r\n"}]}],"ParsedResult":"Success","Version":"2.0.5.1 (2.0.5.1_beta_2020-01-18)","EndTime":"2020-03-18T06:52:53.356392Z","BeginTime":"2020-03-18T06:31:28.2980188Z","Duration":"00:21:25.0583732","MessagesActualLength":0,"WarningsActualLength":0,"ErrorsActualLength":0,"Messages":null,"Warnings":null,"Errors":null,"BackendStatistics":{"RemoteCalls":12,"BytesUploaded":351754007,"BytesDownloaded":10838554,"FilesUploaded":3,"FilesDownloaded":2,"FilesDeleted":0,"FoldersCreated":0,"RetryAttempts":4,"UnknownFileSize":0,"UnknownFileCount":0,"KnownFileCount":740,"KnownFileSize":278276959956,"LastBackupDate":"2020-03-18T01:30:00-05:00","BackupListCount":10,"TotalQuotaSpace":1967925760000,"FreeQuotaSpace":1129191657472,"AssignedQuotaSpace":-1,"ReportedQuotaError":false,"ReportedQuotaWarning":false,"MainOperation":"Backup","ParsedResult":"Success","Version":"2.0.5.1 (2.0.5.1_beta_2020-01-18)","EndTime":"0001-01-01T00:00:00","BeginTime":"2020-03-18T06:30:00.1052866Z","Duration":"00:00:00","MessagesActualLength":0,"WarningsActualLength":0,"ErrorsActualLength":0,"Messages":null,"Warnings":null,"Errors":null}},"ParsedResult":"Error","Version":"2.0.5.1 (2.0.5.1_beta_2020-01-18)","EndTime":"2020-03-18T06:52:53.3958383Z","BeginTime":"2020-03-18T06:30:00.1052866Z","Duration":"00:22:53.2905517","MessagesActualLength":31,"WarningsActualLength":0,"ErrorsActualLength":1,"Messages":["2020-03-18 01:30:00 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started","2020-03-18 01:30:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()","2020-03-18 01:30:08 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (737 bytes)","2020-03-18 01:30:58 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-baabee6e5aa244f2fbdad8e8479aaf7ac.dblock.zip.aes (325.27 MB)","2020-03-18 01:31:03 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20200318T063000Z.dlist.zip.aes (10.10 MB)","2020-03-18 01:31:07 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20200318T063000Z.dlist.zip.aes (10.10 MB)","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-baabee6e5aa244f2fbdad8e8479aaf7ac.dblock.zip.aes (325.27 MB)","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ia5ba4b9e4e6840e4bb1fcca638b808fe.dindex.zip.aes (91.92 KB)","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ia5ba4b9e4e6840e4bb1fcca638b808fe.dindex.zip.aes (91.92 KB)","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00","2020-03-18 01:31:22 -05 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 3/17/2020 1:30:00 AM, 3/15/2020 1:30:01 AM, 3/13/2020 1:30:01 AM, 3/12/2020 1:30:00 AM, .

.
.

Failed to send message: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'SQLiteConnection'.
 => Cannot access a disposed object.
Object name: 'SQLiteConnection'.
Return code: 0

Am I supposed to put the file names in the commandline arguments for the purge-broken-files command? I was under the assumption that Duplicati would know which files were broken and just purge them. If I need to add them manually I will have to run it again.

So what do you suggest the next step would be?

ts678 · April 14, 2020, 1:09am

While file size is more accurately seen in right-click Properties, MS uses KiB, so 319488 is 327155712 which is the number that Duplicati saw. I guess to be extra sure you could read size directly on remote.

Other people have had trouble with CIFS/SMB corrupting files. One person switched to NFS, I believe, however I’m not sure how feasible that is on this Windows system. Basically, your files got truncated…

Duplicati’s DB knows what it expects. It complains if it finds something else. This detects file problems.

The newer backups get affected if blocks originally added in the 3/18 file are still in use in new backup. Deduplication is great at only storing changes, but block backreferences make lost blocks affect more.
I think cleanup process will remove affected files from the backup, leaving holes for next backup to fill.

Was this affected naming the dblock, the dindex, or both? Did you try the dindex repair yet, hiding or moving it, then running Repair? Might as well try to get it back even if the dblock file data is damaged.

The LIST-BROKEN-FILES command and The PURGE-BROKEN-FILES command don’t indicate that.
Recovering by purging files step-by-step example doesn’t use it either. Rather than try to place all the relevant options from your backup job onto a true command prompt run, Commandline use is simpler.

Before doing this, it’s probably best to hide or move those remote files you want Duplicati to adjust for.

You change the Command to list-broken-files, and match the rest, e.g. clear Commandline arguments because those aren’t used here. Most options are safe. Maybe clear any include and exclude options.

The purge-broken-files documentation suggests an initial run with the –dry-run option checked, which just means adding it and checking it in the GUI. You’ll probably see a lot of the same information seen running affected command, but I guess a step-by-step is safer. If OK, remove dry-run and do for real.

So the maybe-redundant steps would be:

See if you can get the dindex file back by moving/renaming it and doing Repair. If so, one thing better.

Get on the remote and make sure the size is wrong there too. It likely will be, but might be worth a try.

Move/rename the dblock and see what list-broken-files thinks. It might look similar to affected.

Do purge-broken-files with --dry-run set. See if it looks like you expect – a limited purging of your files.

Do purge-broken files without --dry-run.

See if backup works without complaints.

I’m not sure what to say to make your SMB 100% reliable, but it seems like whatever went bad is rare. I’d think you could install an sftp server on the Raspberry Pi if you wanted to see if that’s more reliable.
You could also try to figure out if something happened on Mar 18, e.g. event log might show a reboot…

handyguy · April 14, 2020, 1:35pm

Well that seemed to work! I did the step-by-step as you described and I was able to get back to an errorless backup. That was much more complicated than it should have been, but at least I got it working.

Thanks for all your help!