Tray icon didn't show unpause on computer wake, while GUI icon did

[ts678]

• I have searched open and closed issues for duplicates.
• I have searched the forum for related topics.

---

Environment info

• Duplicati version: 2.0.8.1 Beta
• Operating system: Windows 10
• Backend: N/A

Description

After bringing the PC out of sleep today, I noticed that the tray icon was still paused despite a 0 second delay configured in Settings.
About --> System info pauseTimeRemain said it had 0 seconds left. The GUI icon at top of home screen showed the unpaused state.
Wireshark traces of the TrayIcon process to itself seem to agree. I couldn't trace the JavaScript, so instead I ran a backup and the icon went green and then back to the normal solid black (without the pause bars). I did another sleep/wake, and problem did not reoccur.
This Duplicati has no scheduled jobs, and no job was in progress overnight, as evidenced by the gap in the server profiling log below:

2024-05-12 15:57:53 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed
2024-05-13 09:48:08 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started

This sort of problem gets mentioned occasionally in reports, but I'm not sure anyone has reported the differences in the two displays.
I'm almost certain nobody has provided Wireshark displays. I'm not sure if anyone tested a run to prove that it was just a bad display.

Steps to reproduce

1. Have Duplicati sitting idle.
2. Sleep the system.
3. Wake the system.

• Actual result:
  TrayIcon shows paused.
• Expected result:
  TrayIcon shows ready.

Screenshots

Debug log

Wireshark during the odd paused TrayIcon:

...{
  "ProgramState": "Running",
  "UpdatedVersion": null,
  "UpdaterState": "Waiting",
  "UpdateReady": false,
  "UpdateDownloadProgress": 0.0,
  "ActiveTask": null,
  "SchedulerQueueIds": [],
  "ProposedSchedule": [],
  "HasWarning": false,
  "HasError": false,
  "SuggestedStatusIcon": "Ready",
  "EstimatedPauseEnd": "0001-01-01T00:00:00",
  "LastEventID": 3075,
  "LastDataUpdateID": 6,
  "LastNotificationUpdateID": 0

Wireshark during the run of next backup:

...{
  "ProgramState": "Running",
  "UpdatedVersion": null,
  "UpdaterState": "Waiting",
  "UpdateReady": false,
  "UpdateDownloadProgress": 0.0,
  "ActiveTask": {
    "Item1": 5,
    "Item2": "1"
  },
  "SchedulerQueueIds": [],
  "ProposedSchedule": [],
  "HasWarning": false,
  "HasError": false,
  "SuggestedStatusIcon": "Active",
  "EstimatedPauseEnd": "0001-01-01T00:00:00",
  "LastEventID": 3090,
  "LastDataUpdateID": 6,
  "LastNotificationUpdateID": 0
}

[Jojo-1000]

Are you sure it was not a visual refresh bug on Windows side? When I launch debug instances, sometimes the tray icons don't disappear instantly. I had 4-5 icons shown minutes later, even though the processes were killed. They normally disappear when you mouse over the icons.

[ts678]

I'm used to seeing dead Duplicati leave tray icons around until I mouse over them (then they disappear). This one not only stayed when I moused over it, but the right click menu could be displayed, and it turned green (as it should) when the backup was active, then solid black when done (as opposed to black with pause bars).

Another potential pitfall (for me) is that I'm now running 2.0.8.1 Beta in the main system tray and 2.0.8.108 Debug in the uparrow expansion of the system tray. To remove possibility of confusion, I quit the Debug version while trying to sort out the Beta version.

A correction I'll make on myself is that tracing JavaScript is probably relevant only to the browser side (which worked), but I didn't trace whatever C# (presumably) code makes the tray icon change.

Now that it's a new day, I did GitHub search on SuggestedStatusIcon, and wonder if the code it's supposed to affect is near here.

[ts678]

One thing that's curious is that when the problem was happening, there were more connections, at least on one snapshot.
I don't know connection plan.

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:58227        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:59798        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:59808        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:59832        ESTABLISHED     14432
  TCP    127.0.0.1:58227        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:59798        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:59821        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:59832        127.0.0.1:8200         ESTABLISHED     14432

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:58227        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:59935        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:59952        ESTABLISHED     14432
  TCP    127.0.0.1:58227        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:59943        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:59952        127.0.0.1:8200         ESTABLISHED     14432

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:58227        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:59952        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:59956        ESTABLISHED     14432
  TCP    127.0.0.1:58227        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:59943        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:59956        127.0.0.1:8200         ESTABLISHED     14432

Anything ESTABLISHED is double-counted by simple findstr, so filter visually for the LISTEN port on left, and LISTEN PID on right.

EDIT:

The same (up since May 10) Duplicati now looks like these, when idle and with an idle icon.

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:50984        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:53357        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:53375        ESTABLISHED     14432
  TCP    127.0.0.1:50984        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:53365        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:53375        127.0.0.1:8200         ESTABLISHED     14432

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:50984        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:53375        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:53405        ESTABLISHED     14432
  TCP    127.0.0.1:50984        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:53398        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:53405        127.0.0.1:8200         ESTABLISHED     14432

C:\>netstat -ano | findstr 8200
  TCP    127.0.0.1:8200         0.0.0.0:0              LISTENING       14432
  TCP    127.0.0.1:8200         127.0.0.1:50984        ESTABLISHED     14432
  TCP    127.0.0.1:8200         127.0.0.1:55034        TIME_WAIT       0
  TCP    127.0.0.1:8200         127.0.0.1:55086        ESTABLISHED     14432
  TCP    127.0.0.1:50984        127.0.0.1:8200         ESTABLISHED     21064
  TCP    127.0.0.1:55046        127.0.0.1:8200         TIME_WAIT       0
  TCP    127.0.0.1:55086        127.0.0.1:8200         ESTABLISHED     14432

C:\>

[kenkendk]

Based on the traces from @ts678 it looks like it is a visual issue.
If I understand correctly, the Wireshark logs show SuggestedStatusIcon: "Ready" but the UI is displaying paused?

[ts678]

I think I just got this again on wake this morning. Anything I should be looking at differently?

2024-05-26 08:48:17 -04 - [Information-Duplicati.Library.Main.Controller-CompletedOperation]: The operation Backup has completed
2024-05-27 08:03:46 -04 - [Information-Duplicati.Library.Snapshots.MSSQLUtility-NoMSSQLInstance]: Cannot find any MS SQL Server instance. MS SQL Server is probably not installed.
2024-05-27 08:03:46 -04 - [Profiling-Duplicati.Library.Snapshots.HyperVUtility-WMISelect]: Using WMI provider \\localhost\root\virtualization\v2
2024-05-27 08:03:46 -04 - [Information-Duplicati.Library.Snapshots.HyperVUtility-NoHyperVFound]: Cannot open WMI provider \\localhost\root\virtualization\v2. Hyper-V is probably not installed.

pauseTimeRemain : 0

I haven't done Wireshark (or much) on this, but I saved the old .pcapng in case SuggestedStatusIcon was changing and I missed it.

EDIT 1:

If I understand correctly, the Wireshark logs show SuggestedStatusIcon: "Ready" but the UI is displaying paused?

"SuggestedStatusIcon": "Paused" is what was coming over until it went Active at 09:48:01, which is profling log

2024-05-13 09:48:08 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started

I'm not sure why log time is 7 seconds delayed, but I'm pretty sure the Active is related to the backup I had started.

EDIT 2:

Capture looks something like this. After time is the TCP client port number:

May 13, 2024 09:39:11.272273000	59959	Ready
May 13, 2024 09:39:11.272380000	58227	Ready
May 13, 2024 09:40:11.272833000	59971	Ready
May 13, 2024 09:40:11.272843000	58227	Ready
May 13, 2024 09:41:11.272841000	59974	Ready
May 13, 2024 09:41:11.272886000	58227	Ready
May 13, 2024 09:42:11.273531000	58227	Ready
May 13, 2024 09:42:11.273546000	59978	Ready
May 13, 2024 09:43:11.273953000	59981	Ready
May 13, 2024 09:43:11.273994000	58227	Ready
May 13, 2024 09:44:11.274817000	59986	Ready
May 13, 2024 09:44:11.274903000	58227	Ready
May 13, 2024 09:45:11.274840000	59995	Ready
May 13, 2024 09:45:11.274904000	58227	Ready
May 13, 2024 09:46:11.275349000 58227	Ready
May 13, 2024 09:46:11.275363000	59999	Ready
May 13, 2024 09:47:11.276653000	58227	Ready
May 13, 2024 09:47:11.276772000	60004	Ready
May 13, 2024 09:48:01.597907000	58227	Active
May 13, 2024 09:48:01.597927000	60008	Active
May 13, 2024 09:48:01.601772000	60023	Active
May 13, 2024 09:48:01.648802000	60018	Active
May 13, 2024 09:48:11.286857000	60018	Active
May 13, 2024 09:48:11.286900000	60024	Active
May 13, 2024 09:49:11.288634000	60026	Active
May 13, 2024 09:49:11.289018000	58227	Active

EDIT 3:

Icon looks OK after wake this morning (May 28), on the same process and without anything new in profiling log.
From Wireshark traces last night, the polling pattern on port 8200 looks a little nicer, but I don't know true goal:

May 27, 2024 19:44:50.474195000	65516	Ready
May 27, 2024 19:45:50.486312000	65521	Ready
May 27, 2024 19:46:50.493731000	65524	Ready
May 27, 2024 19:47:50.504139000	65530	Ready
May 27, 2024 19:48:50.516217000	49158	Ready
May 27, 2024 19:49:50.528968000 49174	Ready
May 27, 2024 19:50:50.531995000	49183	Ready
May 27, 2024 19:51:50.544440000	49195	Ready
May 27, 2024 19:52:50.556292000	49200	Ready
May 27, 2024 19:53:50.569761000	49205	Ready

I looked at Duplicati with a debugger after problem went away, and I now have at least a vague idea of the code.

[ts678]

Got another one on 2.0.8.1. 2.0.9.101 icon on same system unpaused OK. 2.0.8.1 poll in Wireshark says the usual:

"SuggestedStatusIcon": "Ready",\r\n

I ran debugger some, and now it's at:

>	Duplicati.GUI.TrayIcon.exe!Duplicati.GUI.TrayIcon.ImageLoader.LoadIcon(string filename, System.Drawing.Size size) (IL=0x0036, Native=0x00007FFE622BFD40+0x136)
 	Duplicati.GUI.TrayIcon.exe!Duplicati.GUI.TrayIcon.Windows.WinFormsRunner.SetIcon(Duplicati.GUI.TrayIcon.TrayIcons icon) (IL≈0x00F0, Native=0x00007FFE622BFA10+0x2C0)
 	Duplicati.GUI.TrayIcon.exe!Duplicati.GUI.TrayIcon.TrayIconBase.<>c__DisplayClass23_0.<OnStatusUpdated>b__0() (IL=0x0086, Native=0x00007FFE622BF750+0x16B)

and in source looks like it's gotten the cached value and is about to return, although reading decompiled code is iffy.

			bool flag = ImageLoader.ICONS.TryGetValue(key, out icon);
			Icon result;
			if (flag)
			{
				result = icon;
			}
			else
			{
				bool flag2 = !filename.EndsWith(".ico", StringComparison.OrdinalIgnoreCase);

Unfortunately I can't find the private ICONS dictionary, but a happy-but-wrong cache might explain its poll-resistance.

duplicati/Duplicati/GUI/Duplicati.GUI.TrayIcon/ImageLoader.cs

Lines 60 to 63 in 78ea50c

	if (ICONS.TryGetValue(cachename, out ico))
	return ico;
	if (!filename.EndsWith(".ico", StringComparison.OrdinalIgnoreCase))

EDIT 1:

I set up Wireshark and some more breakpoints to see what a sleep and wake would do that might explain the visual oddity.
I saw nothing weird there. I did notice code where menu item is changed, and that led me to another view of inconsistency:

EDIT 2:

Got it again, presumably on wake. Same inconsistent view of paused TrayIcon offering Pause. GUI icon also gives Pause icon.

About --> System info looks unpaused:

estimatedPauseEnd : 0001-01-01T00:00:00
...
pauseTimeRemain : 0