Release: 2.1.0.102 (Canary) 2024-12-12

kenkendk · December 18, 2024, 1:52pm

That was my mistake. The build failed near the end, so I restarted it, not seeing that the counter had incremented. I rebuilt everything with the 2.1.0.2 version number, but it looks like the manifest file was not overwritten with the correct number.

Thanks for trying this and reporting the result.

I figure out why it fails for MSGraph-based backends: the download waits for the entire file to be downloaded before streaming it. This causes some issues with UI not showing progress, etc, but also triggers the timeout issue.

There are two workarounds for 2.1.0.102:

set --disable-streaming-transfers=true which will skip the timeout stream
set --use-http-client=false which will work with the timeout

It should also be possible to get it working by disabling the timeout with:

--read-write-timeout=0s

But since you report that setting a 1h timeout does not work, I am not 100% sure why setting the timeout does not work for @ollibraun . Did you set it in the backup job advanced options? It does not work setting it as a startup parameter, but you get no warnings if you do.

EDIT: The code always applies 30s timeout, regardless of how you set it . I have a fix for that.

I will continue to debug this a bit more and see if I can make it more smooth. The timeout for the upload is not working correctly with large files, due to the way MSGraph is chuncking and delaying operations.

EDIT: PR is ready for fixing the msgraph issues.

ollibraun · December 18, 2024, 4:47pm

--use-http-client=false

Then I get “Invalid URI: The format of the URI could not be determined.”

--disable-streaming-transfers=true

Yes, that seems to make compacting work for me (it still takes a while, but the error messages are gone, so it’s looking good. Thank you very much!

kenkendk · December 18, 2024, 10:25pm

I see. I will remove support for that switch since it is obviously not working.

Hannes3 · December 20, 2024, 10:14pm

Manual shutdown of the server (via Quit in the trayicon) avoids the error message during computer shutdown.

ollibraun · December 21, 2024, 9:22pm

Ok. Thanks for the info.

New problem with .103 - the service no longer starts:

“C:\Program Files\Duplicati 2\Duplicati.WindowsService.exe” install --log-retention=1D --server-datafolder=C:\ProgramData\Duplicati --disable-db-encryption --webservice-password=password

Duplicati service installation succeeded.

Net start Duplicati
Duplicati service installation failed. Exception: Win32 error 1053 during start service (StartServiceW)

ts678 · December 21, 2024, 10:20pm

I was going to question that (OK, I still will – is it 102 or 103?), given the discussions above.
But https://github.com/duplicati/duplicati/releases/tag/v2.1.0.103_canary_2024-12-21 has it.
I don’t think forum ever got the announcement.

Regardless, watching Task Manager for Duplicati process behavior during the sc might help.
Event Viewer’s new entries in Windows Application event log might also provide some clues.

ollibraun · December 22, 2024, 3:09pm

I’ll postpone my contribution as soon as there’s a post about the.103 here.

I’ve gone back to the.102 everywhere. I don’t have much time to debug right now.

kenkendk · December 22, 2024, 10:49pm

The build process terminated prematurely without errors. I will make a manual post.

There were two changes related to WindowsService in .103:

Changed order or arguments
For .102 and earlier, the event log option --windows-eventlog= would be pre-pended to any user supplied arguments. For .103 it is appended instead, because the agent commandline is a bit more picky than the server currently
Changed eventlog
For .102 all logs were written in Application → Duplicati, but this was a bit noisy as there tends to be a lot of information messages generated. For .103 there is a new Duplicati 2 log where the different parts of Duplicati will write messages and not interfere with the Applications log.

ts678 · December 26, 2024, 1:53pm

Tiny backup while trying to reproduce restore problem of uncreated folders has stuck status.
I’ve seen other small backups stick at Backup complete!, but it’s rare. Maybe time for report.

Profiling log ends with:

2024-12-26 08:16:05 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Started: duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip (1.42 KB)
2024-12-26 08:16:05 -05 - [Profiling-Duplicati.Library.Main.BackendManager-DownloadSpeed]: Downloaded 1.42 KB in 00:00:00.0010016, 1.38 MB/s
2024-12-26 08:16:05 -05 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Get - Completed: duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip (1.42 KB)
2024-12-26 08:16:05 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.BackendManager-RemoteOperationGet]: RemoteOperationGet took 0:00:00:00.001
2024-12-26 08:16:05 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip"
2024-12-26 08:16:06 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: UPDATE "RemoteVolume" SET "VerificationCount" = MAX(1, CASE WHEN "VerificationCount" <= 0 THEN (SELECT MAX("VerificationCount") FROM "RemoteVolume") ELSE "VerificationCount" + 1 END) WHERE "Name" = "duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip" took 0:00:00:00.123
2024-12-26 08:16:06 -05 - [Information-Duplicati.Library.Main.Operation.TestHandler-Test results]: Successfully verified 3 remote files
2024-12-26 08:16:06 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1732626966
2024-12-26 08:16:06 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "LogData" WHERE "Timestamp" < 1732626966 took 0:00:00:00.000
2024-12-26 08:16:06 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1732626966
2024-12-26 08:16:06 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: DELETE FROM "RemoteOperation" WHERE "Timestamp" < 1732626966 took 0:00:00:00.000
2024-12-26 08:16:06 -05 - [Profiling-Timer.Begin-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: Starting - ExecuteNonQuery: PRAGMA optimize
2024-12-26 08:16:06 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Database.ExtensionMethods-ExecuteNonQuery]: ExecuteNonQuery: PRAGMA optimize took 0:00:00:00.004
2024-12-26 08:16:06 -05 - [Profiling-Timer.Finished-Duplicati.Library.Main.Controller-RunBackup]: Running Backup took 0:00:00:07.555
2024-12-26 08:16:06 -05 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed

Status bar says Running task: Backup complete!

Server poll maybe explains why status bar says that, but is server confused?

GET /api/v1/progressstate HTTP/1.1
Host: localhost:8200
Connection: keep-alive
sec-ch-ua-platform: "Windows"
Authorization: Bearer REDACTED
Cache-Control: no-cache
Pragma: no-cache
sec-ch-ua: "Microsoft Edge";v="131", "Chromium";v="131", "Not_A Brand";v="24"
sec-ch-ua-mobile: ?0
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0
Accept: application/json, text/plain, */*
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
Sec-Fetch-Dest: empty
Referer: http://localhost:8200/ngax/index.html
Accept-Encoding: gzip, deflate, br, zstd
Accept-Language: en-US,en;q=0.9
Cookie: default-theme=ngax


HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Thu, 26 Dec 2024 13:32:19 GMT
Server: Kestrel
Transfer-Encoding: chunked

{"BackupID":"4","TaskID":75,"BackendAction":"Get","BackendPath":"duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip","BackendFileSize":1454,"BackendFileProgress":1454,"BackendSpeed":1,"BackendIsBlocking":false,"CurrentFilename":null,"CurrentFilesize":0,"CurrentFileoffset":0,"CurrentFilecomplete":false,"Phase":"Backup_Complete","OverallProgress":1,"ProcessedFileCount":1,"ProcessedFileSize":17,"TotalFileCount":1,"TotalFileSize":17,"StillCounting":false}

EDIT 1:

Because it’s hard to trace Wireshark to a specific tab, here’s the view from the offending tab:

{
“BackupID”: “4”,
“TaskID”: 75,
“BackendAction”: “Get”,
“BackendPath”: “duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip”,
“BackendFileSize”: 1454,
“BackendFileProgress”: 1454,
“BackendSpeed”: 0,
“BackendIsBlocking”: false,
“CurrentFilename”: null,
“CurrentFilesize”: 0,
“CurrentFileoffset”: 0,
“CurrentFilecomplete”: false,
“Phase”: “Backup_Complete”,
“OverallProgress”: 1,
“ProcessedFileCount”: 1,
“ProcessedFileSize”: 17,
“TotalFileCount”: 1,
“TotalFileSize”: 17,
“StillCounting”: false
}

About → System information

Server state properties

lastEventId : 373
lastDataUpdateId : 102
lastNotificationUpdateId : 12
estimatedPauseEnd : “0001-01-01T04:56:02.000Z”
activeTask : {“Item1”:74,“Item2”:null}
programState : Running
lastErrorMessage :
connectionState : connected
connectionAttemptTimer : 0
failedConnectionAttempts : 0
failedAuthAttempts : 0
lastPgEvent : {“BackupID”:“4”,“TaskID”:75,“BackendAction”:“Get”,“BackendPath”:“duplicati-b369beed73efa4bc29e5add7e7a5e28f1.dblock.zip”,“BackendFileSize”:1454,“BackendFileProgress”:1454,“BackendSpeed”:0,“BackendIsBlocking”:false,“CurrentFilename”:null,“CurrentFilesize”:0,“CurrentFileoffset”:0,“CurrentFilecomplete”:false,“Phase”:“Backup_Complete”,“OverallProgress”:1,“ProcessedFileCount”:1,“ProcessedFileSize”:17,“TotalFileCount”:1,“TotalFileSize”:17,“StillCounting”:false}
updaterState : Waiting
updateDownloadLink : https://updates.duplicati.com/canary/duplicati-2.1.0.103_canary_2024-12-21-win-x64-gui.zip
updatedVersion : 2.1.0.103
updateDownloadProgress : 0
proposedSchedule : [{“Item1”:“2”,“Item2”:“2024-12-27T12:20:00Z”}]
schedulerQueueIds :
pauseTimeRemain : 0

There’s nothing after the backup itself such as a notification or a script (which can cause this).

EDIT 2:

EDIT 3:

Edge wanted an update, and this got status bar back to normal, but Duplicati is still confused.

Tray icon is still busy

but I think this is the 401 unauthorized bug, or at least if I trace one back from Wireshark and compare its port to netstat -ano | findstr 8200, it’s on TrayIcon port so that may explain.

Back on the tab, I can click Run and watch it go in, get 200 OK, but not see status bar update, despite a log being created. This is unusual, but backup is fast. A slow one shows same thing.

Refresh of browser clears it up. I’m not sure how such glitches arise, but refresh often helps…

EDIT 4:

I likely must restart Duplicati to get its TrayIcon longpoll “HTTP/1.1 401 Unauthorized” fixed. Fiddling around in the tab with hard refresh and logout/login is still leaving this TrayIcon failing.
Fiddling around in the TrayIcon with Pause and Open can open a new tab but not fix TrayIcon.

ts678 · December 27, 2024, 1:00pm

Wound up having to restart TrayIcon at 1:36 PM yesterday. At some point, another problem arose.
Looking for TrayIcon this morning after PC wake, it’s not visible. Tried Explorer restart. Didn’t help.
The hosted server was doing its scheduled backup though. Icon client code is polling, but not well:

Port 64130 PID is TrayIcon, plus you can probably ID it from the User-Agent string.

GET /api/v1/serverstate?longpoll=true&lastEventId=67&duration=5m HTTP/1.1
Host: localhost:8200
Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ0eXAiOiJBY2Nlc3NUb2tlbiIsInNpZCI6InRyYXlpY29uIiwiZmFtIjoidGVtcG9yYXJ5IiwibmJmIjoxNzM1MjM4MjE0LCJleHAiOjE3MzUyMzkxMTQsImlzcyI6Imh0dHBzOi8vZHVwbGljYXRpIiwiYXVkIjoiaHR0cHM6Ly9kdXBsaWNhdGkifQ.vwFOKUnN3qVOXh3FKmmxYYPiZmDSGbxKpmvTvnQc3GU
User-Agent: Duplicati-TrayIcon-Monitor/2.1.0.102


HTTP/1.1 401 Unauthorized
Content-Length: 0
Date: Fri, 27 Dec 2024 12:45:47 GMT
Server: Kestrel
WWW-Authenticate: Bearer error="invalid_token", error_description="The token expired at '12/26/2024 18:51:54'"

EDIT 1:

TrayIcon unauthorized again, this time TrayIcon is actually 2.1.0.103 to 2.1.0.2 Windows service.

GET /api/v1/serverstate?longpoll=true&lastEventId=105&duration=5m HTTP/1.1
Host: localhost:8200
Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ0eXAiOiJBY2Nlc3NUb2tlbiIsInNpZCI6IndlYi1hcGkiLCJmYW0iOiJ0ZW1wb3JhcnkiLCJuYmYiOjE3MzUzMTg4MTksImV4cCI6MTczNTMxOTcxOSwiaXNzIjoiaHR0cHM6Ly9kdXBsaWNhdGkiLCJhdWQiOiJodHRwczovL2R1cGxpY2F0aSJ9.kDGYsfcqKZQUk8EQ4o1tHqOMbDCuddJ9lkmS_jLU5DI
User-Agent: Duplicati-TrayIcon-Monitor/2.1.0.103


HTTP/1.1 200 OK
Content-Type: application/json; charset=utf-8
Date: Fri, 27 Dec 2024 17:15:57 GMT
Server: Kestrel
Transfer-Encoding: chunked

{"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":106,"LastDataUpdateID":4,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0}

GET /api/v1/serverstate?longpoll=true&lastEventId=106&duration=5m HTTP/1.1
Host: localhost:8200
Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ0eXAiOiJBY2Nlc3NUb2tlbiIsInNpZCI6IndlYi1hcGkiLCJmYW0iOiJ0ZW1wb3JhcnkiLCJuYmYiOjE3MzUzMTg4MTksImV4cCI6MTczNTMxOTcxOSwiaXNzIjoiaHR0cHM6Ly9kdXBsaWNhdGkiLCJhdWQiOiJodHRwczovL2R1cGxpY2F0aSJ9.kDGYsfcqKZQUk8EQ4o1tHqOMbDCuddJ9lkmS_jLU5DI
User-Agent: Duplicati-TrayIcon-Monitor/2.1.0.103


HTTP/1.1 401 Unauthorized
Content-Length: 0
Date: Fri, 27 Dec 2024 17:15:57 GMT
Server: Kestrel
WWW-Authenticate: Bearer error="invalid_token", error_description="The token expired at '12/27/2024 17:15:19'"

Timing is interestingly the same second. I went to see what happened on port 8200 in between:

No.	Time	Source	Destination	Protocol	Length	Info
1157	2024-12-27 12:14:57.762269	::1	::1	HTTP	507	GET /api/v1/serverstate?longpoll=true&lastEventId=105&duration=5m HTTP/1.1 
1158	2024-12-27 12:14:57.762303	::1	::1	TCP	64	trivnet1(8200) → 54790 [ACK] Seq=11267 Ack=9820 Win=2609152 Len=0
1159	2024-12-27 12:15:39.595952	::1	::1	WebSocket	66	WebSocket Pong [FIN] 
1160	2024-12-27 12:15:39.596007	::1	::1	TCP	64	54366 → trivnet1(8200) [ACK] Seq=841 Ack=30234 Win=2588672 Len=0
1161	2024-12-27 12:15:42.764038	::1	::1	TCP	65	[TCP Keep-Alive] 54796 → trivnet1(8200) [ACK] Seq=840 Ack=6864 Win=2611968 Len=1
1162	2024-12-27 12:15:42.764078	::1	::1	TCP	76	[TCP Keep-Alive ACK] trivnet1(8200) → 54796 [ACK] Seq=6864 Ack=841 Win=2618880 Len=0 SLE=840 SRE=841
1163	2024-12-27 12:15:57.774610	::1	::1	WebSocket	435	WebSocket Text [FIN] 
1164	2024-12-27 12:15:57.774644	::1	::1	HTTP/JSON	589	HTTP/1.1 200 OK , JSON (application/json)
1165	2024-12-27 12:15:57.774647	::1	::1	WebSocket	435	WebSocket Text [FIN] 
1166	2024-12-27 12:15:57.774648	::1	::1	TCP	64	54366 → trivnet1(8200) [ACK] Seq=841 Ack=30605 Win=2588160 Len=0
1167	2024-12-27 12:15:57.774700	::1	::1	TCP	64	54790 → trivnet1(8200) [ACK] Seq=9820 Ack=11792 Win=2607104 Len=0
1168	2024-12-27 12:15:57.774704	::1	::1	TCP	64	54796 → trivnet1(8200) [ACK] Seq=841 Ack=7235 Win=2611712 Len=0
1169	2024-12-27 12:15:57.775349	::1	::1	HTTP	507	GET /api/v1/serverstate?longpoll=true&lastEventId=106&duration=5m HTTP/1.1 
1170	2024-12-27 12:15:57.775376	::1	::1	TCP	64	trivnet1(8200) → 54790 [ACK] Seq=11792 Ack=10263 Win=2608896 Len=0
1171	2024-12-27 12:15:57.776852	::1	::1	HTTP	278	HTTP/1.1 401 Unauthorized

EDIT 2:

Sign-in and receipt of access token was at 17:00:18 GMT. I guess it’s a 15 minute token, but there is no “refresh” string in later packets, and token was still being tried at 18:52:01 GMT capture stop.

EDIT 3:

Took that config down (saved the capture though), moved to pure 2.1.0.103 with its hosted server. Finished a backup, went to Quit TrayIcon, found it still green and in the 401 unauthorized problem:

GET /api/v1/serverstate?longpoll=true&lastEventId=28&duration=5m HTTP/1.1
Host: localhost:8400
Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ0eXAiOiJBY2Nlc3NUb2tlbiIsInNpZCI6InRyYXlpY29uIiwiZmFtIjoidGVtcG9yYXJ5IiwibmJmIjoxNzM1MzMwODYzLCJleHAiOjE3MzUzMzE3NjMsImlzcyI6Imh0dHBzOi8vZHVwbGljYXRpIiwiYXVkIjoiaHR0cHM6Ly9kdXBsaWNhdGkifQ.PSjp8HlKSfzwaPVtTbDTkhEY-rgITe65mJtVuF5Gvk4
User-Agent: Duplicati-TrayIcon-Monitor/2.1.0.103


HTTP/1.1 401 Unauthorized
Content-Length: 0
Date: Fri, 27 Dec 2024 20:51:22 GMT
Server: Kestrel
WWW-Authenticate: Bearer error="invalid_token", error_description="The token expired at '12/27/2024 20:36:03'"

kenkendk · December 28, 2024, 3:54pm

From your report, it seems like a reload of the page has the correct status. That should only happen if the server is correct.

I think this is some kind of race condition where the last operations happen so quickly that the reported state is off.

Looking at the output it could be that the progress state (state of current task) is saying “active” but the server state is saying “busy”.

It could very well be related to the 401 problem, where the state is just stuck at whatever got through before the 15 minutes expired.

EDIT: I managed to reproduce this. If the connection is lost for some reason, it will stay in that state and not be able to update the icon. This will be fixed with the update to the TrayIcon disconnect.

But, since the “stuck status” has been a problem before, there is likely still some related issue where the progress is not propagated correctly in all cases.