FailedToProcessFile error

[RedFez]

Hi

I’ve been running Duplicati on a Windows Server Essentials 2016 system for a few months without a problem, backing up shared folders to Backblaze B2. A few days ago, backups started failing with the following errors:

@charset “UTF-8”;[ng:cloak],[ng-cloak],[data-ng-cloak],[x-ng-cloak],.ng-cloak,.x-ng-cloak,.ng-hide:not(.ng-hide-animate){display:none !important;}ng:form{display:block;}.ng-animate-shim{visibility:hidden;}.ng-anchor{position:absolute;} REDFEZSERVER - Duplicati

• • 2020-04-23 08:50:39 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20200422T020000Z.dlist.zip.aes
  • 2020-04-23 08:51:36 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i89fd9c4e698340b6a88ebdf2e3e6b56d.dindex.zip.aes
  • 2020-04-23 08:52:33 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b9d3c6e694a7c470ebca16b7fe89c42a5.dblock.zip.aes

Any ideas where I need to start looking?

Thanks!

[ts678]

Welcome to the forum @RedFez

@RedFez

Any ideas where I need to start looking?

These one-line summaries generally chop off the details behind why the error actually happened.
Using another browser tab to view live log at About → Show log → Live → Retry might get info.

TestHandler in a backup is probably Verifying backend files testing a set of 3 files – and all failed. Network issues could cause failures, but I’d also expect some problems uploading that backup…

[RedFez]

Hi ts678

Thanks for your reply. I really appreciate it.

Here’s the complete log:

