Release: 2.1.0.112 (Canary) 2025-03-26

Releases
1

2.1.0.112_canary_2025-03-26

This release is a canary release intended to be used for testing.

Major changes in this version

  • Updated backends
    The major change in this version is the addition of timeouts to every backend.
    This has the potential to affect each backend individually.

  • Improved validation
    Further increased the checks made to validate that the database is consistent, and added new features to the repair operation to assist in recovering.
    Certain problems are now checked before and after a backup, in an attempt to better close in on the conditions that create these situations.

  • Updates to ngclient
    Updates to reconnect logic and locale support.

Potentially breaking changes (from 2.1.0.109)

  • Location of data folder has changed in some cases, refer to previous release for details
  • Permissions are now applied to the data folder, refer to previous release for details
  • New user interface, ngclient is the default; there is a button to switch between the two

Detailed list of changes:

  • Added retries for sending HTTP-based reports
  • Added warning icon back to TrayIcon
  • Fixed a check that prevented repairs in timezones that are have a negative UTC offset
  • Rewrote a number of SQL queries to avoid localization of SQL strings
  • Added guards against faulty startup delays
  • Updated all backends to use same parsing logic for authentication options
  • Updated all backends to support timeouts
  • Fixed a bug where databases would be created with strict permissions, even if opting out
  • Updated SQLite loading to always set custom pragmas
  • Updated SQLite loading to support custom SQLITE_TMPDIR environment variable
  • Removed unwanted data in report JSON output
  • Added support for deleting empty index files on repair
  • Improved handling of stop “errors”
  • Updated box.com backend to use HttpClient
  • Added option to inject custom parameters into reports
  • Improved error message on manifest version mismatches
  • Removed a warning when attempting to pick a restore date with a negative prefix
  • Support for large form-encoded HTTP reports
  • Fixed an issue where the URL parser would return different results for similar inputs (for the file:// input)
  • Handling backspace on console password input
  • Added guard against fileset errors in the database
  • Added support for rebuilding filesets from remote data on repair
  • TrayIcon can now start in a disconnected state, and keep probing for a connection
  • Added current update channel to reports
  • Added automatic zip64 usage for large bugreports
  • Added support for showing the crashlog in the UI
  • Fixed an issue with some dates causing problems in the timezone aware calculations
  • Added support for sorting the list of backups in the UI
  • Fixed an issue with restoring timestamps and metadata on folders
2

Is that it? Detailed list of changes has none. Job Submit still fails on bad retention.

EDIT 1:

I took screenshot as soon as final screen arrived because it seemed a bit strange.

image
image513Ă—577 26.8 KB

If there’s a path to getting Submit to work, the formula would help testing progress.
Not sure if there’s anything changed though.

3

Tried an Import from file in ngclient of an existing job. On Destination screen:

image

So “Path in the bucket” is showing percent-encoded spaces instead of spaces.

The forward slash at the start also shouldn’t be there.

On Source Data screen, none of my sources are in the tree view, and clicking various things around there doesn’t seem to be willing to show or allow adding.

On Options screen, I do see two of my many options, but all the rest are gone.

EDIT 1:

Decided to try a Submit anyway, and to my surprise it worked and this job and previous fail showed up on the screen. Switch to ngax to see if result looks OK:

image
image525Ă—288 10.1 KB

Bad leading slash went away, bad percent encoding stays.
Application ID and Application Key are missing on display.
Looking in DB, they’re missing too, and URL is percent-encoded without extra /.

Source Data and Options screens look about right, at least there’s loads of stuff.

EDIT 2:

I’m not going to run the import (I did successfully run the new job after it showed).

In ngclient, trying to delete the import seemed to do nothing, but a screen refresh (because I’m having screen update problems even in ngax) showed it got deleted.

Back to ngax and see if I can get a good import and maybe actually try running it.

Looks plausible and runs too. So early ngax test looks good, but what of ngclient?

4

Still unable to use the Linux versions as I reported before: Release: 2.1.0.111 (Canary) 2025-03-15 - #9 by Taomyn although this time it was RPi-OS for ARM64.

root@ziff:/home/pi# duplicati-server-util change-password
Connecting to http://127.0.0.1:8200/...
Failed to obtain a signin token: Could not load file or assembly 'Microsoft.IdentityModel.Abstractions, Version=7.5.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35'. The system cannot find the file specified.

Enter server password:
root@ziff:/home/pi#

Nothing I do allows me to log in with the original server password or to change it, but at least the installation isn’t messing with /etc/default/duplicati so my service settings stay put.

As for Windows, I updated the server I was having S3 issues with, no password problems here, and I started by running a repair on the local backup job first - this one has been fine so far. This is what was reported:

 {
  "MainOperation": "Repair",
  "RecreateDatabaseResults": null,
  "ParsedResult": "Warning",
  "Interrupted": false,
  "Version": "2.1.0.112 (2.1.0.112_canary_2025-03-26)",
  "EndTime": "2025-03-27T07:30:53.2239133Z",
  "BeginTime": "2025-03-27T07:30:18.3719415Z",
  "Duration": "00:00:34.8519718",
  "MessagesActualLength": 4,
  "WarningsActualLength": 1,
  "ErrorsActualLength": 0,
  "Messages": [
    "2025-03-27 08:30:19 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started",
    "2025-03-27 08:30:50 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2025-03-27 08:30:53 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (2.131 KiB)",
    "2025-03-27 08:30:53 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: QuotaInfo - Started:  ()"
  ],
  "Warnings": [
    "2025-03-27 08:30:53 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it"
  ],
  "Errors": [],
  "BackendStatistics": {
    "RemoteCalls": 2,
    "BytesUploaded": 0,
    "BytesDownloaded": 0,
    "FilesUploaded": 0,
    "FilesDownloaded": 0,
    "FilesDeleted": 0,
    "FoldersCreated": 0,
    "RetryAttempts": 0,
    "UnknownFileSize": 0,
    "UnknownFileCount": 0,
    "KnownFileCount": 2182,
    "KnownFileSize": 75906906142,
    "KnownFilesets": 27,
    "LastBackupDate": "2025-03-17T12:56:34+01:00",
    "BackupListCount": 27,
    "TotalQuotaSpace": 13194072424448,
    "FreeQuotaSpace": 3769860030464,
    "AssignedQuotaSpace": -1,
    "ReportedQuotaError": false,
    "ReportedQuotaWarning": false,
    "MainOperation": "Repair",
    "ParsedResult": "Success",
    "Interrupted": false,
    "Version": "2.1.0.112 (2.1.0.112_canary_2025-03-26)",
    "EndTime": "0001-01-01T00:00:00",
    "BeginTime": "2025-03-27T07:30:18.3721948Z",
    "Duration": "00:00:00",
    "MessagesActualLength": 0,
    "WarningsActualLength": 0,
    "ErrorsActualLength": 0,
    "Messages": null,
    "Warnings": null,
    "Errors": null
  }
}

No idea what this means or if I should be concerned - I’ll hold on doing anything more for now.

5

Assuming you refer to the Warning, that got me to look above at release note again, because I was wondering why my backup didn’t delete empty index files, but I read:

and had forgotten the last two words. Running Repair, the expected deletes worked:

Mar 27, 2025 7:42 AM: The operation Repair has completed
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-if679a4ad43af45d7bfb86911f252a50b.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-if679a4ad43af45d7bfb86911f252a50b.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-if0a11ed1fba04f58a22e55e800afd521.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-if0a11ed1fba04f58a22e55e800afd521.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-ie7a84e51d32947a393669ae22c5ba364.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-ie7a84e51d32947a393669ae22c5ba364.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-i75576376d94f400797a6f15ae33f0a9a.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-i75576376d94f400797a6f15ae33f0a9a.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-i45874e960e534e6ab9a8a4f5fbf4ae8c.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-i45874e960e534e6ab9a8a4f5fbf4ae8c.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Backend event: Delete - Completed: duplicati-i293d5c5b08eb4eef87dfd37e0dd910a7.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: Delete - Started: duplicati-i293d5c5b08eb4eef87dfd37e0dd910a7.dindex.zip.aes (541 bytes)
Mar 27, 2025 7:42 AM: Deleting empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume
Mar 27, 2025 7:42 AM: Backend event: List - Completed: (536 bytes)
Mar 27, 2025 7:42 AM: Backend event: List - Started: ()
Mar 27, 2025 7:42 AM: The operation Repair has started

My index files were extremely empty, with basically no backup information inside:

image

"2025-03-27 08:30:53 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it"

so in both the intent looks to be to print a dindex file name. Mine did, yours has something that isn’t even a dindex file name, so maybe some identifier goofed.

6

Second run of the backup that worked once failed, seemingly on a 60 second timeout.
This version has a default 30 second read-write-timeout (compared to 10m in 2.1.0.5), but maybe it’s still considered good due to other changes? Regardless, I’m at default.

What I’m not at default on is my number-of-retries=0 in order to invite some problems.

Summary of profiling log by showing lines containing Backend:

2025-03-27 10:15:35 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationList]: Starting - RemoteOperationList
2025-03-27 10:15:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2025-03-27 10:15:37 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (530 bytes)
2025-03-27 10:15:37 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationList]: RemoteOperationList took 0:00:00:01.865
2025-03-27 10:15:37 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationQuotaInfo]: Starting - RemoteOperationQuotaInfo
2025-03-27 10:15:37 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationQuotaInfo]: RemoteOperationQuotaInfo took 0:00:00:00.000
2025-03-27 10:15:37 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationWaitForEmpty]: Starting - RemoteOperationWaitForEmpty
2025-03-27 10:15:37 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationWaitForEmpty]: RemoteOperationWaitForEmpty took 0:00:00:00.000
2025-03-27 10:19:33 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 10:19:36 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 10:19:45 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b13e8a7dd6fa9480bbb2e526b3fb564d1.dblock.zip.aes (50.00 MiB)
2025-03-27 10:19:47 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bcbc16412d6a04d7f992ce495fbf79854.dblock.zip.aes (49.96 MiB)
2025-03-27 10:19:59 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 49.96 MiB in 00:00:12.2063091, 4.09 MiB/s
2025-03-27 10:19:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bcbc16412d6a04d7f992ce495fbf79854.dblock.zip.aes (49.96 MiB)
2025-03-27 10:19:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ifd44d9a54cff452fb25cfa9cb633b69f.dindex.zip.aes (22.68 KiB)
2025-03-27 10:19:59 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 22.68 KiB in 00:00:00.1120708, 202.41 KiB/s
2025-03-27 10:19:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ifd44d9a54cff452fb25cfa9cb633b69f.dindex.zip.aes (22.68 KiB)
2025-03-27 10:19:59 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:26.250
2025-03-27 10:20:05 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 10:20:06 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bece0e7d87b8044d68a5566888024ab3e.dblock.zip.aes (10.67 MiB)
2025-03-27 10:20:07 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 10.67 MiB in 00:00:01.8287084, 5.84 MiB/s
2025-03-27 10:20:07 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bece0e7d87b8044d68a5566888024ab3e.dblock.zip.aes (10.67 MiB)
2025-03-27 10:20:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-id76a89bc466144119f95b88874d233c1.dindex.zip.aes (63.36 KiB)
2025-03-27 10:20:08 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 63.36 KiB in 00:00:00.1126734, 562.30 KiB/s
2025-03-27 10:20:08 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-id76a89bc466144119f95b88874d233c1.dindex.zip.aes (63.36 KiB)
2025-03-27 10:20:08 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:02.761
2025-03-27 10:20:14 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 10:20:14 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20250327T141533Z.dlist.zip.aes (958.18 KiB)
2025-03-27 10:20:15 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 958.18 KiB in 00:00:00.8435476, 1.11 MiB/s
2025-03-27 10:20:15 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20250327T141533Z.dlist.zip.aes (958.18 KiB)
2025-03-27 10:20:15 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.047
2025-03-27 10:20:46 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:01:10.493
2025-03-27 10:20:46 -04 - [Retry-Duplicati.Library.Main.Backend.Handler-RetryPut]: Operation Put with file duplicati-b13e8a7dd6fa9480bbb2e526b3fb564d1.dblock.zip.aes attempt 1 of 0 failed with message: The operation has timed out.
2025-03-27 10:20:47 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Failed: duplicati-b13e8a7dd6fa9480bbb2e526b3fb564d1.dblock.zip.aes ()
2025-03-27 10:20:47 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerHandlerFailure]: Error in handler: The operation has timed out.
2025-03-27 10:20:47 -04 - [Warning-Duplicati.Library.Main.Backend.DatabaseCollector-FlushingMessagesToLog]: Update: duplicati-20250327T141533Z.dlist.zip.aes State: Uploading Size: 981181 Hash: ivaEIdbYmYnSVLEB3P3/H2WQXTQmFWK9OgWdymAPLWo=

