I have a number of backup jobs running, some of them quite big (1-2TB) with lots of files. I am using Duplicati 2.1.0.3_beta_2025-01-22 running in a Docker container on an Asustor NAS and all jobs use WebDAV. The destination for all jobs is my friend’s NAS who uses the exact same setup to backup his files on my NAS. We have been running this setup successfully for years.
For 1-2 months now I keep getting weird errors. The very small jobs do not have them, the medium ones do randomly and the big ones almost all the time. My friend has jobs comparable in size and amount of files but does not have any of these problems.
From what I can see the jobs start, verify the backend, then gather the local files, do the backup, delete obsolete files and then verify some remote files - and then the errors occurr:
{
"DeletedFiles": 0,
"DeletedFolders": 0,
"ModifiedFiles": 0,
"ExaminedFiles": 131841,
"OpenedFiles": 0,
"AddedFiles": 0,
"SizeOfModifiedFiles": 0,
"SizeOfAddedFiles": 0,
"SizeOfExaminedFiles": 940296395245,
"SizeOfOpenedFiles": 0,
"NotProcessedFiles": 0,
"AddedFolders": 0,
"TooLargeFiles": 0,
"FilesWithError": 0,
"ModifiedFolders": 0,
"ModifiedSymlinks": 0,
"AddedSymlinks": 0,
"DeletedSymlinks": 0,
"PartialBackup": false,
"Dryrun": false,
"MainOperation": "Backup",
"CompactResults": null,
"VacuumResults": null,
"DeleteResults": {
"DeletedSetsActualLength": 0,
"DeletedSets": [],
"Dryrun": false,
"MainOperation": "Delete",
"CompactResults": null,
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "2025-02-02T17:27:31.4274279Z",
"BeginTime": "2025-02-02T17:22:14.2549805Z",
"Duration": "00:05:17.1724474",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null,
"BackendStatistics": {
"RemoteCalls": 123,
"BytesUploaded": 0,
"BytesDownloaded": 79071627,
"FilesUploaded": 0,
"FilesDownloaded": 23,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 80,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 17992,
"KnownFileSize": 941514800728,
"LastBackupDate": "2025-01-21T04:12:53+00:00",
"BackupListCount": 5,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-02-02T17:19:20.443248Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
},
"RepairResults": null,
"TestResults": {
"MainOperation": "Test",
"VerificationsActualLength": 41,
"Verifications": [
{
"Key": "duplicati-20240520T032031Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-20250117T060545Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-20240926T030616Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-20250121T041253Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-20240221T030657Z.dlist.zip.aes",
"Value": []
},
{
"Key": "duplicati-i28ff18a115034a3ababd18040d170d60.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i0966f832880648bdb5a79c20f3cde72f.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i843d4db94158409194c00ba36b86c67c.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i63687af844114f89961821440f6a76aa.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-id0f5c86ab0e44d1184943d61d4d86eb2.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-ie09c821de2db4bedada4326193f16e4e.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i40a951a4ab624e529e7359b45492f6f1.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i0c15fd3de39e4ae9b5a8f350de6fcc83.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-ic58020b7883e4c3ab010d369fde9e627.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i6c51bc3a42944f42abea8b3ee9919026.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-ied8ce90e22aa48af8e8fe373f32d9787.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-ifaaba43d52f442debaf24895c18a78fb.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-ib00eb1c17d804855ad5dc637bf8d549e.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i48869c23a68b4992ba31a2d2fbd2ae45.dindex.zip.aes",
"Value": []
},
{
"Key": "duplicati-i3d961a240da94245a9544a883aaf7e54.dindex.zip.aes",
"Value": []
}
],
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "2025-02-02T22:08:00.4589673Z",
"BeginTime": "2025-02-02T17:27:50.8262877Z",
"Duration": "04:40:09.6326796",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null,
"BackendStatistics": {
"RemoteCalls": 123,
"BytesUploaded": 0,
"BytesDownloaded": 79071627,
"FilesUploaded": 0,
"FilesDownloaded": 23,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 80,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 17992,
"KnownFileSize": 941514800728,
"LastBackupDate": "2025-01-21T04:12:53+00:00",
"BackupListCount": 5,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-02-02T17:19:20.443248Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
},
"ParsedResult": "Error",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "2025-02-02T22:08:04.1677097Z",
"BeginTime": "2025-02-02T17:19:20.4432415Z",
"Duration": "04:48:43.7244682",
"MessagesActualLength": 253,
"WarningsActualLength": 0,
"ErrorsActualLength": 19,
"Messages": [
"2025-02-02 17:19:20 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
"2025-02-02 17:20:12 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-02 17:20:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying: ()",
"2025-02-02 17:20:52 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-02 17:20:57 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (17.57 KB)",
"2025-02-02 17:22:14 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-StartCheck]: Start checking if backups can be removed",
"2025-02-02 17:22:14 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-FramesAndIntervals]: Time frames and intervals pairs: 7.00:00:00 / 1.00:00:00, 28.00:00:00 / 7.00:00:00, 365.00:00:00 / 31.00:00:00",
"2025-02-02 17:22:14 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupList]: Backups to consider: 01/17/2025 06:05:45, 09/26/2024 03:06:16, 05/20/2024 03:20:31, 02/21/2024 03:06:57",
"2025-02-02 17:22:14 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-BackupsToDelete]: Backups outside of all time frames and thus getting deleted: ",
"2025-02-02 17:22:14 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler:RetentionPolicy-AllBackupsToDelete]: All backups to delete: ",
"2025-02-02 17:27:31 +00 - [Information-Duplicati.Library.Main.Operation.DeleteHandler-DeleteResults]: No remote filesets were deleted",
"2025-02-02 17:27:31 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-02 17:27:50 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed: (17.57 KB)",
"2025-02-02 17:27:50 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240520T032031Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:28:07 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240520T032031Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:28:07 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20250117T060545Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:31:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20250117T060545Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:31:17 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20240926T030616Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:31:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20240926T030616Z.dlist.zip.aes (15.08 MB)",
"2025-02-02 17:31:29 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20250121T041253Z.dlist.zip.aes (15.08 MB)"
],
"Warnings": [],
"Errors": [
"2025-02-02 18:15:25 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bd88f3b975909424d93fc6b721e2cc1f3.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 18:27:48 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bc9a1b83a2c26453584edf7f6733e726f.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 18:43:29 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b02efd09058f247bd8036805f8b7c880d.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 19:02:54 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b9818619d75854fa0b08e215779bb58f5.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 19:29:00 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bf623c889c50d424fb67855e0a77f7a47.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 19:49:03 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b4bdb82a990274a3597bc792b4bf72bb5.dblock.zip.aes\nIOException: Received an unexpected EOF or 0 bytes from the transport stream.",
"2025-02-02 20:00:31 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b2b3288aa5b084615bb0edabb537971d8.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 20:09:48 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-ba69b1c89c2164e94a42d5cbfad28083d.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 20:27:40 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b011d44d85c4048b0a260b6e52476c7f9.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 20:38:44 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-be46e8e4cfeee4520b584d94e8192d125.dblock.zip.aes\nHttpRequestException: Resource temporarily unavailable (figment.myasustor.com:33566)",
"2025-02-02 20:45:16 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b152f8849466f499db133879baf0ab29a.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 20:58:21 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bdae54830419e4041b10346645875bb14.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 21:10:06 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b801614091c154437b53d0f63d2565ef8.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 21:23:35 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b2be9a4e41a7a4fcea1c5223201d72449.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 21:30:45 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b93c6381fdba04242b5d6959f0d29f0ee.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 21:42:20 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b3b48b5a1b7cb4adab8552b94b27cbd3f.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 21:49:37 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-b3767663ce2ee4ae89fc036c0d40d658f.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 22:08:00 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bef6f93e4749442d1a859aad88e6cd89f.dblock.zip.aes\nTaskCanceledException: The operation was canceled.",
"2025-02-02 22:08:00 +00 - [Error-Duplicati.Library.Main.Operation.TestHandler-Test results]: Verified 41 remote files with 18 problem(s)"
],
"BackendStatistics": {
"RemoteCalls": 123,
"BytesUploaded": 0,
"BytesDownloaded": 79071627,
"FilesUploaded": 0,
"FilesDownloaded": 23,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 80,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 17992,
"KnownFileSize": 941514800728,
"LastBackupDate": "2025-01-21T04:12:53+00:00",
"BackupListCount": 5,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": -1,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-02-02T17:19:20.443248Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
}
After this has happened a couple of times it gets worse. The process seems to be the same but while in the first situation the backup shows as successful but with errors in the second situation it shows as failed:
{
"DeletedFiles": 0,
"DeletedFolders": 0,
"ModifiedFiles": 0,
"ExaminedFiles": 0,
"OpenedFiles": 0,
"AddedFiles": 0,
"SizeOfModifiedFiles": 0,
"SizeOfAddedFiles": 0,
"SizeOfExaminedFiles": 0,
"SizeOfOpenedFiles": 0,
"NotProcessedFiles": 0,
"AddedFolders": 0,
"TooLargeFiles": 0,
"FilesWithError": 0,
"ModifiedFolders": 0,
"ModifiedSymlinks": 0,
"AddedSymlinks": 0,
"DeletedSymlinks": 0,
"PartialBackup": false,
"Dryrun": false,
"MainOperation": "Backup",
"CompactResults": null,
"VacuumResults": null,
"DeleteResults": null,
"RepairResults": null,
"TestResults": null,
"ParsedResult": "Fatal",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "2025-02-03T04:12:23.0130154Z",
"BeginTime": "2025-02-03T04:07:09.1588366Z",
"Duration": "00:05:13.8541788",
"MessagesActualLength": 11,
"WarningsActualLength": 0,
"ErrorsActualLength": 1,
"Messages": [
"2025-02-03 04:07:09 +00 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started",
"2025-02-03 04:09:12 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-03 04:09:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying: ()",
"2025-02-03 04:09:52 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-03 04:10:22 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying: ()",
"2025-02-03 04:10:32 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-03 04:11:02 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying: ()",
"2025-02-03 04:11:12 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-03 04:11:42 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Retrying: ()",
"2025-02-03 04:11:52 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started: ()",
"2025-02-03 04:12:22 +00 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Failed: ()"
],
"Warnings": [],
"Errors": [
"2025-02-03 04:12:23 +00 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: A task was canceled.\nTaskCanceledException: A task was canceled."
],
"BackendStatistics": {
"RemoteCalls": 5,
"BytesUploaded": 0,
"BytesDownloaded": 0,
"FilesUploaded": 0,
"FilesDownloaded": 0,
"FilesDeleted": 0,
"FoldersCreated": 0,
"RetryAttempts": 4,
"UnknownFileSize": 0,
"UnknownFileCount": 0,
"KnownFileCount": 0,
"KnownFileSize": 0,
"LastBackupDate": "0001-01-01T00:00:00",
"BackupListCount": 0,
"TotalQuotaSpace": 0,
"FreeQuotaSpace": 0,
"AssignedQuotaSpace": 0,
"ReportedQuotaError": false,
"ReportedQuotaWarning": false,
"MainOperation": "Backup",
"ParsedResult": "Success",
"Interrupted": false,
"Version": "2.1.0.3 (2.1.0.3_beta_2025-01-22)",
"EndTime": "0001-01-01T00:00:00",
"BeginTime": "2025-02-03T04:07:09.158841Z",
"Duration": "00:00:00",
"MessagesActualLength": 0,
"WarningsActualLength": 0,
"ErrorsActualLength": 0,
"Messages": null,
"Warnings": null,
"Errors": null
}
}
Please note that I never cancelled anything manually and the exact error messages (files) and the number of error entries (how many times) varies from run to run.
There are 2 things to mention:
-
I can see that the stats of the Docker container running Duplicati on my NAS show a very high memory usage, currently 5-6GB, see below. Every new job increases the memory usage - the memory gets freed occasionally but it never goes down to the starting value of about 150MB after some big jobs were run unless I restart the container. CPU usage is also high at some points but this seems to make sense as these are the moments Duplicati really has to do something.
-
The other thing we observe is that the CPU usage of my friend’s NAS goes to 100% during the moments when these errors occurr. I assume this has to do with the listing of files but I wonder why this would cause such a high CPU usage…?
I am pretty much stuck on this. As it is related to large, old backup jobs it is difficult to reproduce, say by using a different destination. It could be related to my friend’s NAS - but then why don’t I have the same problem in the reverse configuration? It could be that the remote files are corrupted - but how could this happen for all jobs out of the blue and wouldn’t this cause different error messages?
I tend to think that it has to be something on my side as the behavior varies when I restart the container - are there any options to reduce the memory footprint? I saw posts on “disable-piped-streaming” but I don’t have that option (anymore?). There is a “disable-filepath-cache” option which is marked as deprecated. I didn’t see any other option that seemed to have an impact on the memory usage… but I found this post: Duplicati doesn't release memory after completing a backup · Issue #5015 · duplicati/duplicati · GitHub
All just wild guesses - any ideas, suggestions please?