Failed to process file duplicati-XXXXX.dblock.zip.aes

Support
1

Trying to track down a problem that’s been hounding me for a while and can’t seem to find a fix here on the forum. Basic situation:

  • Duplicati - 2.0.5.1_beta_2020-01-18 (also happened with previous Canary build, so I don’t think it’s release related)
  • Windows 10 (running as a service)
  • Backblaze B2 cloud storage

I get the “Failed to process file” message for every run. However, it’s choking on a different file every time. For example, here’s the log snippet from the latest run:

"ParsedResult": "Error",
  "Version": "2.0.5.1 (2.0.5.1_beta_2020-01-18)",
  "EndTime": "2020-01-19T14:43:34.2528993Z",
  "BeginTime": "2020-01-19T14:17:40.070016Z",
  "Duration": "00:25:54.1828833",
  "MessagesActualLength": 24,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 1,
  "Messages": [
    "2020-01-19 08:17:40 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2020-01-19 08:17:55 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2020-01-19 08:17:56 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (572 bytes)",
    "2020-01-19 08:18:10 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...",
    "2020-01-19 08:18:15 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20191019T053003Z.dlist.zip.aes (534.37 KB)",
    "2020-01-19 08:18:16 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20191019T053003Z.dlist.zip.aes (534.37 KB)",
    "2020-01-19 08:18:16 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 1 remote fileset(s)",
    "2020-01-19 08:18:41 -06 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required",
    "2020-01-19 08:18:41 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2020-01-19 08:18:42 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (571 bytes)",
    "2020-01-19 08:18:43 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20191213T053124Z.dlist.zip.aes (530.73 KB)",
    "2020-01-19 08:18:46 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20191213T053124Z.dlist.zip.aes (530.73 KB)",
    "2020-01-19 08:18:46 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-ic08cfc0116b14ec9bc9b7887b11ca0f8.dindex.zip.aes (162.65 KB)",
    "2020-01-19 08:18:47 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-ic08cfc0116b14ec9bc9b7887b11ca0f8.dindex.zip.aes (162.65 KB)",
    "2020-01-19 08:18:47 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)",
    "2020-01-19 08:21:12 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)",
    "2020-01-19 08:21:22 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)",
    "2020-01-19 08:25:09 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)",
    "2020-01-19 08:25:19 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)",
    "2020-01-19 08:28:52 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes (200.02 MB)"
  ],
  "Warnings": [],
  "Errors": [
    "2020-01-19 08:43:34 -06 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b85fe9f99af1445c389a4a446dd079193.dblock.zip.aes"
  ],

Here’s the run before that:

 "ParsedResult": "Error",
  "Version": "2.0.5.1 (2.0.5.1_beta_2020-01-18)",
  "EndTime": "2020-01-19T05:48:38.5726837Z",
  "BeginTime": "2020-01-19T05:30:00.1004759Z",
  "Duration": "00:18:38.4722078",
  "MessagesActualLength": 24,
  "WarningsActualLength": 0,
  "ErrorsActualLength": 1,
  "Messages": [
    "2020-01-18 23:30:00 -06 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
    "2020-01-18 23:30:15 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2020-01-18 23:30:16 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (573 bytes)",
    "2020-01-18 23:30:31 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteRemoteFileset]: Deleting 1 remote fileset(s) ...",
    "2020-01-18 23:30:36 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Started: duplicati-20191018T053000Z.dlist.zip.aes (534.26 KB)",
    "2020-01-18 23:30:37 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Delete - Completed: duplicati-20191018T053000Z.dlist.zip.aes (534.26 KB)",
    "2020-01-18 23:30:37 -06 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: Deleted 1 remote fileset(s)",
    "2020-01-18 23:31:01 -06 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required",
    "2020-01-18 23:31:01 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2020-01-18 23:31:02 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (572 bytes)",
    "2020-01-18 23:31:03 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20191102T053000Z.dlist.zip.aes (535.08 KB)",
    "2020-01-18 23:31:06 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20191102T053000Z.dlist.zip.aes (535.08 KB)",
    "2020-01-18 23:31:06 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i8cc4a263414e425fa4753e3ad4459adc.dindex.zip.aes (169.43 KB)",
    "2020-01-18 23:31:07 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i8cc4a263414e425fa4753e3ad4459adc.dindex.zip.aes (169.43 KB)",
    "2020-01-18 23:31:07 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)",
    "2020-01-18 23:32:37 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)",
    "2020-01-18 23:32:47 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)",
    "2020-01-18 23:37:14 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)",
    "2020-01-18 23:37:24 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)",
    "2020-01-18 23:40:41 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes (199.95 MB)"
  ],
  "Warnings": [],
  "Errors": [
    "2020-01-18 23:48:38 -06 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b04d41534e3e64f0bb0c9a79c345e0f9d.dblock.zip.aes"
  ],

So it doesn’t seem to be a particular file it’s having a problem with. Before I go ahead and delete/recreate the backup, is there some other debugging steps or a known fix that I can use to salvage this backup?

Thanks,

HG

2

The TestHandler is Verifying backend files after backup the same way as The TEST command can do:

This is a rolling check, i.e. when executed another time different samples are verified than in the first run.

which is kind of worrisome because it sounds like it’s found many bad files. The dblocks have file data, whereas dlist and dindex are information about what the data means, and such info is also in local DB and can be used to rebuild dlist and dindex files if need be. There is only one copy of dblock file info…

Viewing the Duplicati Server Logs at About → Show log → Live → Retry would give more info about whatever the sampled test is objecting to. How many times it retries may be significant, as a solid error repeating itself for 5 or 6 tries before exhausting the retry count is better proof of an actual file problem.

You can download the file and try to look at it with AES Crypt if you like. If it won’t open, it’s damaged…

Have you ever throttled Duplicati’s usage of the Internet connection? That could do temporary damage on downloads and permanent damage on uploads. Both are fixed now, but prior damage would persist.

Quite a lot of guessing above. Probably need a look at the file. Typical dblock would be about what you set for Remote Volume Size (default 50 MB), but the last dblock at the end of a backup may be smaller.

Please at least try to catch the error message with some detail, and then we will have some better idea.

1 Like
3

AES Crypt was able to decrypt the file just fine. However, this got me thinking:

“Well, no, I never throttle the connection in Duplicati, that’s silly!” I responded with a bit of snarkiness. Well. I went ahead and checked the backup configuration just to prove you wrong. Turns out that you were right! :astonished: For some reason throttling was turned on for this backup and I have no idea how it got there. The only thing I can think of is that this was one of the earliest systems I installed Duplicati on and perhaps I was doing some testing during the installs?

Anyway, I turned off throttling and reran the backup. Worked instantly with no errors! Thanks for the tip. I would have been chasing that down for weeks!

Given the potential for corruption due to the throttling, I’m going to delete the back-end data set and refresh the backup just to be safe. But at least I now know what caused the issue in the first place.

Thanks again,

HG

1 Like