Interrupted Compact - What to do next?

Version: 2.0.6.3_beta_2021-06-17
Backup Size: 40GB / 23 Versions
Backend: Backblaze B2

Lost internet in the middle of an auto-Compact. Is there anything special that I need to do to recover? From this post, it seems like the Compact process is fairly failsafe. Is there any manual command I should run to verify the integrity of the local database or remote fileset?

Also, the auto-Compact was part of a backup job, which completed before the Compact began (as verified in the log), so why is there no log in the GUI for the completed backup job?

The below log snippets just show that the internet failed as it was trying to download a DBLOCK to compact. Which should be a good place to fail, I believe.

2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-b7bd678b7c2a64f91b2c3f4e7342d60e6.dblock.zip.aes (179.21 MB)
2022-10-10 01:10:46: Backend event: Delete - Completed: duplicati-b7bd678b7c2a64f91b2c3f4e7342d60e6.dblock.zip.aes (179.21 MB)
2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes (102.51 KB)
2022-10-10 01:10:46: Backend event: Delete - Completed: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes (102.51 KB)
2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-bd0f90a535cf64895840dfaac1d17cea1.dblock.zip.aes (23.64 MB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-bd0f90a535cf64895840dfaac1d17cea1.dblock.zip.aes (23.64 MB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes (23.64 KB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes (23.64 KB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-bbd0666fce32e4eda8ecf382df9543ce8.dblock.zip.aes (61.96 MB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-bbd0666fce32e4eda8ecf382df9543ce8.dblock.zip.aes (61.96 MB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes (42.83 KB)
2022-10-10 01:10:48: Backend event: Delete - Completed: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes (42.83 KB)
2022-10-10 01:11:00: Backend event: Get - Started: duplicati-b130edbaf35c24ce2b57d129c161c8ba0.dblock.zip.aes (77.59 MB)
2022-10-10 01:11:09: Backend event: Get - Completed: duplicati-b130edbaf35c24ce2b57d129c161c8ba0.dblock.zip.aes (77.59 MB)
2022-10-10 01:11:09: Backend event: Get - Started: duplicati-b39fd7c089f824e679b9daf9288ebb642.dblock.zip.aes (161.54 MB)
2022-10-10 01:11:30: Backend event: Get - Completed: duplicati-b39fd7c089f824e679b9daf9288ebb642.dblock.zip.aes (161.54 MB)
2022-10-10 01:11:30: Backend event: Get - Started: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:12:10: Backend event: Get - Retrying: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:12:20: Backend event: Get - Started: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:12:51: Backend event: Get - Retrying: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:13:01: Backend event: Get - Started: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:13:32: Backend event: Get - Retrying: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:13:42: Backend event: Get - Started: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:14:13: Backend event: Get - Retrying: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:14:24: Backend event: Get - Started: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:14:55: Backend event: Get - Failed: duplicati-bb749a8a925434753b5f0a4f0d22b5621.dblock.zip.aes (80.35 MB)
2022-10-10 01:14:55: Backend event: Get - Started: duplicati-b32ceabb7c6974a658d451a3cf1473664.dblock.zip.aes (72.43 MB)
2022-10-10 01:15:15 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
System.Net.WebException: The remote name could not be resolved: 'api.backblazeb2.com'

It’s good to have that log. There’s at least one bug:

Error during compact forgot a dindex file deletion, getting Missing file error next run. #4129

so if you fall into that, you’ll be able to see the actual Delete and so can just run the Repair.

I suppose a slightly more conservative way to get a preview of things is “Verify files” button.
Unless you have something unusual configured, just running Backup does a similar check.

The deletes all finished for that series of DBLOCKs, so that bug shouldn’t affect me (hopefully).

That happens with the open issue. Deletes finish, error occurs, DB rolls back, so it forgets the deletes.
You can test to see if you’re OK…

Whoa. I read the bug report but didn’t realize that. I am not sure what to do. Please tell me exactly what needs to be done to restore integrity (if it is even possible) before the next backup run. I really don’t want to restart my entire backup and lose all the history. Thanks.

Edit: Uh-oh. Ran ‘Verify Files’ and got this: ‘Found 3 files that are missing from the remote storage, please run repair’. Will clicking ‘Repair’ completely fix the problem, or do I need to manually edit the database?

Edit 2: It appears that to completely repair the damage, the following SQL commands need to be run (from ts678’s post in the bug report):

SELECT “Name” FROM “Remotevolume” WHERE Type == “Index” AND “State” == “Verified” AND “ID” NOT IN (SELECT “IndexVolumeID” FROM “IndexBlockLink”)

and then

UPDATE “RemoteVolume” SET “State” = “Deleting” WHERE Type == “Index” AND “State” == “Verified” AND “ID” NOT IN (SELECT “IndexVolumeID” FROM “IndexBlockLink”)

The Deleting dindex patch should be committed immediately. Manually editing a SQL database is really not user-friendly.

Edit 3: Should the SQL commands be run before, after or instead of the Repair?

2022-10-10 11:26:26 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2022-10-10 11:26:26 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation List has started
2022-10-10 17:18:49 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started
2022-10-10 17:19:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2022-10-10 17:19:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (443 bytes)
2022-10-10 17:19:09 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-b7bd678b7c2a64f91b2c3f4e7342d60e6.dblock.zip.aes
2022-10-10 17:19:09 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bd0f90a535cf64895840dfaac1d17cea1.dblock.zip.aes
2022-10-10 17:19:09 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-bbd0666fce32e4eda8ecf382df9543ce8.dblock.zip.aes
2022-10-10 17:19:09 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Deleting: duplicati-20221010T043856Z.dlist.zip.aes
2022-10-10 17:19:12 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-b315a2efb3ec84d52bdf8850669851e7a.dblock.zip.aes
2022-10-10 17:19:12 -04 - [Information-Duplicati.Library.Main.Operation.FilelistProcessor-RemoteUnwantedMissingFile]: removing file listed as Temporary: duplicati-i5474994074284f02a744c1a82d0fd339.dindex.zip.aes
2022-10-10 17:19:12 -04 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes
2022-10-10 17:19:12 -04 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes
2022-10-10 17:19:12 -04 - [Warning-Duplicati.Library.Main.Operation.FilelistProcessor-MissingFile]: Missing file: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes
2022-10-10 17:19:12 -04 - [Error-Duplicati.Library.Main.Operation.FilelistProcessor-MissingRemoteFiles]: Found 3 files that are missing from the remote storage, please run repair

All three of your files seen as missing were actually deleted, according to log comparison below:

The Delete are the end of one compact cycle. The Get start the next one, so is a good time to fail,
except for the forgetting that Delete had happened (forgetting is due to unfinished DB transaction).

Let’s also look at the non-dindex messages to see if there seems to be a similar cleanup problem:

This doesn’t have a match in posted log, but it might be before the posted part. Search log if you wish.

I’ve been looking at the lengthy old issue to see if a good way to fix this is known. Not clear one exists.
Just running Repair pushed up some dindex files, but they were then extra, with no associated dblock.
This bothered DB recreate. I was wondering if going hands-on in DB was needed, and it looks like you
already are in there (in later edits). The basic idea would be to get rid of the Remotevolume table rows thinking they know those dindex files, but first make sure that ID isn’t in IndexBlockLink IndexVolumeID.

Make a copy of the database before trying such experiments. I’ll look at your SQL, but mine’s not great.
You seem to have a similar idea, but details matter, so rather than setting State I call for manual delete.
Having a tested procedure that works on the issue test case would be nice. Maybe yours would be it…

Even better, if you do C# and GitHub, would be to test the proposed patch and submit the pull request.
There is such a shortage of developer volunteers that it might sit, but at least it could be readied to go.
Eventually the original author might show up if nobody else does it first, and would be a good reviewer.

Thanks for your help. Actually, those are your SQL statements - I just copied them from the bug report.

I have made a copy of the database. Running the first SQL command gives 3 records:

duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes
duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes
duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes

Is it safe to run the second command and set the state to Deleting or do you have an alternate command to simply delete the records? BTW, I have not yet run ‘Repair’. Should I do that, or did ‘Verify Files’ already do what ‘Repair’ would have.

Yes, the other dindex files you couldn’t find in the log were successfully deleted:

2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-b7bd678b7c2a64f91b2c3f4e7342d60e6.dblock.zip.aes (179.21 MB)
2022-10-10 01:10:46: Backend event: Delete - Completed: duplicati-b7bd678b7c2a64f91b2c3f4e7342d60e6.dblock.zip.aes (179.21 MB)
2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes (102.51 KB)
2022-10-10 01:10:46: Backend event: Delete - Completed: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes (102.51 KB)
2022-10-10 01:10:46: Backend event: Delete - Started: duplicati-bd0f90a535cf64895840dfaac1d17cea1.dblock.zip.aes (23.64 MB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-bd0f90a535cf64895840dfaac1d17cea1.dblock.zip.aes (23.64 MB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes (23.64 KB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes (23.64 KB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-bbd0666fce32e4eda8ecf382df9543ce8.dblock.zip.aes (61.96 MB)
2022-10-10 01:10:47: Backend event: Delete - Completed: duplicati-bbd0666fce32e4eda8ecf382df9543ce8.dblock.zip.aes (61.96 MB)
2022-10-10 01:10:47: Backend event: Delete - Started: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes (42.83 KB)
2022-10-10 01:10:48: Backend event: Delete - Completed: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes (42.83 KB)

But the dlist file is very weird. Seems that it was renamed. Here are all the log entries for it:

2022-10-10 00:46:48: Backend event: Put - Started: duplicati-20221010T043856Z.dlist.zip.aes (10.75 MB)
2022-10-10 00:47:20: Backend event: Put - Retrying: duplicati-20221010T043856Z.dlist.zip.aes (10.75 MB)
2022-10-10 00:47:30: Backend event: Put - Rename: duplicati-20221010T043856Z.dlist.zip.aes (10.75 MB)
2022-10-10 00:47:30: Backend event: Put - Rename: duplicati-20221010T043857Z.dlist.zip.aes (10.75 MB)
2022-10-10 00:47:30: Renaming "duplicati-20221010T043856Z.dlist.zip.aes" to "duplicati-20221010T043857Z.dlist.zip.aes"
2022-10-10 00:47:30: Backend event: Put - Started: duplicati-20221010T043857Z.dlist.zip.aes (10.75 MB)
2022-10-10 00:47:37: Backend event: Put - Completed: duplicati-20221010T043857Z.dlist.zip.aes (10.75 MB)

2022-10-10 00:49:19: Backend event: Delete - Started: duplicati-20221010T043856Z.dlist.zip.aes ()
2022-10-10 00:49:19: Delete operation failed for duplicati-20221010T043856Z.dlist.zip.aes with FileNotFound, listing contents
2022-10-10 00:49:20: Listing indicates file duplicati-20221010T043856Z.dlist.zip.aes was deleted correctly

That explains why the context for the first statement was missing. It was not copied.

can find extra dindex files, then if the user wishes, they can be set up for remote deletion as described previously:

That part seems to have worked, naming your three confused files.
Your log output shows outputs of code that handles Deleting State.

That’s in RemoteListAnalysis, which is run by VerifyRemoteList which I assume Verify files runs.
You’ve also pushed the button and seen it in action. Well, I guess you can run the second SQL, then
push the button again to see what it does, then push it again to see if things now seem to be happy…

Seems to have worked. Here is the ‘Verify Files’ log. Crossing my fingers.

For anyone who has the same situation, the SQL browser I downloaded was DB Browser for SQLite

2022-10-10 19:07:16: The operation Test has started
2022-10-10 19:08:14: The operation Test has started
2022-10-10 19:08:47: Backend event: List - Started:  ()
2022-10-10 19:08:49: Backend event: List - Completed:  (443 bytes)
2022-10-10 19:08:49: removing file listed as Deleting: duplicati-i1ddf470ccbd343c0aae9bd42b735858b.dindex.zip.aes
2022-10-10 19:08:49: removing file listed as Deleting: duplicati-iac3e0c3730da44bfbed3a7510e822102.dindex.zip.aes
2022-10-10 19:08:49: removing file listed as Deleting: duplicati-i3cb62aba375a45b6ae36fa4e0f3dbd10.dindex.zip.aes
2022-10-10 19:08:51: Backend event: Get - Started: duplicati-20221010T043857Z.dlist.zip.aes (10.75 MB)
2022-10-10 19:08:53: Backend event: Get - Completed: duplicati-20221010T043857Z.dlist.zip.aes (10.75 MB)
2022-10-10 19:08:53: Backend event: Get - Started: duplicati-id5c9e009bd604bc7942153aa93272807.dindex.zip.aes (50.56 KB)
2022-10-10 19:08:53: Backend event: Get - Completed: duplicati-id5c9e009bd604bc7942153aa93272807.dindex.zip.aes (50.56 KB)
2022-10-10 19:08:57: Backend event: Get - Started: duplicati-b453ca0558513482dbc3df60a588947b8.dblock.zip.aes (199.86 MB)
2022-10-10 19:09:24: Backend event: Get - Completed: duplicati-b453ca0558513482dbc3df60a588947b8.dblock.zip.aes (199.86 MB)

I’m not going to post SQL without testing, but SQL DELETE Statement suggests how to write the syntax.
An advantage of setting State Deleting is that the code looks more careful about files’ presence/absence.

You can see if the next Verify files comes up clean. If so, the similar test done at backup start should.

Yes, the next ‘Verify Files’ came up clean. Hope this is the end of the problem. Thanks for all your help.

1 Like

Based on my experience, even if the backups are running and everything seems to be fine. The backup can be corrupted. Only way to be sure is to run full restore test. I do that regularly and unfortunately find every now and then corrupted backups.

The missing files issue can be remedied by repair, it works quite well. And I earlier said in some discussion that the issue is probably fixed, but it’s not. I got it again just yesterday. Similar experience to the opening post.

Aside from getting backups going again, does Repair break database recreate for you as it did for me?

This method basically causes the problem where things seem fine until you find they’re not quite fine…
That’s why I’m recommending against it, although running SQL in a DB browser is a very ugly cleanup.

EDIT: On the other hand, post below seems to think Repair’s extra dindex files were OK. Who knows?
Maybe the results vary depending on the exact nature of the failure? This could use more investigation.

… as evidenced not only by that, but by the issue about it still being open. Feel free to read through that.

If everything else tracks well, you’ve hit the open issue that nobody’s volunteered to fix in several years.
Issue has been hugely studied and even got steps to reproduce, but developers have been unavailable.

Duplicati very much needs developers. Even non-expert could play with the test case and proposed fix.
As a community effort, Duplicati relies on volunteers in all areas. Right now, many areas are super low.