I was using my previous SQL query again today in Python after doing kill testing on Duplicati which was unfortunately accumulating some extra dindex files with an actual “vol” file pointing to a dblock that was missing. This caused Recreate to error when I finally ran it. I put in a test to try to catch it earlier, but I’m pretty sure it caught the issue where an error during compact forgot dindex file deletion, getting Missing file error next run. Because I’m trying to keep the test rolling, I run a Repair on this error, and apparently what’s uploaded is this sort of mostly-empty just-a-manifest file. Makes sense, as this file was set up for deletion, and no longer has an entry in IndexBlockLink to find the dblock filename it’s supposed to index.
Running backup at 2022-05-07 18:12:57.166290
Timed out after 6 seconds
Statistics: started: 14 timeout: 2 missing: 0 extra: 0 marked: 0
Running backup at 2022-05-07 18:13:08.472690
Exit code 100
stderr was:
ErrorID: MissingRemoteFiles
Found 2 files that are missing from the remote storage, please run repair
Running repair at 2022-05-07 18:13:11.702707
Listing remote folder ...
Uploading file (233 bytes) ...
Uploading file (233 bytes) ...
Statistics: started: 15 timeout: 2 missing: 1 extra: 0 marked: 0
Running backup at 2022-05-07 18:13:22.303555
Exit code 0
duplicati-ie7c5f92748ff4b5ea45e1f01f026fa52.dindex.zip
duplicati-i3c359a2d644c45f484c7e7f5d689dc52.dindex.zip
Statistics: started: 16 timeout: 2 missing: 1 extra: 0 marked: 0
These two files don’t bother the Recreate, so I might have to work harder to filter out the noise they add.
EDIT to add profiling log to confirm interrupted compact:
2022-05-07 18:13:01 -04 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting because there is 25.52% wasted space and the limit is 25%
...
2022-05-07 18:13:02 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: Starting - RemoteOperationDelete
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-ie7c5f92748ff4b5ea45e1f01f026fa52.dindex.zip (18.09 KB)
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-ie7c5f92748ff4b5ea45e1f01f026fa52.dindex.zip (18.09 KB)
2022-05-07 18:13:02 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:00.000
2022-05-07 18:13:02 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: Starting - RemoteOperationDelete
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-be4bfcbdea2cb43319f4025b73db8e660.dblock.zip (4.91 MB)
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-be4bfcbdea2cb43319f4025b73db8e660.dblock.zip (4.91 MB)
2022-05-07 18:13:02 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:00.001
2022-05-07 18:13:02 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: Starting - RemoteOperationDelete
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-i3c359a2d644c45f484c7e7f5d689dc52.dindex.zip (18.09 KB)
2022-05-07 18:13:02 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-i3c359a2d644c45f484c7e7f5d689dc52.dindex.zip (18.09 KB)
2022-05-07 18:13:02 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationDelete]: RemoteOperationDelete took 0:00:00:00.000
2022-05-07 18:13:03 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: Starting - RemoteOperationGet
2022-05-07 18:13:03 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bceb3198dc64c43fdaf4ce7d7c4c8f3e6.dblock.zip (5.09 MB)
2022-05-07 18:13:03 -04 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded 5.09 MB in 00:00:00.0292879, 173.73 MB/s
2022-05-07 18:13:03 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-bceb3198dc64c43fdaf4ce7d7c4c8f3e6.dblock.zip (5.09 MB)
2022-05-07 18:13:03 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:00.030
2022-05-07 18:13:09 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started