Restoring metadata requires duplicate redownloads of dblocks?

Hi,

I am testing restoring a backup from Box and Google Drive currently, on same the host as the one with the Duplicati backup database, and I’ve been watching the restore folder where all ~2 million files have been restored.

Duplicati now switched to a stage called “Downloading files…” and watching the log, I’m seeing lots of these messages for all the files:

Recording metadata from remote data:

However, I am pretty sure that I also saw dblock downloads in between all these.

I did check the box to restore permissions for this backup, so my question is this: does Duplicati download dblock files to restore and then separately redownload them to assign metadata information, such as user:group and file permissions? If so, this seems like an operation that could use some optimization.

Thanks.

I don’t think so. I’m not that expert in all the code, but I took a look. Plus I’ll show what a restore looks like:

2019-08-06 14:27:06 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Restore has started
2019-08-06 14:27:06 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2019-08-06 14:27:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (13 bytes)
2019-08-06 14:27:09 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b6729062d35ea44e1b7adeabb07f2c288.dblock.zip (768.82 KB)
2019-08-06 14:27:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b6729062d35ea44e1b7adeabb07f2c288.dblock.zip (768.82 KB)
2019-08-06 14:27:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b6cb6b5bc36ed4e8186e0c2f46ecedfdd.dblock.zip (769.09 KB)
2019-08-06 14:27:10 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:11 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b6cb6b5bc36ed4e8186e0c2f46ecedfdd.dblock.zip (769.09 KB)
2019-08-06 14:27:11 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b877ed4171e164c0ca538468173a41b19.dblock.zip (768.82 KB)
2019-08-06 14:27:11 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:11 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:12 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b877ed4171e164c0ca538468173a41b19.dblock.zip (768.82 KB)
2019-08-06 14:27:12 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b164efc2e762e42bcba22ee8fd72fde03.dblock.zip (768.82 KB)
2019-08-06 14:27:12 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:12 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b164efc2e762e42bcba22ee8fd72fde03.dblock.zip (768.82 KB)
2019-08-06 14:27:12 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b05fc64be19734e54b87de2f66dee5e6f.dblock.zip (768.82 KB)
2019-08-06 14:27:12 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:13 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b05fc64be19734e54b87de2f66dee5e6f.dblock.zip (768.82 KB)
2019-08-06 14:27:13 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b30191c1bc6bd4af29668f475a81c64c9.dblock.zip (257.09 KB)
2019-08-06 14:27:13 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:14 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b30191c1bc6bd4af29668f475a81c64c9.dblock.zip (257.09 KB)
2019-08-06 14:27:14 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingFile]: Patching file with remote data: C:\restore here\4MiB.pet
2019-08-06 14:27:14 -04 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-PatchingMetadata]: Patching metadata with remote data: C:\restore here\4MiB.pet

Above used backup from a bug chase using special settings – a 4 MiB uncompressible file, 1 MiB remote volume size, and 256 KiB block size. So 3 blocks per remote volume, plus maybe a bit more. Specifically, small things like metadata can fit in a dblock even if it already has three 256 KiB blocks in it. The math for blocks says 16 are required, so that means 5 dblocks of 3 blocks per dblock, and 1 at 1 block per dblock.

Each of the 6 dblocks is opened, and whatever is needed is taken from it. File patching happens 6 times, and one of the dblocks carries the bonus of a metadata block which is recorded, then applied at very end.

You can test this on your restore using live log at Information level (and a sharp eye), or more casually by –log-file and –log-file-log-level=information, then do Linux egrep or similar on the log using expression of:

StartingOperation|BackendEvent|PatchingFile|RecordingMetadata|PatchingMetadata

To see PatchingFile, you will probably need –no-local-blocks in order to force it to download for everything.

The routine below seems to be where dblock turns into various things, such as metadata or data for a file:

I was observing Patching file with remote data while the (pretty quick) first portion of the restore was running and creating the files on the disk. Once this initial and quick stage was finished (1-2 hours for the ~400GB ~2 million files), the 2nd stage consisted only of Recording metadata from remote data and took ages. I checked this morning and the total restore took: Last successful restore: Yesterday at 11:54 PM (took 13:02:01).

During this time, all restored files were owned by root. This morning, once the restore was fully finished, I checked again and found the ownership/permissions to be correct.

I wasn’t using a log file, so unfortunately I can’t go back and look, but I can try to restore again with a log and see if I can spot the issue again. I’ll update to the latest experimental first though due to Recreating database logic/understanding/issue/slow.

Correction: It may have been Target file is patched with some local data instead of remote data during the first stage that I was observing.

Does this mean local files from the original source were used for this and no dblock downloads were made, but then to restore ownership/perms, dblocks were downloaded?

OK, here we go. After patching data, it moved to the “Recording metadata from remote data” stage and started downloading all the dblock files. So the metadata is stored together with the raw files inside dblocks and not separately somewhere (perhaps in the database or a separate set of files that would be much smaller to download)? Seems like there could be some optimizations to make here.

2019-08-06 17:39:09 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/08/5d4299c1e38ce/<SNIP>.apk
2019-08-06 17:39:09 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/08/5d4299ca0dcad/
2019-08-06 17:39:09 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/08/5d4299ca0dcad/<SNIP>.apk
2019-08-06 17:39:09 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/08/5d4299cb02c51/<SNIP>.apk


2019-08-06 17:39:28 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b2de185fe1fb444eb973241ebf342fc86.dblock.zip.aes (249.34 MB)
2019-08-06 17:39:28 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b1ee9ac54951a45569a18e731bec0bc4a.dblock.zip.aes (240.97 MB)
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc189b49b/
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc1c4e8e4/
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc1c4e8e4/<SNIP>.apk
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc2c0f319/
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc2c0f319/<SNIP>.apk
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc36a1fcb/
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc36a1fcb/<SNIP>.apk
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc4204519/<SNIP>.apk
2019-08-06 17:39:28 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bc5bc0ea1/<SNIP>.apk


2019-08-06 17:39:48 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b1ee9ac54951a45569a18e731bec0bc4a.dblock.zip.aes (240.97 MB)
2019-08-06 17:39:48 -07 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b37f509e1474046dcb1cf9c5357f9eb02.dblock.zip.aes (243.18 MB)
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb6c9f059/
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb77ae9ff/
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb77ae9ff/<SNIP>.apk
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb8b3e650/
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb8b3e650/<SNIP>.apk
2019-08-06 17:39:48 -07 - [Verbose-Duplicati.Library.Main.Operation.RestoreHandler-RecordingMetadata]: Recording metadata from remote data: /tmp/duplicati_restore/<SNIP>/uploads/2019/07/5d31bb9232afe/

That would be my assumption, but I haven’t researched or tested it. In a situation where the restored isn’t exactly the current file (e.g. current changed since backup, or you’re restoring am old version), I’d expect some downloads, otherwise it could probably get all the same file content from the unchanged local file…

How the backup process works

Metadata is treated like a normal block of data

Quite possibly so, but there are plenty of other issues and feature requests (pushing 1000 probably) to compete with it for limited (far from ideal…) amounts of time that the development volunteers can give.

Thinking through use cases more than we can right here would be useful. Full disaster recovery would probably download a lot. Recovery of a few files due to a loss or “oops” wouldn’t typically take that long.

Please also note that this is not just an initial question of how blocks are packed into dblocks. Compact operations would also have to treat blocks as different types, when time comes to repack new dblocks.

Test restore done to original system at different location probably shows this idiosyncracy the best, but using --no-local-blocks (as one should to get a better test) will probably look pretty balanced in its work.

The transition point between FilePatchedWithLocal messages phase and remote dblock phase is here:

Or at least I think so. You can test your restores if you’re curious enough, to see if this pattern matches.