{ “DeletedFiles”: 2, “DeletedFolders”: 0, “ModifiedFiles”: 0, “ExaminedFiles”: 12298, “OpenedFiles”: 3, “AddedFiles”: 3, “SizeOfModifiedFiles”: 0, “SizeOfAddedFiles”: 16874, “SizeOfExaminedFiles”: 24867197116, “SizeOfOpenedFiles”: 16874, “NotProcessedFiles”: 0, “AddedFolders”: 0, “TooLargeFiles”: 0, “FilesWithError”: 0, “ModifiedFolders”: 0, “ModifiedSymlinks”: 0, “AddedSymlinks”: 0, “DeletedSymlinks”: 0, “PartialBackup”: false, “Dryrun”: false, “MainOperation”: “Backup”, “CompactResults”: { “DeletedFileCount”: 0, “DownloadedFileCount”: 0, “UploadedFileCount”: 0, “DeletedFileSize”: 0, “DownloadedFileSize”: 0, “UploadedFileSize”: 0, “Dryrun”: false, “VacuumResults”: null, “MainOperation”: “Compact”, “ParsedResult”: “Success”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “2020-04-26T02:01:50.8200073Z”, “BeginTime”: “2020-04-26T02:01:38.5622491Z”, “Duration”: “00:00:12.2577582”, “MessagesActualLength”: 0, “WarningsActualLength”: 0, “ErrorsActualLength”: 0, “Messages”: null, “Warnings”: null, “Errors”: null, “BackendStatistics”: { “RemoteCalls”: 20, “BytesUploaded”: 1214679, “BytesDownloaded”: 0, “FilesUploaded”: 3, “FilesDownloaded”: 0, “FilesDeleted”: 0, “FoldersCreated”: 0, “RetryAttempts”: 12, “UnknownFileSize”: 0, “UnknownFileCount”: 1, “KnownFileCount”: 1010, “KnownFileSize”: 23981348266, “LastBackupDate”: “2020-04-26T03:00:00+01:00”, “BackupListCount”: 50, “TotalQuotaSpace”: 0, “FreeQuotaSpace”: 0, “AssignedQuotaSpace”: -1, “ReportedQuotaError”: false, “ReportedQuotaWarning”: false, “MainOperation”: “Backup”, “ParsedResult”: “Success”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “0001-01-01T00:00:00”, “BeginTime”: “2020-04-26T02:00:00.0065075Z”, “Duration”: “00:00:00”, “MessagesActualLength”: 0, “WarningsActualLength”: 0, “ErrorsActualLength”: 0, “Messages”: null, “Warnings”: null, “Errors”: null } }, “VacuumResults”: null, “DeleteResults”: null, “RepairResults”: null, “TestResults”: { “MainOperation”: “Test”, “VerificationsActualLength”: 3, “Verifications”: [ { “Key”: “duplicati-20200426T020000Z.dlist.zip.aes”, “Value”: [ { “Key”: “Error”, “Value”: “The underlying connection was closed: An unexpected error occurred on a send.” } ] }, { “Key”: “duplicati-ia7daf0b0ad7d4f12aa166ceadd8ecf69.dindex.zip.aes”, “Value”: [ { “Key”: “Error”, “Value”: “The underlying connection was closed: An unexpected error occurred on a send.” } ] }, { “Key”: “duplicati-b264adf87ba7d4ee0a23819966f1a4373.dblock.zip.aes”, “Value”: [ { “Key”: “Error”, “Value”: “The underlying connection was closed: An unexpected error occurred on a send.” } ] } ], “ParsedResult”: “Success”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “2020-04-26T02:04:51.2796477Z”, “BeginTime”: “2020-04-26T02:01:55.4240225Z”, “Duration”: “00:02:55.8556252”, “MessagesActualLength”: 0, “WarningsActualLength”: 0, “ErrorsActualLength”: 0, “Messages”: null, “Warnings”: null, “Errors”: null, “BackendStatistics”: { “RemoteCalls”: 20, “BytesUploaded”: 1214679, “BytesDownloaded”: 0, “FilesUploaded”: 3, “FilesDownloaded”: 0, “FilesDeleted”: 0, “FoldersCreated”: 0, “RetryAttempts”: 12, “UnknownFileSize”: 0, “UnknownFileCount”: 1, “KnownFileCount”: 1010, “KnownFileSize”: 23981348266, “LastBackupDate”: “2020-04-26T03:00:00+01:00”, “BackupListCount”: 50, “TotalQuotaSpace”: 0, “FreeQuotaSpace”: 0, “AssignedQuotaSpace”: -1, “ReportedQuotaError”: false, “ReportedQuotaWarning”: false, “MainOperation”: “Backup”, “ParsedResult”: “Success”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “0001-01-01T00:00:00”, “BeginTime”: “2020-04-26T02:00:00.0065075Z”, “Duration”: “00:00:00”, “MessagesActualLength”: 0, “WarningsActualLength”: 0, “ErrorsActualLength”: 0, “Messages”: null, “Warnings”: null, “Errors”: null } }, “ParsedResult”: “Error”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “2020-04-26T02:04:51.2796477Z”, “BeginTime”: “2020-04-26T02:00:00.0065075Z”, “Duration”: “00:04:51.2731402”, “MessagesActualLength”: 42, “WarningsActualLength”: 0, “ErrorsActualLength”: 3, “Messages”: [ “2020-04-26 03:00:00 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started”, “2020-04-26 03:00:44 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”, “2020-04-26 03:00:47 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (1008 bytes)”, “2020-04-26 03:01:09 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b0905c0bf92fe4e8e94605a86f248de51.dblock.zip.aes (4.76 KB)”, “2020-04-26 03:01:30 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b0905c0bf92fe4e8e94605a86f248de51.dblock.zip.aes (4.76 KB)”, “2020-04-26 03:01:30 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:01:31 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i83f5bb6f2366463f809745d7cd0908c6.dindex.zip.aes (1.06 KB)”, “2020-04-26 03:01:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i83f5bb6f2366463f809745d7cd0908c6.dindex.zip.aes (1.06 KB)”, “2020-04-26 03:01:38 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:01:50 +01 - [Information-Duplicati.Library.Main.Database.LocalDeleteDatabase-CompactReason]: Compacting not required”, “2020-04-26 03:01:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()”, “2020-04-26 03:01:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (1011 bytes)”, “2020-04-26 03:01:55 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:01:57 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:07 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:11 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:21 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:25 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:35 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)”, “2020-04-26 03:02:40 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Retrying: duplicati-20200426T020000Z.dlist.zip.aes (1.15 MB)” ], “Warnings”: , “Errors”: [ “2020-04-26 03:02:54 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20200426T020000Z.dlist.zip.aes”, “2020-04-26 03:03:52 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-ia7daf0b0ad7d4f12aa166ceadd8ecf69.dindex.zip.aes”, “2020-04-26 03:04:51 +01 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b264adf87ba7d4ee0a23819966f1a4373.dblock.zip.aes” ], “BackendStatistics”: { “RemoteCalls”: 20, “BytesUploaded”: 1214679, “BytesDownloaded”: 0, “FilesUploaded”: 3, “FilesDownloaded”: 0, “FilesDeleted”: 0, “FoldersCreated”: 0, “RetryAttempts”: 12, “UnknownFileSize”: 0, “UnknownFileCount”: 1, “KnownFileCount”: 1010, “KnownFileSize”: 23981348266, “LastBackupDate”: “2020-04-26T03:00:00+01:00”, “BackupListCount”: 50, “TotalQuotaSpace”: 0, “FreeQuotaSpace”: 0, “AssignedQuotaSpace”: -1, “ReportedQuotaError”: false, “ReportedQuotaWarning”: false, “MainOperation”: “Backup”, “ParsedResult”: “Success”, “Version”: “2.0.5.1 (2.0.5.1_beta_2020-01-18)”, “EndTime”: “0001-01-01T00:00:00”, “BeginTime”: “2020-04-26T02:00:00.0065075Z”, “Duration”: “00:00:00”, “MessagesActualLength”: 0, “WarningsActualLength”: 0, “ErrorsActualLength”: 0, “Messages”: null, “Warnings”: null, “Errors”: null } }

I also checked some files that had been created that day and they backed up just fine. So it does seem to be failing on verification

[ts678]

A bit more here, but a live log is still needed to see the details behind the one-line error summaries.
If this can’t be done, options –log-file and –log-file-log-level=retry work nicely, but need more setup.

This log at least confirms “RetryAttempts”: 12 and shows some specific ones that were needed.

“UnknownFileCount”: 1 is unusual. Is there something there besides Duplicati dlist, dblock, dindex?
Duplicati should have a folder per backup, and can even give errors if it finds extra files in the area.
“UnknownFileSize”: 0 says whatever this is, it has no size. I don’t know how an extra folder will say.
All of this may or may not be relevant to the primary issue of the error, but I will mention it anyway…

“The underlying connection was closed: An unexpected error occurred on a send.”
looks like either a networking error or a B2 oddity. Possibly other error lines would identify it better.

@RedFez

So it does seem to be failing on verification

You can test just the verification (without backup) with the Verify files button for the backup job.
There are several more complicated ways, but let’s hold off until the live log shows what happened.

Because there might be network issues, let me ask if your networking is usually very reliable or not.
My own consumer-quality networking equipment sometimes needs reconnects, reboots, and so on.