Some feedback and experience with a restore

Hi all,

Just something interesting - while experimenting with different backends and backup systems - ended up with real life need to test out restore functionality.

Background: my main backup - 415gb. Irreplacable photos and stuff stretching back 20 years. for some reason, after messing around with the various backup solutions - the original location only 380gb. Inspecting a bit and found out it seems to have lost files (interestingly, very random like swiss cheese — the photos are in folders by date (YYYYMMDD) and some folders lost nothing, some lost a few, others lost everything inside with a stub)

Props: Duplicati with OneDrive backend - had an initial panick coz the failure was coming at a bad time (see my other threads, in the middle of testing which means my normal 3 copy backup was actually down to 1). Ended up choosing OD coz it was the most stable backend and Duplicati coz when it comes down it; the big data file approach would put less strain on computer and less of a failure-during-failure situation

Experience: some trepidation when trying out the restore (from a 3rd party computer). The authentication went ok but some nervousness around the process since literally first time. The weakness of not seeing the backup sizes in the version history popped out - I didn’t know which backup to restore from - i know a week ago it the filestore was ~415 gb and it must have been some problem in last week that deleted the files - but the backup is daily and didn’t know which was the problem ‘too small’ backup … ended up using my other backup solution (arq) which shows the file structure in each backup and could establish that last friday morning things were good - so could give guidance on the restore.

On the restore itself - great error free experience; took a while but ended up with parallel filestructure with all files intact. GREAT SUCCESS FOR DUPLICATI

A few feature requests and/or observations:

  1. the progress bars on restore are pretty useless; from the temporary data base creation to the actual restore - the bars don’t give much clues on how much to go; i think good to replace with a XX of YY type of text update.
  2. restore placement - basically the photos don’t change but some are missing; I ended up restoring everything and copying over - currently have overwrite (theortiically ok but heavier resource usage for no real gain) and restore-as-copy-with-timestamp (don’t want to clean up the duplicates) but would be nice to restore in place; with a ‘skip if existing’ it would restore the missing files and I don’t need to clean up afterwards…

How did you do the restore? Sounds like you may have picked Restore → Direct restore from backup files. This method is slower than doing Restore → and picking your backup set name from the list. If you do the latter, no temporary database needs to be created.

Also, you can easily browse the file structure of each backup version. I agree it would have been nice if Duplicati also showed the backup size. Would have helped you spot the correct version to restore from.

Completely agree - I’m actually surprised Duplicati doesn’t have this ability already!

There’s an existing ticket for this but unfortunately we haven’t gotten around to addressing it yet.

may be why. Maybe being cautious? But it will definitely need DB creation work that original wouldn’t.

I think what it does if the file exists and is the same as its backup is to leave it alone. There’s no point making an exact duplicate. Missing files would be restored, and files not the same as backup version (which might not apply in your case unless you do photo editing) are rebuilt into the version you want. When files truly differ, then it makes sense to go to timestamps so that versions can be distinguished.

This confused me the first time I hit it, the docs could maybe be better, and somebody check me here.

Duplicati can do rapid rebuilding of files even if the destination location is different, if source files exist which can supply blocks. Only blocks which can’t be found on local system files need be downloaded.

–no-local-blocks

Duplicati will attempt to use data from source files to minimize the amount of downloaded data. Use this option to skip this optimization and only use remote data.

This is a good option to use when testing, although using a different system will also force downloads.

Yeh - this is actually the serious side of my hobby and as I said some irreplacable photos. So I didn’t want complications if another disaster happened and hence restoring from 3rd party computer. The database rework was some time, but wasn’t significant in grand scheme and dwarfed by the downloading-data-blocks anyway.

Give me a couple of days for dust to settle and for me to stablize the existing backup and I will test this. It certainly would help reduce the post-restore merging overhead.

Hmm - help me understand; I suppose this works only on the original computer. So in my case, there is some swiss-cheese missing-files and duplicati will go through the location and note which files are there and verify it match the restore version blocks? For my case no changes for sure but in other cases if the file are different then get the timestamp treatment. I suppose this would help my use case a lot to reduce the network traffic which is the speed major bottleneck

I’ll have to experiment with it, but I could still see the desire to skip existing files no matter what. Typical options in backup software for handling existing files include skip, overwrite if older, overwrite always.

Yes.