Job log:

 Warnings 2 
2025-03-27 10:20:47 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerHandlerFailure]: Error in handler: The operation has timed out.
TimeoutException: The operation has timed out.
2025-03-27 10:20:47 -04 - [Warning-Duplicati.Library.Main.Backend.DatabaseCollector-FlushingMessagesToLog]: Update: duplicati-20250327T141533Z.dlist.zip.aes State: Uploading Size: 981181 Hash: ivaEIdbYmYnSVLEB3P3/H2WQXTQmFWK9OgWdymAPLWo=
Operation: put File: duplicati-20250327T141533Z.dlist.zip.aes Result: {"Size":981181,"Hash":"ivaEIdbYmYnSVLEB3P3/H2WQXTQmFWK9OgWdymAPLWo="}
Update: duplicati-20250327T141533Z.dlist.zip.aes State: Uploaded Size: 981181 Hash: ivaEIdbYmYnSVLEB3P3/H2WQXTQmFWK9OgWdymAPLWo=
 Errors 2 
2025-03-27 10:20:47 -04 - [Error-Duplicati.Library.Main.Operation.BackupHandler-FatalError]: Fatal error
TimeoutException: The operation has timed out.
2025-03-27 10:20:47 -04 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: The operation has timed out.
TimeoutException: The operation has timed out.

