Number-of-retries option clarification

Support
1

Hi,

I’ve been having issues with backup failure and duplicati crashing on me entirely, and I think I’m having backend issues with my backend storage via webDAV. I’m not sure what the underlying cause of this is, but from having run the backups in verbose mode, I’m seeing all sorts of assorted errors with the files - but that’s not why I’m posting here.

What I’ve come to realize is that “number-of-retries” appears to be a “global” value, rather than a per-file value after having adjusted the number-of-retries from 5 to 20. When looking at the logs, I then saw retries for several files, but the retries number only ever got higher even though after a single retry, the next one usually was successful. So I went to the documentation on the option:

--number-of-retries = 5

If an upload or download fails, Duplicati will retry a number of times before failing. Use this to handle unstable network connections better.

I’d like to suggest that the documentation be more clear that this is per job and not per file so if someone else runs into this, it will hopefully be more obvious.

Oh, I almost forgot - it would also be useful that when the backups do fail due to retries, that this be the reason given rather than something like:

Failed: Value cannot be null.
Parameter name: path
Details: System.ArgumentNullException: Value cannot be null.

which I believe was the result of the last operation which was retried rather than having hit the “number-of-retries” maximum. Both are important, but if I set number-of-retries to 20 and get 20 different errors on uploading or downloading, how important is the last one over the other 19?

2

I think it’s per file not per job. Please look at a log (live or file) at retry level for lines such as:

2020-11-11 12:40:47 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8c8dde38cd634404ba8274f1691bc21b.dblock.zip.aes (4.92 MB)
2020-11-11 12:40:48 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5585c6cfe074412fbe16cbba211fd440.dblock.zip.aes (4.94 MB)
2020-11-11 12:40:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b15f03b22737148819a4868d2acf7bb8a.dblock.zip.aes (4.97 MB)
2020-11-11 12:40:52 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bde9dff00aefd46e581f56bc05cb2310a.dblock.zip.aes (4.93 MB)
2020-11-11 12:40:56 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bde0e10b15db24cf0a6aa847d0613db06.dblock.zip.aes (4.92 MB)
2020-11-11 12:40:56 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bce57ea346f1d42a9a277495477dba327.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b4e9c7e66db0d45638a60c3fee0e4d90c.dblock.zip.aes (4.96 MB)
2020-11-11 12:41:01 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b564c7030f3a04b5987dbddf577088623.dblock.zip.aes (4.96 MB)
2020-11-11 12:41:02 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bde0e10b15db24cf0a6aa847d0613db06.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bde0e10b15db24cf0a6aa847d0613db06.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:02 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bce57ea346f1d42a9a277495477dba327.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bce57ea346f1d42a9a277495477dba327.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:03 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b15f03b22737148819a4868d2acf7bb8a.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:03 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b15f03b22737148819a4868d2acf7bb8a.dblock.zip.aes (4.97 MB)
2020-11-11 12:41:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b8a6bce9e117d4e2d8a794f770a166e4c.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:06 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b1ca73db35723482986ed296fd8098eb6.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:09 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ba7e7f27a7a05453b9b8db07a41243c54.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:10 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b36bf1b3b77a84780a1b8fa563f0d6960.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:11 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b36bf1b3b77a84780a1b8fa563f0d6960.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:11 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b36bf1b3b77a84780a1b8fa563f0d6960.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bde0e10b15db24cf0a6aa847d0613db06.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bde0e10b15db24cf0a6aa847d0613db06.dblock.zip.aes" to "duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes"
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bce57ea346f1d42a9a277495477dba327.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bce57ea346f1d42a9a277495477dba327.dblock.zip.aes" to "duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes"
2020-11-11 12:41:12 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b15f03b22737148819a4868d2acf7bb8a.dblock.zip.aes (4.97 MB)
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bbf34731966054dde8bd88690cf4bb758.dblock.zip.aes (4.97 MB)
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b15f03b22737148819a4868d2acf7bb8a.dblock.zip.aes" to "duplicati-bbf34731966054dde8bd88690cf4bb758.dblock.zip.aes"
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bbf34731966054dde8bd88690cf4bb758.dblock.zip.aes (4.97 MB)
2020-11-11 12:41:13 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes attempt 2 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:13 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes attempt 2 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:13 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-b1ca73db35723482986ed296fd8098eb6.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:13 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-b1ca73db35723482986ed296fd8098eb6.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:14 -05 - [Retry-Duplicati.Library.Main.Operation.Backup.BackendUploader-RetryPut]: Operation Put with file duplicati-ba7e7f27a7a05453b9b8db07a41243c54.dblock.zip.aes attempt 1 of 6 failed with message: The remote server returned an error: (403) Forbidden.
2020-11-11 12:41:14 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ba7e7f27a7a05453b9b8db07a41243c54.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:14 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bcb80aa297aaa47cc94df1417d05e7b05.dblock.zip.aes (4.85 MB)
2020-11-11 12:41:15 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b5585c6cfe074412fbe16cbba211fd440.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i0e55d8e9bdd34d2e8117ebf277d6e3fe.dindex.zip.aes (3.17 KB)
2020-11-11 12:41:16 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20201111T174000Z.dlist.zip.aes (41.40 KB)
2020-11-11 12:41:18 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i0e55d8e9bdd34d2e8117ebf277d6e3fe.dindex.zip.aes (3.17 KB)
2020-11-11 12:41:21 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b36bf1b3b77a84780a1b8fa563f0d6960.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:21 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bd4354baa1dd943e5aa61d55b00967c14.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:21 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b36bf1b3b77a84780a1b8fa563f0d6960.dblock.zip.aes" to "duplicati-bd4354baa1dd943e5aa61d55b00967c14.dblock.zip.aes"
2020-11-11 12:41:21 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bd4354baa1dd943e5aa61d55b00967c14.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b4e9c7e66db0d45638a60c3fee0e4d90c.dblock.zip.aes (4.96 MB)
2020-11-11 12:41:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-icf58c7f003a7449e8ea2a241e18830e8.dindex.zip.aes (3.11 KB)
2020-11-11 12:41:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bea9fac0ca99f411bbda4f108155f0423.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:23 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-bafacb56a48464ea985c2331f0a8df572.dblock.zip.aes" to "duplicati-bea9fac0ca99f411bbda4f108155f0423.dblock.zip.aes"
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-bff63d2b7c1a54ef496b0ea758cca1778.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b1ca73db35723482986ed296fd8098eb6.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b5aaf0638a399456b9036b6ae1f7d6793.dblock.zip.aes" to "duplicati-bff63d2b7c1a54ef496b0ea758cca1778.dblock.zip.aes"
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-ba7e7f27a7a05453b9b8db07a41243c54.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b76bf2a3d4023478d97c009ac3e698af9.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bea9fac0ca99f411bbda4f108155f0423.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Rename: duplicati-b4aca83fc2ca3404aadb136b7339dec67.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-ba7e7f27a7a05453b9b8db07a41243c54.dblock.zip.aes" to "duplicati-b4aca83fc2ca3404aadb136b7339dec67.dblock.zip.aes"
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.Operation.Backup.BackendUploader-RenameRemoteTargetFile]: Renaming "duplicati-b1ca73db35723482986ed296fd8098eb6.dblock.zip.aes" to "duplicati-b76bf2a3d4023478d97c009ac3e698af9.dblock.zip.aes"
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bff63d2b7c1a54ef496b0ea758cca1778.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b4aca83fc2ca3404aadb136b7339dec67.dblock.zip.aes (4.91 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b76bf2a3d4023478d97c009ac3e698af9.dblock.zip.aes (4.94 MB)
2020-11-11 12:41:24 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-icf58c7f003a7449e8ea2a241e18830e8.dindex.zip.aes (3.11 KB)
2020-11-11 12:41:27 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20201111T174000Z.dlist.zip.aes (41.40 KB)
2020-11-11 12:41:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bde9dff00aefd46e581f56bc05cb2310a.dblock.zip.aes (4.93 MB)
2020-11-11 12:41:54 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i7d4558c4c1214ccc939a9f83a95a6a40.dindex.zip.aes (3.00 KB)
2020-11-11 12:41:55 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8c8dde38cd634404ba8274f1691bc21b.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:55 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i728a0d312b6c4f6ab879a13d4b1f3c68.dindex.zip.aes (4.04 KB)
2020-11-11 12:41:57 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bea9fac0ca99f411bbda4f108155f0423.dblock.zip.aes (4.92 MB)
2020-11-11 12:41:57 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i7845b9d64e534c109ac855cc10a17b49.dindex.zip.aes (3.03 KB)
2020-11-11 12:41:58 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i7d4558c4c1214ccc939a9f83a95a6a40.dindex.zip.aes (3.00 KB)
2020-11-11 12:41:58 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i7845b9d64e534c109ac855cc10a17b49.dindex.zip.aes (3.03 KB)
2020-11-11 12:41:59 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i728a0d312b6c4f6ab879a13d4b1f3c68.dindex.zip.aes (4.04 KB)
2020-11-11 12:42:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bd4354baa1dd943e5aa61d55b00967c14.dblock.zip.aes (4.94 MB)
2020-11-11 12:42:02 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i8d6ae3010633476ab12edf64adaf5e4d.dindex.zip.aes (3.00 KB)
2020-11-11 12:42:03 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b8a6bce9e117d4e2d8a794f770a166e4c.dblock.zip.aes (4.91 MB)
2020-11-11 12:42:04 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ia5836bd5e782470b8331543d74635bc7.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:04 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i8d6ae3010633476ab12edf64adaf5e4d.dindex.zip.aes (3.00 KB)
2020-11-11 12:42:05 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ia5836bd5e782470b8331543d74635bc7.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:21 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bcb80aa297aaa47cc94df1417d05e7b05.dblock.zip.aes (4.85 MB)
2020-11-11 12:42:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-iffba0f849f4d44b88ab80ef37b3ab0d8.dindex.zip.aes (16.75 KB)
2020-11-11 12:42:23 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-iffba0f849f4d44b88ab80ef37b3ab0d8.dindex.zip.aes (16.75 KB)
2020-11-11 12:42:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b564c7030f3a04b5987dbddf577088623.dblock.zip.aes (4.96 MB)
2020-11-11 12:42:28 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i534c3dd4e3c843cb9228e84bcc630e54.dindex.zip.aes (16.78 KB)
2020-11-11 12:42:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bbf34731966054dde8bd88690cf4bb758.dblock.zip.aes (4.97 MB)
2020-11-11 12:42:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i73de5b51c657473c8853c8496512aaf5.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:29 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i534c3dd4e3c843cb9228e84bcc630e54.dindex.zip.aes (16.78 KB)
2020-11-11 12:42:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bff63d2b7c1a54ef496b0ea758cca1778.dblock.zip.aes (4.92 MB)
2020-11-11 12:42:30 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ia9dad1cd81554004a2d175129666eae7.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:31 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i73de5b51c657473c8853c8496512aaf5.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:32 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ia9dad1cd81554004a2d175129666eae7.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:35 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b4aca83fc2ca3404aadb136b7339dec67.dblock.zip.aes (4.91 MB)
2020-11-11 12:42:36 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ia8bcef2d6c064aba8af9cafd802327f4.dindex.zip.aes (3.00 KB)
2020-11-11 12:42:36 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b76bf2a3d4023478d97c009ac3e698af9.dblock.zip.aes (4.94 MB)
2020-11-11 12:42:37 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i8b37496794b942afa84ffe535286cc27.dindex.zip.aes (3.03 KB)
2020-11-11 12:42:37 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ia8bcef2d6c064aba8af9cafd802327f4.dindex.zip.aes (3.00 KB)
2020-11-11 12:42:38 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i8b37496794b942afa84ffe535286cc27.dindex.zip.aes (3.03 KB)
2020-11-11 12:43:14 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-verification.json (181.62 KB)
2020-11-11 12:43:22 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-verification.json (181.62 KB)

The above were extracted from a log-file using the regular expression:

2020-11-11 12:4.*(Backend event: Put|attempt|Renaming|Rename)

is not what I got. As you can see, it goes back down to 1 the next time it mentions. Got logs?

I can’t speak for webdav (don’t have it – got logs?) but here’s a fatal failure from Google Drive. I have my retries set low as a test, so I can see what happens when retries run out. What was emailed to me was:

C: Failed: The remote server returned an error: (500) Internal Server Error.
C: Details: System.Net.WebException: The remote server returned an error: (500) Internal Server Error.
C:    at Duplicati.Library.Main.BackendManager.List()
C:    at Duplicati.Library.Main.Operation.FilelistProcessor.RemoteListAnalysis(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, IEnumerable`1 protectedFiles)
C:    at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, IEnumerable`1 protectedFiles)
C:    at Duplicati.Library.Main.Operation.BackupHandler.PostBackupVerification(String currentFilelistVolume)
C:    at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()
C: --- End of stack trace from previous location where exception was thrown ---
C:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
C:    at CoCoL.ChannelExtensions.WaitForTaskOrThrow(Task task)
C:    at Duplicati.Library.Main.Controller.<>c__DisplayClass14_0.<Backup>b__0(BackupResults result)
C:    at Duplicati.Library.Main.Controller.RunAction[T](T result, String[]& paths, IFilter& filter, Action`1 method)
C: 
C: Log data:
C: 2020-10-07 10:42:33 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
C: System.Net.WebException: The remote server returned an error: (500) Internal Server Error.
C:    at Duplicati.Library.Main.BackendManager.List()
C:    at Duplicati.Library.Main.Operation.FilelistProcessor.RemoteListAnalysis(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, IEnumerable`1 protectedFiles)
C:    at Duplicati.Library.Main.Operation.FilelistProcessor.VerifyRemoteList(BackendManager backend, Options options, LocalDatabase database, IBackendWriter log, IEnumerable`1 protectedFiles)
C:    at Duplicati.Library.Main.Operation.BackupHandler.PostBackupVerification(String currentFilelistVolume)
C:    at Duplicati.Library.Main.Operation.BackupHandler.<RunAsync>d__20.MoveNext()

so it’s kind of hard to read, and what’s also ugly is that on a fatal error you don’t get a normal job log, but Home → About → Show log will usually get something that you can look at, if you think to go look there.
I’m not sure where you’re looking, but please check there to see if you see a more meaningful reason…

It’s the combination of these things. You get a certain number of tries. If you run out, you might hear about the last failure. If you log at Retry level rather than Information level, you can hear about earlier failures. Regardless, the thinking is probably that you’re looking for some information on what had failed, and not a non-informative report that it failed too often. Please look at your server logs for useful info on the failures.

You mention verbose mode run, and if that’s the log level then that would get even more than retry level, however if you want to focus on retries, then retry level (more details than information) is a good one.
Then you can filter, either by hand based on my example, or if you have regular expressions, mimic mine.

3

Something else might be wrong with my system. After a few days of running normal backups, a small backup of nightly log data is now crashing mono/duplicati entirely. I’ve restarted it 4 times this morning - same results each time:

[root@voyageur centos]# date;mono /usr/share/Duplicati/updates/2.0.5.1/Duplicati.Server.exe;date
Tue Dec  8 07:27:54 CST 2020
[ERROR] FATAL UNHANDLED EXCEPTION: System.ArgumentNullException: Value cannot be null.
Parameter name: path
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share, System.Int32 bufferSize, System.Boolean anonymous, System.IO.FileOptions options) [0x00014] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at System.IO.FileStream..ctor (System.String path, System.IO.FileMode mode, System.IO.FileAccess access, System.IO.FileShare share) [0x00000] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at (wrapper remoting-invoke-with-check) System.IO.FileStream..ctor(string,System.IO.FileMode,System.IO.FileAccess,System.IO.FileShare)
  at Duplicati.Library.Main.Volumes.VolumeReaderBase.LoadCompressor (System.String compressor, System.String file, Duplicati.Library.Main.Options options, System.IO.Stream& stream) [0x00000] in <8f1de655bd1240739a78684d845cecc8>:0
  at Duplicati.Library.Main.Volumes.VolumeReaderBase..ctor (System.String compressor, System.String file, Duplicati.Library.Main.Options options) [0x00007] in <8f1de655bd1240739a78684d845cecc8>:0
  at Duplicati.Library.Main.Volumes.IndexVolumeReader..ctor (System.String compressor, System.String file, Duplicati.Library.Main.Options options, System.Int64 hashsize) [0x00000] in <8f1de655bd1240739a78684d845cecc8>:0
  at Duplicati.Library.Main.BackendManager.RenameFileAfterError (Duplicati.Library.Main.BackendManager+FileEntryItem item) [0x0018a] in <8f1de655bd1240739a78684d845cecc8>:0
  at Duplicati.Library.Main.BackendManager.ThreadRun () [0x002de] in <8f1de655bd1240739a78684d845cecc8>:0
  at System.Threading.ThreadHelper.ThreadStart_Context (System.Object state) [0x00014] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00071] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state) [0x0002b] in <6de68d9ed0b943838b4ddc538c95c31e>:0
  at System.Threading.ThreadHelper.ThreadStart () [0x00008] in <6de68d9ed0b943838b4ddc538c95c31e>:0
Tue Dec  8 07:33:54 CST 2020

Each time I restart Duplicati, it continues the same backup operation where it left off - “Deleting unwanted files”. How do I break the cycle? I’ll confess that I haven’t run backups from the command line much, always use the web interface.

4

Good question. Is this a scheduled job? These run automatically at start if they’re already past their time. Does GUI stay up long enough to do anything, such as hit the pause button or put a pause into Settings?

Actually, I guess you must have a GUI if you can see it say “Deleting unwanted files”, so you “should” be able to get it to pause, and the pause should (I think) include a pause on running late jobs at server start.

You might have to take another crash, but the goal would be to have a GUI (and no fast crash) next start.

On Linux systems, one good thing to check is that mono --version is at least 5 (5.10 coming up soon).
CentOS instructions, if needed. Largest but most complete package to install would be mono-complete.

What would be helpful would be a better view of how it got to that ending (which Google search can’t find having been reported before), and that might require some job-level logging after the crash cycle stops…

5

it’s resuming a scheduled job - it looks like it’s detecting that it didn’t complete and starting it again where it left off. I’m running it again but this time I added on logging options:

–log-file=/var/log/duplicati.log --log-level=profiling

As for mono version - 6.12.0.90:

[root@voyageur log]# mono --version
Mono JIT compiler version 6.12.0.90 (tarball Fri Sep  4 13:46:01 UTC 2020)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. www.mono-project.com
        TLS:           __thread
        SIGSEGV:       altstack
        Notifications: epoll
        Architecture:  amd64
        Disabled:      none
        Misc:          softdebug 
        Interpreter:   yes
        LLVM:          yes(610)
        Suspend:       hybrid
        GC:            sgen (concurrent by default)
[root@voyageur log]#

I don’t have mono-complete installed, but I have these:

[root@voyageur log]# yum list | grep ^mono | egrep @
mono-core.x86_64                         6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-data.x86_64                         6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-data-oracle.x86_64                  6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-data-sqlite.x86_64                  6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-devel.x86_64                        6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-extras.x86_64                       6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-mvc.x86_64                          6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-wcf.x86_64                          6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-web.x86_64                          6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-winforms.x86_64                     6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable
mono-winfxcore.x86_64                    6.12.0.90-0.xamarin.3.epel7    @mono-centos7-stable

Ok, this is related to the number-of-retries. You might want the rest of the logfile for context, but here are the retries incrementing upon Put operations with what appear to be different files:

[root@voyageur log]# egrep Retry duplicati.log  | tail
2020-12-08 12:05:08 -06 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-i09f87a0e92ad45a382324997961e2da3.dindex.zip.aes attempt 42 of 200 failed with message: Value cannot be null.
2020-12-08 12:05:08 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-i09f87a0e92ad45a382324997961e2da3.dindex.zip.aes ()
2020-12-08 12:05:18 -06 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-ie640c61b13c1467bbdeb317d0f8e4ff4.dindex.zip.aes attempt 43 of 200 failed with message: Value cannot be null.
2020-12-08 12:05:18 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ie640c61b13c1467bbdeb317d0f8e4ff4.dindex.zip.aes ()
2020-12-08 12:05:28 -06 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-ie54b80f17dd5437e9bf471246360b9be.dindex.zip.aes attempt 44 of 200 failed with message: Value cannot be null.
2020-12-08 12:05:28 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ie54b80f17dd5437e9bf471246360b9be.dindex.zip.aes ()
2020-12-08 12:05:38 -06 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-ia744f5a29753479a86eefa537b373c3b.dindex.zip.aes attempt 45 of 200 failed with message: Value cannot be null.
2020-12-08 12:05:38 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-ia744f5a29753479a86eefa537b373c3b.dindex.zip.aes ()
2020-12-08 12:05:49 -06 - [Retry-Duplicati.Library.Main.BackendManager-RetryPut]: Operation Put with file duplicati-if1b0a5dc90e64e8893143e40ae7f91f7.dindex.zip.aes attempt 46 of 200 failed with message: Value cannot be null.
2020-12-08 12:05:49 -06 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Retrying: duplicati-if1b0a5dc90e64e8893143e40ae7f91f7.dindex.zip.aes ()
[root@voyageur log]#
6

When I setup the profiling and log collection, the backup completed. However today, it crashed again and when I restarted it I am again seeing this pattern repeat itself - logs are in reverse order as they came from the GUI live view:

* Dec 10, 2020 12:20 PM: Renaming "duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes" to "duplicati-i472bff55f1784038aa65593b41794611.dindex.zip.aes"

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-i472bff55f1784038aa65593b41794611.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Retrying: duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Operation Put with file duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes attempt 70 of 200 failed with message: Value cannot be null. Parameter name: path

* Dec 10, 2020 12:20 PM: RemoteOperationPut took 0:00:00:00.000

* Dec 10, 2020 12:20 PM: Starting - RemoteOperationPut

* Dec 10, 2020 12:20 PM: Renaming "duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes" to "duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes"

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-if77e01cc8fd8411890aec995e4ee3c08.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Retrying: duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Operation Put with file duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes attempt 69 of 200 failed with message: Value cannot be null. Parameter name: path

* Dec 10, 2020 12:20 PM: RemoteOperationPut took 0:00:00:00.000

* Dec 10, 2020 12:20 PM: Starting - RemoteOperationPut

* Dec 10, 2020 12:20 PM: Renaming "duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes" to "duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes"

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-i829899b68cad458697f36ecd7dea87a0.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Retrying: duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Operation Put with file duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes attempt 68 of 200 failed with message: Value cannot be null. Parameter name: path

* Dec 10, 2020 12:20 PM: RemoteOperationPut took 0:00:00:00.000

* Dec 10, 2020 12:20 PM: Starting - RemoteOperationPut

* Dec 10, 2020 12:20 PM: Renaming "duplicati-i5b65cfdf06484bf3ab77dae03ab5ccc9.dindex.zip.aes" to "duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes"

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-iaa601ccd8e004378ad331c6b022d79f4.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Rename: duplicati-i5b65cfdf06484bf3ab77dae03ab5ccc9.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Backend event: Put - Retrying: duplicati-i5b65cfdf06484bf3ab77dae03ab5ccc9.dindex.zip.aes ()

* Dec 10, 2020 12:20 PM: Operation Put with file duplicati-i5b65cfdf06484bf3ab77dae03ab5ccc9.dindex.zip.aes attempt 67 of 200 failed with message: Value cannot be null. Parameter name: path
7

File rename for the retry is normal error handling. “Value cannot be null. Parameter name: path” is not.
This likely needs deep code understanding, so might need a GitHub Issue unless an expert comes by.

The issue with an issue is that ideally it wants steps to reproduce the problem from scratch. Can you?
Ideally an issue would also be reproducible on any destination. If it needs only your WebDAV, it’s tough.
Still, I think there are deveopers who know the code better than I do, who might be able to shed light…

My guess at the higher levels of what’s going on is based on your earlier stack trace, which might be

which would take it to VolumeReaderBase then a file open which might choke on a (somehow) null path.
Assuming this is a path that was passed down, this might be item.Indexfile.Item2.LocalFilename

item is a FileEntryItem here and Indexfile is here as Tuple<IndexVolumeWriter, FileEntryItem>
LocalFilename is here and talks about a LocalTempFile. Might temp space have gotten filled, I wonder?
tempdir describes how to move it around. If it’s not that, then I probably can’t trace this deeper into code.

Inside that Delete is a potential compact. You’re now trying uploads (Put), so setting no-auto-compact might put an end to at least what you posted (a larger log view would show if Compact actually began).
This isn’t a long-term plan because wasted space will build up, but you could try it. Check tmp as well.

8

If an IndexVolumeWriter is involved, it’s possible that this null reference exception was fixed here:

9

The timing of the original fault intro on Oct 19, 2019 looks like it would have left 2.0.5.1 vulnerable to issue.
Also the issue description (by me) talks about a failed put during compact as here, however the difference is that that was a dblock and this is a dindex, and crash stack is different. It might be worth a try. Thanks!

The fix was Mar 21, and made 2.0.5.104. 2.0.5.106 was the job DB jump to version 11, so I think a test on Canary from Beta would be reversible if a leading-edge release like Canary (new fixes, plus maybe bugs) isn’t desired. Getting there could get awkward. The automatic updater would want to do Canary 2.0.5.111, which would mean a database version upgrade which would mean extra effort for a downgrade to 2.0.5.1.

Maybe the thing to do for a test is to install from the 2.0.5.104 builds area then refuse any newer offerings.
@stahr would you like to see if it’s fixed in a newer release that’s not yet in any Beta so far? Canary has been stable lately as far as I know (and I run it), but it’s always possible that some future Canary won’t be.

If there are any backups that aren’t caught in this loop, you could also look at Complete log in the job log.
RetryAttempts in BackendStatistics being high would mean something’s flaky with WebDAV transfer.

10

Well, good news and bad news - the backups are all working at the moment. There are two jobs which had been having issues, both using the same backend. One is done nightly and just copies log files. The other runs only on weekend and copies all 150G of maildir files. Both were routinely failing but both have been working now. The only thing of note is that my system was rebooted 5 days ago - so maybe it was something in memory or kernel related. I will unset the retries and see if I can get the log file backup to fail.

11

That means it’s a good time to sample the job logs’ Complete log → BackendStatistics → RetryAttempts, which might show whether you’re getting an excessive (but not fatally so) number. Earlier, it was really bad.