To simulate the missing files, test behavior with truly different files, and go beyond, I tested the following:

I set up a test based on a text file I had laying around that was large enough to have two default 100 KB blocks. I renamed it with .jpg to keep Duplicati from compressing, and added intended plan to file name:

to_lose
no_edit
to_edit which in this case edited the start of the last line, and added one more partial line after past end.

I added a new file to folder to verify Restore would leave it alone. Beyond that, I thought Restore would make the folder what it was at time of backup, and would not overwrite my edited file but make another.

Result of a dir command (plus dragging files into notepad to inspect) confirms that that was what it did:

05/17/2019  06:30 PM           262,144 length262144.txt.no_edit.jpg
05/17/2019  06:30 PM           262,144 length262144.txt.to_edit.2020-02-10.jpg
02/10/2020  11:29 AM           262,150 length262144.txt.to_edit.jpg
05/17/2019  06:30 PM           262,144 length262144.txt.to_lose.jpg
02/10/2020  11:30 AM                 0 New Text Document.txt

Looking at a –log-file at –log-file-log-level=verbose one can see the decision-making needed to get the lost file back, revert the edited one, and leave the unedited one alone. Patches with local data don’t log:

2020-02-10 11:31:21 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (3 bytes)
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (2/10/2020 4:26:31 PM) ...
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreTargetFileCount]: Needs to restore 3 files (768.00 KB)
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreSourceSize]: Restore list contains 13 blocks with a total size of 768.54 KB
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TargetExistsInCorrectVersion]: Target file exists and is correct version: C:\tmp\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TargetFileRetargeted]: Target file exists and will be restored to: C:\tmp\patch test\length262144.txt.to_edit.2020-02-10.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MissingTargetFile]: Target file does not exist: C:\tmp\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b0987b42501bd4497b487b3449e6d08fd.dblock.zip (157.37 KB)
2020-02-10 11:31:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b0987b42501bd4497b487b3449e6d08fd.dblock.zip (157.37 KB)
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\tmp\patch test\length262144.txt.to_edit.2020-02-10.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\tmp\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\patch test\
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\patch test\length262144.txt.to_edit.2020-02-10.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\tmp\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\patch test\
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\patch test\length262144.txt.to_edit.2020-02-10.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\tmp\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\tmp\patch test\length262144.txt.to_edit.2020-02-10.jpg
2020-02-10 11:31:22 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\tmp\patch test\length262144.txt.to_lose.jpg

Restore to a different location has a similar log except with a local data remark and more verification because there had been 3 files restored without the one not having to be restored due to no change:

2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (3 bytes)
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.Database.LocalRestoreDatabase-SearchingBackup]: Searching backup 0 (2/10/2020 4:26:31 PM) ...
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreTargetFileCount]: Needs to restore 3 files (768.00 KB)
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MappingRestorePath]: Mapping restore path prefix to "C:\tmp\patch test\" to "C:\restore here\patch test\"
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Database.LocalRestoreDatabase-RestoreSourceSize]: Restore list contains 13 blocks with a total size of 768.54 KB
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MissingTargetFile]: Target file does not exist: C:\restore here\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MissingTargetFile]: Target file does not exist: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-MissingTargetFile]: Target file does not exist: C:\restore here\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-FilePatchedWithLocal]: Target file is patched with some local data: C:\restore here\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-FilePatchedWithLocal]: Target file is patched with some local data: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-LocalSourceMissing]: Local source file not found: C:\tmp\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-FilePatchedWithLocal]: Target file is not patched any local data: C:\restore here\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.Operation.RestoreHandler-RemoteFileCount]: 1 remote files are required to restore
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b0987b42501bd4497b487b3449e6d08fd.dblock.zip (157.37 KB)
2020-02-10 11:54:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b0987b42501bd4497b487b3449e6d08fd.dblock.zip (157.37 KB)
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\restore here\patch test\
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\restore here\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\restore here\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\restore here\patch test\
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\restore here\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\restore here\patch test\length262144.txt.to_lose.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\restore here\patch test\length262144.txt.no_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\restore here\patch test\length262144.txt.to_edit.jpg
2020-02-10 11:54:06 -05 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-TestFileIntegrity]: Testing restored file integrity: C:\restore here\patch test\length262144.txt.to_lose.jpg

Nice work there. Good to see duplicati actions match intuition.

