Release: 2.1.0.102 (Canary) 2024-12-12

Releases
29

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:

image
image1020×702 38.8 KB

EDIT 3:

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

Tray icon is still busy

image

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.