Backblaze web UI for the time of the backup has:

duplicati-20250327T141533Z.dlist.zip.aes (Warning but made it)
duplicati-b13e8a7dd6fa9480bbb2e526b3fb564d1.dblock.zip.aes (timed out but made it)
duplicati-bcbc16412d6a04d7f992ce495fbf79854.dblock.zip.aes
duplicati-bece0e7d87b8044d68a5566888024ab3e.dblock.zip.aes
duplicati-id76a89bc466144119f95b88874d233c1.dindex.zip.aes
duplicati-ifd44d9a54cff452fb25cfa9cb633b69f.dindex.zip.aes

RemoteOperation table has:

put duplicati-b13e8a7dd6fa9480bbb2e526b3fb564d1.dblock.zip.aes
put duplicati-bcbc16412d6a04d7f992ce495fbf79854.dblock.zip.aes
put duplicati-ifd44d9a54cff452fb25cfa9cb633b69f.dindex.zip.aes
put duplicati-bece0e7d87b8044d68a5566888024ab3e.dblock.zip.aes
put duplicati-id76a89bc466144119f95b88874d233c1.dindex.zip.aes

image
image748Ă—256 18.6 KB

OK, now try a second backup and see if it can clean up things and succeed…

EDIT 1:

Still fails on timeout, but in less time. Activity summary from the log file:

2025-03-27 11:27:00 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationList]: Starting - RemoteOperationList
2025-03-27 11:27:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()
2025-03-27 11:27:01 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (536 bytes)
2025-03-27 11:27:01 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationList]: RemoteOperationList took 0:00:00:01.295
2025-03-27 11:27:01 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationQuotaInfo]: Starting - RemoteOperationQuotaInfo
2025-03-27 11:27:01 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationQuotaInfo]: RemoteOperationQuotaInfo took 0:00:00:00.000
2025-03-27 11:27:02 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationWaitForEmpty]: Starting - RemoteOperationWaitForEmpty
2025-03-27 11:27:02 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationWaitForEmpty]: RemoteOperationWaitForEmpty took 0:00:00:00.000
2025-03-27 11:28:09 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:28:09 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:28:09 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20250327T141534Z.dlist.zip.aes (958.18 KiB)
2025-03-27 11:28:09 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-if2316671cd3d42798b1ae7d48186b530.dindex.zip.aes (22.81 KiB)
2025-03-27 11:28:10 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 958.18 KiB in 00:00:01.2938010, 740.60 KiB/s
2025-03-27 11:28:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20250327T141534Z.dlist.zip.aes (958.18 KiB)
2025-03-27 11:28:10 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.799
2025-03-27 11:28:11 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 22.81 KiB in 00:00:01.6136102, 14.13 KiB/s
2025-03-27 11:28:11 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-if2316671cd3d42798b1ae7d48186b530.dindex.zip.aes (22.81 KiB)
2025-03-27 11:28:11 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.649
2025-03-27 11:29:09 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:29:09 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:29:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b5f9bb79bf67d44d993cd7657811dcc79.dblock.zip.aes (50.00 MiB)
2025-03-27 11:29:10 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bef3586058687402a8f556cb38b7213cf.dblock.zip.aes (49.97 MiB)
2025-03-27 11:29:20 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:29:20 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-b65ec1c6e478c4dc3b18422a75fbe0632.dblock.zip.aes (8.43 MiB)
2025-03-27 11:29:25 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 8.43 MiB in 00:00:05.2113622, 1.62 MiB/s
2025-03-27 11:29:25 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-b65ec1c6e478c4dc3b18422a75fbe0632.dblock.zip.aes (8.43 MiB)
2025-03-27 11:29:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-i22b7cff2eb19460a9144cf918e2a62c0.dindex.zip.aes (53.89 KiB)
2025-03-27 11:29:26 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 53.89 KiB in 00:00:00.6330919, 85.12 KiB/s
2025-03-27 11:29:26 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-i22b7cff2eb19460a9144cf918e2a62c0.dindex.zip.aes (53.89 KiB)
2025-03-27 11:29:26 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:06.392
2025-03-27 11:29:33 -04 - [Profiling-Timer.Begin-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: Starting - RemoteOperationPut
2025-03-27 11:29:33 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-20250327T152657Z.dlist.zip.aes (958.22 KiB)
2025-03-27 11:29:34 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 958.22 KiB in 00:00:00.8538193, 1.10 MiB/s
2025-03-27 11:29:34 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-20250327T152657Z.dlist.zip.aes (958.22 KiB)
2025-03-27 11:29:34 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:01.028
2025-03-27 11:29:38 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 49.97 MiB in 00:00:27.4970785, 1.82 MiB/s
2025-03-27 11:29:38 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bef3586058687402a8f556cb38b7213cf.dblock.zip.aes (49.97 MiB)
2025-03-27 11:29:38 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-ied44d06a4ad342908644ce2c3bedc6dd.dindex.zip.aes (22.73 KiB)
2025-03-27 11:29:38 -04 - [Profiling-Duplicati.Library.Main.Backend.PutOperation-UploadSpeed]: Uploaded 22.73 KiB in 00:00:00.1280924, 177.46 KiB/s
2025-03-27 11:29:38 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-ied44d06a4ad342908644ce2c3bedc6dd.dindex.zip.aes (22.73 KiB)
2025-03-27 11:29:38 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:28.921
2025-03-27 11:29:55 -04 - [Profiling-Timer.Finished-Duplicati.Library.Main.Backend.Handler-RemoteOperationPut]: RemoteOperationPut took 0:00:00:45.804
2025-03-27 11:29:55 -04 - [Retry-Duplicati.Library.Main.Backend.Handler-RetryPut]: Operation Put with file duplicati-b5f9bb79bf67d44d993cd7657811dcc79.dblock.zip.aes attempt 1 of 0 failed with message: The operation has timed out.
2025-03-27 11:29:55 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Failed: duplicati-b5f9bb79bf67d44d993cd7657811dcc79.dblock.zip.aes ()
2025-03-27 11:29:59 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerHandlerFailure]: Error in handler: The operation has timed out.
2025-03-27 11:29:59 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerDisposeWhileActive]: Terminating 1 active uploads
2025-03-27 11:29:59 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerDisposeWhileActive]: Terminating 1 active uploads
2025-03-27 11:29:59 -04 - [Warning-Duplicati.Library.Main.Backend.Handler-BackendManagerDisposeError]: upload was active during termination, but completed successfully
2025-03-27 11:29:59 -04 - [Warning-Duplicati.Library.Main.Backend.DatabaseCollector-FlushingMessagesToLog]: Update: duplicati-20250327T152657Z.dlist.zip.aes State: Uploading Size: 981213 Hash: Zc+xSN+gA6I1htJwdpMzG7JG4TK6R+uwMQi1Dd/4nh4=