I gotta say tho; coz things are beta/canary etc etc when it comes to the serious side of a restore after a mini-disaster like mine; it just feels too risky to try out different options. particularly on restores where I don’t have much opportunity to practice

Update on the restore; things completed but noticed some errors/warnings in the log:

  1. [Warning-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFileLocalFailed]: Failed to patch file: …
  2. [Warning-Duplicati.Library.Main.Operation.RestoreHandler-MetadataWriteFailed]: Failed to apply metadata to file: …
  3. [Error-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFailed]: Failed to patch with remote file: …
  4. [Error-Duplicati.Library.Main.Operation.RestoreHandler-RestoreFileFailed]: Failed to restore file: … File hash is ULTvgLvyLcZzcyyAhWrD3Hhf8Xv8YayRu1eJzlHmd6Y=, expected hash is REEZqUcBZW2PCKC3EOUMZ6HG1txvbo9/7Bd7WOfGdvA=",

#2 seems not-so-bad (running on NTFS and don’t really know what metadata there is actually! but certainly I don’t think I am missing anything).

#1 / #3 - not too share what that actually means and not sure why one is considered warning while the other an error?

#4 - sounds bad; does it mean somehow the data file got corrupted (bit-rot I suppose? a bit amazing on something like OneDrive which should have 99.xxxxx% reliability?). If this was the only backup; does that mean original file gone forever?

Is this the automatic default log (summary), the live log mentioned there (better), or a –log-file (best)?
Many warnings and errors supply details which the summary removes, so it’s hard to say what this is.

https://github.com/duplicati/duplicati/blob/v2.0.5.1-2.0.5.1_beta_2020-01-18/Duplicati/Library/Main/Operation/RestoreHandler.cs allows some guessing, though I didn’t write it, and am not expert.

PatchingFileLocalFailed looks like something went wrong while working original source blocks for file, which seems odd if this is still the 3rd party computer that presumably doesn’t have your original files.

MetadataWriteFailed would (I think) usually just be simple things like timestamps unless restore does more, e.g. you check Restore read/write permissions, in which case the NTFS ACL is restored.

PatchingFailed (unlike PatchingFileLocalFailed) is in the working with remote dblocks used to rebuild files back to desired form. I’m not sure what happens on this error. Possibly the file didn’t rebuild right.

RestoreFileFailed is in file integrity testing, and it makes sense if this is the file where PatchingFailed, otherwise I’m not sure. There’s a detailed message on this one (like on the rest) that could say more.
EDIT: On second glance, the others are more useful. This one is sending an exception to itself I think.

Or possibly a problem in upload. Before 2.0.5.1, throttling (speed limit) on connection use could cause scrambled files that aren’t findable by the usual name and length check. The Verifying backend files is sampled verification balanced among files, but incomplete unless configured up. It might have missed.

Before 2.0.5.1 download could also corrupt files, but that was easily corrected by turning off throttling…

Arguing against this theory is that damaged remote files are usually encrypted, so you get a decryption complaint first. If they’re not encrypted you might get a complaint when its hash (integrity check) is run.

There have been other backup integrity bugs fixed in 2.0.5.1 as well. Possibly you had hidden damage.

Duplicati.CommandLine.RecoveryTool.exe is more forgiving of certain types of damage, but whether it needs to be tried is an individual choice depending on how much would be gained by the extra effort…

I used the log that is available in the web interface.

For PatchingFileLocalFailed, agree it looks really strange. There is only a couple of errors of that nature in the list which is bizaare - it is a 3rd party computer; so either should be none (expected) or many (ie all the files). I have no idea why only two

For the warnings on metadata - couldn’t really end up finding out (I do note know details on NTFS alternate metadata or streams and don’t use them so don’t even know wher eto look)

For the RestoreFileFailed, there was a number of files listed (about 7 or so) --=- it was really bizare as well as the first few I hand checked (they are JPG files) looked fine; no corruption/distortion. looked like the picture. But after the first few (one particular folder) went to the other bunch which was in a second folder; all of them showed classic signs of corruption (part of picture ok but then afterwards there is a disortion on image).

Anyway; 7 errors out of about 200k files isn’t bad (but would be nice to be 100% error-free since these are irreplaceable memories).

I have another parallel backup (the Arq one) so assuming the errors are independent I should be ok and salvage everything

A good outcome and useful learnings. A ton of work tho