Release: 2.1.0.110 (Canary) 2025-02-28

[ts678]

@kenkendk

The value will be pushed over a websocket when it changes, but I can see that the task list and the poll are not guarded by the same lock, so it is possible that this is a race where the task data is not updated when the notification is sent, but is then changed shortly after the data is sent.

What would that theory make in Edge developer tools (or Wireshark if need be)?

The key to getting a WS view seems to be to let devtools see WS start. Refresh.

I made a new backup, and pushed Run until the GUI seemed to not react to that.

run went in with server response 16:40:19
WS last message was 16:40:17

I went to look at the GUI job logs action, but got 500 (Internal Server Error).
Fortunately I had a server log running, which was an easy way to watch backups.

2025-03-25 16:40:16 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2025-03-25 16:40:17 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed
2025-03-25 16:40:19 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started
2025-03-25 16:40:20 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed

WebSocket messages:

16:40:16 {"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1529,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:16 {"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1530,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:16 {"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1530,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:16 {"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1531,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:17 {"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1532,"LastDataUpdateID":80,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:17 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1533,"LastDataUpdateID":80,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

16:40:17 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1534,"LastDataUpdateID":80,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

EDIT 1:

EDIT 2:

I’ll repeat the copy (direct from Edge) of second and third identical messages, in case duplicate notifications are not supposed to happening. Is there any benefit?

{"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1530,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

{"ActiveTask":{"Item1":34,"Item2":"5"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":1530,"LastDataUpdateID":79,"LastNotificationUpdateID":26,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

EDIT 3:

Above test was on 2.1.0.111 TrayIcon with server profiling log. In case the log or TrayIcon somehow changes timings, I tried 2.1.0.5 Stable server, Hung after six:

I’m not sure if all the GUI hangs are from the same cause, but I get glitches often. Other examples include adding a new job and then not seeing it until I do refresh. Recreate (which is sometimes a slow start by nature) will sometimes just sit there. Pressing it again gets a complaint because it’s already running (despite no signs).

While I have 2.1.0.5 up, I think I’ll see if some other buttons will misbehave for me.

EDIT 4:

Maybe around 10 Repair runs caused status bar hang, but it cleared itself up later, possibly due to some seemingly periodic WS that were coming (once per minutes).

07:59:18 repair
07:59:18 progressstate
07:59:19 backups
... many progressstate
08:00:19 progressstate

07:59:19 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":171,"LastDataUpdateID":28,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:19 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":172,"LastDataUpdateID":28,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:19 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":173,"LastDataUpdateID":28,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:19 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":174,"LastDataUpdateID":28,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:20 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":175,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:20 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":177,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
07:59:20 {"ActiveTask":{"Item1":26,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":176,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
08:00:20 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":178,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
08:01:20 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":179,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}
(there's now a WS message every minute)
08:20:20 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Ready","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":198,"LastDataUpdateID":29,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

EDIT 5:

Compact now gets stuck after less then 10 runs:

The fact that it says backup is a separate open issue. This isn’t recovering itself.

10:49:02 compact gets {"Status":"OK","ID":36}
and then it swings into progressstate (still going)

WS activity

10:49:02 {"ActiveTask":null,"ProgramState":"Running","SchedulerQueueIds":[{"Item1":36,"Item2":"1"}],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":410,"LastDataUpdateID":38,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

10:49:02 {"ActiveTask":{"Item1":36,"Item2":"1"},"ProgramState":"Running","SchedulerQueueIds":[],"ProposedSchedule":[],"HasWarning":false,"HasError":false,"SuggestedStatusIcon":"Active","EstimatedPauseEnd":"0001-01-01T00:00:00","LastEventID":411,"LastDataUpdateID":38,"LastNotificationUpdateID":0,"UpdatedVersion":null,"UpdaterState":"Waiting","UpdateDownloadLink":null,"UpdateDownloadProgress":0.0}

EDIT 6:

To test some pre-WebSocket versions, 2.0.8.1 and 2.0.9.101 did 30 backups OK.

v2.0.9.102_canary_2024-08-02 went to WebSocket. It gave me access problems, and I wound up using v2.0.9.104_canary_2024-08-21 which showed the problem.

[kenkendk]

@ts678

16:40:17 {"ActiveTask":null,

This one should update the UI to show that it is completed.

@ts678

To test some pre-WebSocket versions, 2.0.8.1 and 2.0.9.101 did 30 backups OK.

Ok, so we can narrow this down to websockets.
That should be easier to fix.

My theory is then that it happens because the order of messages can be flipped a bit.
Previously, it would fetch all messages, but now some are pushed, so there is small period where a message can arrive before a fetch and this causes the UI to enter a wrong state.

I have registered it as an issue: UI can enter a stuck state · Issue #6101 · duplicati/duplicati · GitHub

[jberry02]

@jberry02

@walloutlet

… Just did a version jump from from 2.1.0.109 to 2.1.0.110 via a Docker install and the new default UI (ngclient) display a blank or empty screen.

I am able to change the URL to point to /ngax and the UI loads fine. …

I am seeing the same thing on a Windows 10 system using Firefox from a Linux system as the browser. I am not seeing the issue on a Linux system (again using Firefox on a Linux system as the browser). In all cases Duplicati is running as a system service on port 8200.

Further testing shows the problem also exists when using chromium and seamonkey (again, browser on Linux system, Duplicati on Windows 10 system).

In all the above cases changing the URL to /ngax/ brings up the prior interface.

I can confirm that this problem no longer exists in .116.