Error backing up to OneDrive personal

Support
1

Have been using Duplicati for well over a year without issues - backing up to OneDrive. Recently - In the last thee weeks I have been getting the following error: " * 2022-03-13 12:25:08 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-RemoteFileProcessingFailed]: Failed to process file duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes"

Can’t figure out what the cause might be. It looks like a file is failing to upload - but not sure why. Pasting the complete log below. Any ideas on what to do? Note that I have this job scheduled to run automatically and I have not added any new files to the directories being backed up since the error started. Could that have anything to do with it?

Here is the complete log:

{
“MainOperation”: “Test”,
“VerificationsActualLength”: 3,
“Verifications”: [
{
“Key”: “duplicati-20210604T112932Z.dlist.zip.aes”,
“Value”: []
},
{
“Key”: “duplicati-i61cf14786e884009ba7c429f54e1b523.dindex.zip.aes”,
“Value”: []
},
{
“Key”: “duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes”,
“Value”: [
{
“Key”: “Error”,
“Value”: “HTTP timeout 00:01:40 exceeded.”
}
]
}
],
“ParsedResult”: “Error”,
“Version”: “2.0.6.3 (2.0.6.3_beta_2021-06-17)”,
“EndTime”: “2022-03-13T10:25:08.9171686Z”,
“BeginTime”: “2022-03-13T10:15:23.6146562Z”,
“Duration”: “00:09:45.3025124”,
“MessagesActualLength”: 17,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 1,
“Messages”: [
“2022-03-13 12:15:23 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Test has started”,
“2022-03-13 12:15:24 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”,
“2022-03-13 12:16:04 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (3.13 KB)”,
“2022-03-13 12:16:05 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20210604T112932Z.dlist.zip.aes (49.28 KB)”,
“2022-03-13 12:16:07 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20210604T112932Z.dlist.zip.aes (49.28 KB)”,
“2022-03-13 12:16:07 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-i61cf14786e884009ba7c429f54e1b523.dindex.zip.aes (17.97 KB)”,
“2022-03-13 12:16:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-i61cf14786e884009ba7c429f54e1b523.dindex.zip.aes (17.97 KB)”,
“2022-03-13 12:16:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:17:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:17:58 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:19:38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:19:48 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:21:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:21:38 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:23:18 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:23:28 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”,
“2022-03-13 12:25:08 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Failed: duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes (49.99 MB)”
],
“Warnings”: [],
“Errors”: [
“2022-03-13 12:25:08 +02 - [Error-Duplicati.Library.Main.Operation.TestHandler-RemoteFileProcessingFailed]: Failed to process file duplicati-bf9de0a24aef24f4f9c5c7a32b8083a5d.dblock.zip.aes”
],
“BackendStatistics”: {
“RemoteCalls”: 8,
“BytesUploaded”: 0,
“BytesDownloaded”: 68858,
“FilesUploaded”: 0,
“FilesDownloaded”: 2,
“FilesDeleted”: 0,
“FoldersCreated”: 0,
“RetryAttempts”: 4,
“UnknownFileSize”: 0,
“UnknownFileCount”: 0,
“KnownFileCount”: 3206,
“KnownFileSize”: 82774920798,
“LastBackupDate”: “2022-02-17T12:00:00+02:00”,
“BackupListCount”: 10,
“TotalQuotaSpace”: 1104880336896,
“FreeQuotaSpace”: 948484991522,
“AssignedQuotaSpace”: -1,
“ReportedQuotaError”: false,
“ReportedQuotaWarning”: false,
“MainOperation”: “Test”,
“ParsedResult”: “Success”,
“Version”: “2.0.6.3 (2.0.6.3_beta_2021-06-17)”,
“EndTime”: “0001-01-01T00:00:00”,
“BeginTime”: “2022-03-13T10:15:23.6146562Z”,
“Duration”: “00:00:00”,
“MessagesActualLength”: 0,
“WarningsActualLength”: 0,
“ErrorsActualLength”: 0,
“Messages”: null,
“Warnings”: null,
“Errors”: null
}
}

2

One other point on this - despite the errors - Duplicati reports that the backups are successful. I tried to add some files, ran the backup again, and then attempted to restore two of the newly added files. This worked fine - files were restored and no errors reported. Does this mean that I can ignore the error above? Anything else that can be done to diagnose?

  • David
3

Welcome to the forum @David_Sokolic

That is possibly the first half of it. The second half is Verifying backend files noticing a bad download.
Watching live log at About → Show log → Live log → Warning will get you a more detailed message.
If you’d rather not do a backup to get its post-backup verification, you can use Verify files button.

If you’re somewhat ambitious, you can get an Export As Command-line URL, edit to empty folder, run Duplicati.CommandLine.BackendTester.exe awhile to see if OneDrive is able to handle this basic test.

OneDrive high levels of uploaded file corruption describes increasing ambitious diagnostics that I tried. Nobody had responded to my Feb 4 post asking if anyone else was seeing this, but possibly you are?
I’m reluctant to just ask for the file because there’s no telling what’s inside, if OneDrive is scrambling it.

If you think you may have some damaged files at the destination, you can sample more, or all of them.
The TEST command for example run from GUI Commandline would be one way to get a large sample.

When you identify a bad file (for example the one you named), you can also look at date, size, and try AES Crypt or Duplicati’s CLI SharpAESCrypt.exe to see if that file is in fact no longer possible to open.

4

One other potential issue - I recently upgraded my workstation from Windows 10 to Windows 11 and the problem started after this. I had two backups running - and they both exhibit this problem since upgrading to Windows 11. I created another test backup - and had the same problem. Could it be related to windows 11 somehow?

5

Before speculating on that, please identify what the problem is, at least to the extent live log can show.

6

I did look at the live log and noticed that verification of some files was failing with the message “HTTP timeout 00:01:40 exceeded”. I changed the HTTP HTTP-operation-timeout parameter in the backup configuration to 7 minutes and this seems to have fixed the problem. Does that make sense?

7

Yes and I see that I missed the usual clues of original post. Sorry about that, and glad you found it,
although for many people with timeouts this hits on upload because Internet upload speed is lower.
Yours hit on download. I don’t know what speed you expect, but you can do some math, if you like.

I still have no idea whether or not Windows 11 contributed anything that reduced download speeds.

If you have old job logs before then, you could look at Complete log sections for RetryAttempts. Possibly it was on the edge of timing out all number-of-retries (default 5) before, and finally hit that.
File sizes may vary. The one shown is about as big as the default limit. Maybe others were smaller.