EDIT 2:

I thought I’d try BackendTester before tweaking read-write-timeout, but it did its own. Is this really a good representation of what an actual backup would use for timeout?

3/27/2025 12:19:21 PM
[12:19:21 616] Starting run no 4
[12:19:22 530] Read Write Timeout set to infinite (because implements ITimeoutExemptBackend)
[12:19:22 531] Generating file 0 (19.00 MiB)
[12:19:22 758] Generating file 1 (37.92 MiB)
[12:19:23 182] Generating file 2 (13.39 MiB)
[12:19:23 333] Generating file 3 (47.08 MiB)
[12:19:23 855] Generating file 4 (10.00 MiB)
[12:19:23 974] Generating file 5 (8.70 MiB)
[12:19:24 110] Generating file 6 (2.50 MiB)
[12:19:24 151] Generating file 7 (28.57 MiB)
[12:19:24 496] Generating file 8 (37.16 MiB)
[12:19:24 993] Generating file 9 (24.78 MiB)
[12:19:25 308] Uploading wrong files ...
[12:19:25 308] Generating file 10 (1.56 KiB)
[12:19:25 319] Uploading file 0, 1.56 KiB ...  done! in 558 ms
[12:19:25 878] Uploading file 0, 1.56 KiB ...  done! in 290 ms
[12:19:26 169] Uploading file 9, 1.56 KiB ...  done! in 247 ms
[12:19:26 418] Uploading files ...
[12:19:26 418] Uploading file 0, 19.00 MiB ...  done! in 7530 ms
[12:19:33 949] Uploading file 1, 37.92 MiB ...  done! in 28094 ms
[12:20:02 043] Uploading file 2, 13.39 MiB ...  done! in 11229 ms
[12:20:13 273] Uploading file 3, 47.08 MiB ... [12:20:44 763] Failed to upload file 3, error message: System.TimeoutException: The operation has timed out.
   at Duplicati.StreamUtil.TimeoutObservingStream.ReadImplAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at System.IO.Stream.<>c.<BeginReadInternal>b__38_0(Object <p0>)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at System.IO.Stream.<CopyToAsync>g__Core|27_0(Stream source, Stream destination, Int32 bufferSize, CancellationToken cancellationToken)
   at System.Net.Http.StreamToStreamCopy.<CopyAsync>g__DisposeSourceAsync|1_0(Task copyTask, Stream source)
   at System.Net.Http.HttpContent.<CopyToAsync>g__WaitAsync|56_0(ValueTask copyTask)
   at System.Net.Http.HttpConnection.SendRequestContentAsync(HttpRequestMessage request, HttpContentWriteStream stream, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnection.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Duplicati.Library.Backend.Backblaze.B2.PutAsync(String remotename, Stream stream, CancellationToken cancelToken)
   at Duplicati.Library.Utility.Utility.Await(Task task)
   at Duplicati.CommandLine.BackendTester.Program.Uploadfile(String localfilename, Int32 i, String remotefilename, IBackend backend, Boolean disableStreaming, Int64 throttle, Int32 readWriteTimeout), remote name: yyBNPiiTQNNBCPSikwlAfR after 31563 ms
[12:20:44 840] Uploading file 4, 10.00 MiB ...  done! in 2868 ms
[12:20:47 709] Uploading file 5, 8.70 MiB ...  done! in 3508 ms
[12:20:51 218] Uploading file 6, 2.50 MiB ...  done! in 2436 ms
[12:20:53 655] Uploading file 7, 28.57 MiB ...  done! in 23314 ms
[12:21:16 970] Uploading file 8, 37.16 MiB ...  done! in 24095 ms
[12:21:41 066] Uploading file 9, 24.78 MiB ...  done! in 15139 ms

EDIT 3:

Going to an infinite read-write-timeout (0s) seems to have solved the upload fails.
Recovery code seems to have managed to deal with the mess, so good job there.

But why does Canary continue to suffer? This was asked before. Response was:

If there’s no need, then why does it fail by default with small destination (561 files)?

7

Warnings on GUI Restore when picking a time (including default newest):

image
image494Ă—370 26.3 KB

EDIT 1:

NGAX

EDIT 2:

ngclient is not very good at showing errors, but the job log has a warning:

“2025-03-27 19:48:03 -04 - [Warning-Duplicati.Library.Main.Controller-OptionValidationError]: The value "20250327T234803Z" supplied to --time does not represent a valid time”

and if you go back to ngax, some warning popups are awaiting you there…

8

image

is presumably the “Added support for sorting the list of backups in the UI”.
I initially couldn’t find it in the UI, but refresh put it in the upper right corner.
It’s very fragile though, e.g. if you change page and return home, it’s gone.

9

Further to my previous report, I went ahead and tried the S3 backup again, this time I got:

  "Errors": [
    "2025-03-28 08:54:26 +01 - [Error-Duplicati.Library.Main.Controller-FailedOperation]: The operation Backup has failed with error: Detected 306 file(s) in FilesetEntry without corresponding FileLookup entry in the following filesets:\r\nFileset 2: 10/03/2025 05:20:13 (id = 11)\r\nDatabaseInconsistencyException: Detected 306 file(s) in FilesetEntry without corresponding FileLookup entry in the following filesets:\r\nFileset 2: 10/03/2025 05:20:13 (id = 11)"

So I ran a repair and got:

  "Messages": [
    "2025-03-28 08:57:19 +01 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Repair has started",
    "2025-03-28 08:57:19 +01 - [Information-Duplicati.Library.Main.Operation.RepairHandler-RepairingBrokenFilesets]: Repairing 1 broken filesets",
    "2025-03-28 08:57:19 +01 - [Information-Duplicati.Library.Main.Operation.RepairHandler-RepairingBrokenFileset]: Repairing broken fileset 1 of 1: 10/03/2025 05:20:13",
    "2025-03-28 08:57:19 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-20250310T042013Z.dlist.zip.aes (4.234 MiB)",
    "2025-03-28 08:57:21 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-20250310T042013Z.dlist.zip.aes (4.234 MiB)",
    "2025-03-28 08:57:33 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  ()",
    "2025-03-28 08:57:35 +01 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (15.673 KiB)"
  ],
  "Warnings": [
    "2025-03-28 08:57:35 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it",
    "2025-03-28 08:57:35 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it"
  ],

I then re-ran the S3 backup which then worked fine. A repair afterwards then showed:

 "Warnings": [
    "2025-03-28 11:08:28 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it",
    "2025-03-28 11:08:28 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it"
  ],

For the local backup job, it ran fine, but for curiosity I ran a repair on it and it logged:

  "Warnings": [
    "2025-03-28 08:58:19 +01 - [Warning-Duplicati.Library.Main.Operation.RepairHandler-LargeEmptyIndexFile]: The empty index file Duplicati.Library.Main.Database.LocalRepairDatabase+RemoteVolume is larger than expected, choosing not to delete it"
  ],

I’m still not sure what I’m supposed to do about these index files which it chooses not to delete.

10

Not sure how to deal with it going forward, since the commits are in a different repo.
But there was no additional fixes to ngclient for this round.

We are working on it. I have added your findings as issues.

I see there is a bug that prevents you from seeing the filename. The feature is a new cleanup that identifies leftover index files and removes them. According to the database they contain no needed information so they can be safely deleted.

I will fix the issue preventing the name from being displayed, so we can see what file it is.

It does not have any negative impact, but it does give a warning on each run.

I see that part needs to be fixed. The ITimeoutExemptBackend was used for the timeout system prior to this release but should not be used anymore.

The read-write-timeout is not an upload timeout, it is an inactivity timeout. Every time some data is processed, the timer is reset. So a default of 30 seconds means that not even a single byte was processed for 30 seconds, which would indicate a stalled connection IMO.

This looks like it timed out after 45 seconds. Any clue as to why it would time out? Network issues?

We can increase the timeout to 60s by default, but it should not be required.

:1st_place_medal:

Fixed one parsing error, but apparently created a new one.
I have registered an issue.

No, that is a good point. They should be deleted, so perhaps I should just update the code to delete them anyway. They serve no purpose anymore.

1 Like
11

Unlike with 2.1.0.111, I get the following message with SharePoint backup targets:

2025-03-28 04:00:00 +01 - [Warning-Duplicati.Library.Main.Controller-UnsupportedOption]: The specified option --site-id is not supported and will be ignored.

It seems, however, that the backup is working.

12

Options from AdditionalSupportedCommands seem gone (per help) , so also:

onedrivev2 has lost drive-id
msgroup has lost group-id and group-email

13

I didn’t find where that is. You mean https://docs.duplicati.com/?

What does that mean? With the option I get the warning, but the backup seems to work. Without the option, access to SharePoint doesn’t work.

Via the CLI can site-id be used? SharePoint v2 (Graph API) | Duplicati

I’m confused. :slight_smile:

14

It means it’s also gone from Duplicati.CommandLine help, e.g. for onedrivev2 or msgroup.

Interesting result. I didn’t think Duplicati could process options it didn’t know, but maybe it can.

The AdditionalSupportedCommands reference is code. That part wasn’t really written for you.