Long update delays with automatic snap refresh Firefox and Thunderbird

[Mika Haaja]

System Ubuntu 24.04.1, snapd 2.63.
Firefox being closed prevents automatic snap updates for firefox when snapd update is taking place.
Normally snap refresh checks updates four times a day. If Firefox is not open during any refresh check, the update goes to the background system and gets stuck.
As a reference to the earlier Pug tracking: https://bugs.launchpad.net/ubuntu/+source/firefox/+bug/2074295

I have encountered this same problem in many 24.04 installations and updated installations.

Yesterday, by chance, I noticed in another installation where Firefox has not been updated automatically for a 19 days after firefox 132.0 release. When Firefox was open, and snapd automatic refresh took over. There was a notification about a Firefox update. And after closing Firefox, it had updated to the latest version.

I've tried to look for instructions on how to get the trace a reason more precisely snapd background updater, but I haven't found any instructions.

These data and logs below are from a virtual machine where I've been letting everything update automatically for over a month now. I haven't done any manual updates.

snap list
Name Version Rev Tracking Publisher Notes
bare 1.0 5 latest/stable canonical✓ base
core 16-2.61.4-20240607 17200 latest/stable canonical✓ core
core22 20241001 1663 latest/stable canonical✓ base
firefox 131.0.3-1 5134 latest/stable mozilla✓ -
firmware-updater 0+git.7983059 147 latest/stable/… canonical✓ -
gnome-42-2204 0+git.510a601 176 latest/stable/… canonical✓ -
gtk-common-themes 0.1-81-g442e511 1535 latest/stable/… canonical✓ -
snap-store 0+git.4fcd62b7 1218 latest/stable/… canonical✓ -
snapd 2.63 21759 latest/stable canonical✓ snapd
snapd-desktop-integration 0.9 253 latest/stable/… canonical✓ -
thunderbird 128.4.2esr-1 562 latest/stable/… canonical✓ -

snap info firefox
name: firefox
summary: Mozilla Firefox web browser
publisher: Mozilla✓
store-url: https://snapcraft.io/firefox
contact: https://support.mozilla.org/kb/file-bug-report-or-feature-request-mozilla
license: unset
description: |
  Firefox is a powerful, extensible web browser with support for modern web
  application technologies.
commands:
  - firefox
  - firefox.geckodriver
snap-id: 3wdHCAVyZEmYsCMFDE9qt92UV8rC8Wdk
tracking: latest/stable
refresh-date: 33 days ago, at 17:49 EEST
channels:
  latest/stable: 132.0.2-2 2024-11-12 (5273) 286MB -
  latest/candidate: 132.0.2-2 2024-11-11 (5273) 286MB -
  latest/beta: 133.0b9-1 2024-11-15 (5299) 286MB -
  latest/edge: 134.0a1 2024-11-18 (5308) 313MB -
  esr/stable: 128.4.0esr-1 2024-10-29 (5191) 283MB -
  esr/candidate: 128.4.0esr-1 2024-10-30 (5218) 283MB -
  esr/beta: ↑
  esr/edge: ↑
installed: 131.0.3-1 (5134) 285MB -

snap changes
no changes found

snap refresh --time
timer: 00:00~24:00/4
last: today at 18:59 EET
next: tomorrow at 03:30 EET

journalctl -u snapd

-- Boot c38fe82b08df47a9a27eecd7c2b27f4d --
Nov 13 16:25:03 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 13 16:25:03 kayttaja-VirtualBox snapd[973]: overlord.go:271: Acquiring state lock file
Nov 13 16:25:03 kayttaja-VirtualBox snapd[973]: overlord.go:276: Acquired state lock file
Nov 13 16:25:03 kayttaja-VirtualBox snapd[973]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 13 16:25:03 kayttaja-VirtualBox snapd[973]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 13 16:25:03 kayttaja-VirtualBox snapd[973]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 13 16:25:04 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 13 16:35:04 kayttaja-VirtualBox snapd[973]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 13 16:35:04 kayttaja-VirtualBox snapd[973]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 13 17:20:27 kayttaja-VirtualBox snapd[973]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"
Nov 13 18:45:46 kayttaja-VirtualBox snapd[973]: main.go:168: Exiting on terminated signal.
Nov 13 18:45:46 kayttaja-VirtualBox systemd[1]: Stopping snapd.service - Snap Daemon...
Nov 13 18:45:49 kayttaja-VirtualBox snapd[973]: overlord.go:515: Released state lock file
Nov 13 18:45:49 kayttaja-VirtualBox systemd[1]: snapd.service: Deactivated successfully.
Nov 13 18:45:49 kayttaja-VirtualBox systemd[1]: Stopped snapd.service - Snap Daemon.
Nov 13 18:45:49 kayttaja-VirtualBox systemd[1]: snapd.service: Consumed 1.465s CPU time, 40.0M memory peak, 0B memory swap peak.

-----------------------------------------------------------------------------------------------------------

-- Boot 84f5f501ab2e4bdd93f3fab3884523fb --
Nov 14 16:48:16 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 14 16:48:16 kayttaja-VirtualBox snapd[934]: overlord.go:271: Acquiring state lock file
Nov 14 16:48:16 kayttaja-VirtualBox snapd[934]: overlord.go:276: Acquired state lock file
Nov 14 16:48:16 kayttaja-VirtualBox snapd[934]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 14 16:48:16 kayttaja-VirtualBox snapd[934]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 14 16:48:16 kayttaja-VirtualBox snapd[934]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 14 16:48:16 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 14 16:58:16 kayttaja-VirtualBox snapd[934]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 14 16:58:17 kayttaja-VirtualBox snapd[934]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"
Nov 14 16:58:27 kayttaja-VirtualBox snapd[934]: storehelpers.go:1019: cannot refresh snap "thunderbird": snap has no updates available
Nov 14 17:15:05 kayttaja-VirtualBox systemd[1]: Stopping snapd.service - Snap Daemon...
Nov 14 17:15:05 kayttaja-VirtualBox snapd[934]: main.go:168: Exiting on terminated signal.
Nov 14 17:15:08 kayttaja-VirtualBox snapd[934]: overlord.go:515: Released state lock file
Nov 14 17:15:08 kayttaja-VirtualBox systemd[1]: snapd.service: Deactivated successfully.
Nov 14 17:15:08 kayttaja-VirtualBox systemd[1]: Stopped snapd.service - Snap Daemon.
Nov 14 17:15:08 kayttaja-VirtualBox systemd[1]: snapd.service: Consumed 4.056s CPU time, 452.6M memory peak, 0B memory swap peak.

-----------------------------------------------------------------------------------------------------------

-- Boot eeb89191abe14aebb15a00fac60c54f9 --
Nov 18 16:24:19 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 18 16:24:19 kayttaja-VirtualBox snapd[984]: overlord.go:271: Acquiring state lock file
Nov 18 16:24:19 kayttaja-VirtualBox snapd[984]: overlord.go:276: Acquired state lock file
Nov 18 16:24:20 kayttaja-VirtualBox snapd[984]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 18 16:24:20 kayttaja-VirtualBox snapd[984]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 18 16:24:20 kayttaja-VirtualBox snapd[984]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 18 16:24:20 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 18 16:34:20 kayttaja-VirtualBox snapd[984]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 18 16:34:20 kayttaja-VirtualBox snapd[984]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 18 18:49:46 kayttaja-VirtualBox systemd[1]: Stopping snapd.service - Snap Daemon...
Nov 18 18:49:46 kayttaja-VirtualBox snapd[984]: main.go:168: Exiting on terminated signal.
Nov 18 18:49:49 kayttaja-VirtualBox snapd[984]: overlord.go:515: Released state lock file
Nov 18 18:49:49 kayttaja-VirtualBox systemd[1]: snapd.service: Deactivated successfully.
Nov 18 18:49:49 kayttaja-VirtualBox systemd[1]: Stopped snapd.service - Snap Daemon.
Nov 18 18:49:49 kayttaja-VirtualBox systemd[1]: snapd.service: Consumed 1.248s CPU time, 39.4M memory peak, 0B memory swap peak.

I have shortened the log. I can also deliver the previous log complete if necessary.

uprecords -B -m 20
     # Uptime | System Boot up
----------------------------+---------------------------------------------------
-> 1 0 days, 01:46:13 | Linux 6.8.0-48-generic Mon Nov 18 18:49:52 2024
     2 0 days, 02:25:31 | Linux 6.8.0-48-generic Mon Nov 18 16:24:15 2024
     3 0 days, 02:20:46 | Linux 6.8.0-48-generic Wed Nov 13 16:25:00 2024
     4 0 days, 03:31:44 | Linux 6.8.0-48-generic Tue Nov 12 17:31:29 2024
     5 0 days, 01:39:58 | Linux 6.8.0-47-generic Mon Oct 28 19:12:33 2024
     6 0 days, 01:00:04 | Linux 6.8.0-47-generic Sat Oct 26 20:35:59 2024
     7 0 days, 01:05:09 | Linux 6.8.0-47-generic Fri Oct 25 16:21:29 2024
     8 0 days, 01:14:12 | Linux 6.8.0-45-generic Fri Oct 18 18:02:53 2024
     9 0 days, 02:16:16 | Linux 6.8.0-45-generic Thu Oct 17 16:43:32 2024
    10 0 days, 01:19:01 | Linux 6.8.0-45-generic Sat Oct 12 17:26:52 2024
    11 0 days, 02:39:02 | Linux 6.8.0-41-generic Fri Sep 6 17:21:57 2024
    12 0 days, 02:15:45 | Linux 6.8.0-41-generic Sat Aug 31 10:59:02 2024
    13 0 days, 02:27:30 | Linux 6.8.0-40-generic Fri Aug 23 15:58:08 2024
    14 0 days, 01:07:46 | Linux 6.8.0-40-generic Thu Aug 15 21:47:30 2024
    15 0 days, 01:06:18 | Linux 6.8.0-39-generic Tue Aug 13 21:44:59 2024

The new thing about this particular installation is that Thunderbird has also not updated automatically for six days now. In the past, there have been no update problems with Thunderbird. I suspect this stuck Firefox update is blocking the Thunderbird update as well.

[Mika Haaja (mika32)]

Thunderbird was updated today. Firefox has still not been updated because I have kept it closed during the automatic refresh check.

-- Boot cb12409811dd40da82c80945ff89f140 --
Nov 21 16:03:15 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 21 16:03:15 kayttaja-VirtualBox snapd[985]: overlord.go:271: Acquiring state lock file
Nov 21 16:03:15 kayttaja-VirtualBox snapd[985]: overlord.go:276: Acquired state lock file
Nov 21 16:03:15 kayttaja-VirtualBox snapd[985]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 21 16:03:15 kayttaja-VirtualBox snapd[985]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 21 16:03:15 kayttaja-VirtualBox snapd[985]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 21 16:03:15 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 21 16:13:15 kayttaja-VirtualBox snapd[985]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 21 16:13:16 kayttaja-VirtualBox snapd[985]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"
Nov 21 16:13:26 kayttaja-VirtualBox snapd[985]: storehelpers.go:1019: cannot refresh snap "thunderbird": snap has no updates available

snap changes
ID Status Spawn Ready Summary
53 Done today at 16:13 EET today at 16:13 EET Automaattisesti päivitä snap "thunderbird"

snap info firefox
name: firefox
summary: Mozilla Firefox web browser
publisher: Mozilla✓
store-url: https://snapcraft.io/firefox
contact: https://support.mozilla.org/kb/file-bug-report-or-feature-request-mozilla
license: unset
description: |
  Firefox is a powerful, extensible web browser with support for modern web application
  technologies.
commands:
  - firefox
  - firefox.geckodriver
snap-id: 3wdHCAVyZEmYsCMFDE9qt92UV8rC8Wdk
tracking: latest/stable
refresh-date: 36 days ago, at 17:49 EEST
channels:
  latest/stable: 132.0.2-2 2024-11-12 (5273) 286MB -
  latest/candidate: 133.0-1 2024-11-21 (5330) 286MB -
  latest/beta: 133.0b9-1 2024-11-19 (5317) 286MB -
  latest/edge: 134.0a1 2024-11-21 (5334) 314MB -
  esr/stable: 128.4.0esr-1 2024-10-29 (5191) 283MB -
  esr/candidate: 128.5.0esr-1 2024-11-20 (5325) 282MB -
  esr/beta: ↑
  esr/edge: ↑
installed: 131.0.3-1 (5134) 285MB -

uprecords -B -m 20
     # Uptime | System Boot up
----------------------------+---------------------------------------------------
-> 1 0 days, 00:30:08 | Linux 6.8.0-48-generic Thu Nov 21 16:03:10 2024
     2 0 days, 01:02:11 | Linux 6.8.0-48-generic Wed Nov 20 16:45:59 2024
     3 0 days, 01:02:53 | Linux 6.8.0-48-generic Tue Nov 19 16:38:00 2024
     4 0 days, 03:07:11 | Linux 6.8.0-48-generic M...

[Mika Haaja (mika32)]

Finally, firefox updated without firefox being open during the automatic snap refresh. It has been 24 days since the release of version 132.0. Firefox version updated directly to version 132.0.2, skipping versions 132.0 and 132.0.1 completely.

Something apparently forced the update in the end. So, Firefox being closed does not prevent the update completely. But the delay for the update is quite long.

I also attached a journalctl log from the time of the firefox update.

journalctl -u snapd
-- Boot b6a0f6d00d7d47d5995052536894ffec --
Nov 22 16:34:02 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 22 16:34:02 kayttaja-VirtualBox snapd[937]: overlord.go:271: Acquiring state lock file
Nov 22 16:34:02 kayttaja-VirtualBox snapd[937]: overlord.go:276: Acquired state lock file
Nov 22 16:34:02 kayttaja-VirtualBox snapd[937]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 22 16:34:02 kayttaja-VirtualBox snapd[937]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 22 16:34:02 kayttaja-VirtualBox snapd[937]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 22 16:34:02 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 22 16:44:03 kayttaja-VirtualBox snapd[937]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 22 16:44:03 kayttaja-VirtualBox snapd[937]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 22 16:44:18 kayttaja-VirtualBox snapd[937]: storehelpers.go:1019: cannot refresh snap "firefox": snap has no updates available
Nov 22 16:54:10 kayttaja-VirtualBox snapd[937]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 22 16:55:24 kayttaja-VirtualBox snapd[937]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"

snap changes
ID Status Spawn Ready Summary
54 Done today at 16:44 EET today at 16:44 EET Automaattisesti päivitä snap "firefox"

snap info firefox
name: firefox
summary: Mozilla Firefox web browser
publisher: Mozilla✓
store-url: https://snapcraft.io/firefox
contact: https://support.mozilla.org/kb/file-bug-report-or-feature-request-mozilla
license: unset
description: |
  Firefox is a powerful, extensible web browser with support for modern web application
  technologies.
commands:
  - firefox
  - firefox.geckodriver
snap-id: 3wdHCAVyZEmYsCMFDE9qt92UV8rC8Wdk
tracking: latest/stable
refresh-date: today at 16:44 EET
channels:
  latest/stable: 132.0.2-2 2024-11-12 (5273) 286MB -
  latest/candidate: 133.0-2 2024-11-22 (5...

[Mika Haaja (mika32)]

Below is the logs when firefox snap auto frefresh failed.

This time also the weekly update notification happened while the virtual machine was running. It also did not update firefox or thunderbird.

snap refresh --time
timer: 00:00~24:00/4
last: today at 16:05 EET
next: today at 19:16 EET

journalctl -u snapd
-- Boot 0977a1c49c844d9c99559173badec28e --
Nov 26 15:55:17 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: overlord.go:271: Acquiring state lock file
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: overlord.go:276: Acquired state lock file
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 26 15:55:18 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 26 16:05:18 kayttaja-VirtualBox snapd[940]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 26 16:05:19 kayttaja-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 26 16:38:47 kayttaja-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"

snap changes
no changes found

journalctl
Nov 26 16:05:17 kayttaja-VirtualBox anacron[911]: Job `cron.weekly' started
Nov 26 16:05:17 kayttaja-VirtualBox anacron[3262]: Updated timestamp for job `cron.weekly' to 2024-11-26
Nov 26 16:05:17 kayttaja-VirtualBox systemd[1]: anacron.service: Deactivated successfully.
Nov 26 16:05:17 kayttaja-VirtualBox anacron[911]: Job `cron.weekly' terminated
Nov 26 16:05:17 kayttaja-VirtualBox anacron[911]: Normal exit (2 jobs run)
Nov 26 16:05:18 kayttaja-VirtualBox snapd[940]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 26 16:05:19 kayttaja-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 26 16:10:17 kayttaja-VirtualBox systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Nov 26 16:10:17 kayttaja-VirtualBox systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories...
Nov 26 16:10:17 kayttaja-VirtualBox systemd[1]: sysstat-collect.service: Deactivated successfully.
Nov 26 16:10:17 kayttaja-VirtualBox systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Nov 26 16:10:17 kayttaja-VirtualBox systemd[1]: systemd-tmpfiles-clean.servi...

[Maciej Borzecki (maciek-borzecki)]

Hi,

The following information is repeated numerous times in the logs:

Nov 22 16:54:10 kayttaja-VirtualBox snapd[937]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"

Which means that snapd reached out to the snap store including the list of locally installed snap revisions in the request, and the snap store responded indicating no updates for said list of snaps. I suspect this has to do with phased rollouts, which are configurable by the snap publisher (Mozilla in this case). However, I neither have control nor visibility of that.

If your system is up very rarely, it will obviously miss the refresh window quite often and it probably ends up dragging somewhere around the tail of the snap release curve.

Note, you can try running manual `snap refresh firefox`, which behaves slightly differently and includes a request to the store to provide you the latest available revision.

For completeness, `snap info` fetches the information from the store, that's why the latest version of Firefox is present there.

[Mika Haaja (mika32)]

Hi.

Thanks for your reply.

I have noticed the same thing in the logs. But the first time when updates are available the logs are different. For example today.
Nov 26 16:38:47 user-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"

snapd sees the update, and I understand the snap application should go to the background system for download. And then install? Or is the phased rollouts in question in between this stage?

I have also noticed that the "snap changes" log clears itself when this problem appears.

I have noticed this problem in several installations, whose normal use has been similar to the use of this virtual machine. Even less often running. In this particular virtual machine, I have always waited after starting it for the automatic snap refresh to check for updates before shutting down the machine.

I also know how to update snaps manually. But not all users of these problematic installations know how to do that, and they rely on automatic updates. These are older people who mainly use their computers for banking and healthcare-related things.

I made this pug report because I can't figure out for myself at which stage the update gets stuck. And possibly make a proper bug report when the real reason is figured out. If the reason is phased rollouts, I think Mozilla wants to hear about it.

[Mika Haaja (mika32)]

Firefox was updated to version 133.0 today. 6 days after release. This update delay is perhaps somehow tolerable.

Sanapd was updated to version 2.66.1 on 30.11.2024 in this virtual machine. In another installation, where the snapd version is still 2.65.3, Firefox did not update yet today.
It seems that the snapd update might have fixed the update delay situation. I'm still monitoring the situation regarding that second installation.

I noticed that for some reason uprecords doesn't list all the virtual machine runs, even the longer ones, so I won't include it here.

journalctl -u snapd
-- Boot 0977a1c49c844d9c99559173badec28e --
Nov 26 15:55:17 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: overlord.go:271: Acquiring state lock file
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: overlord.go:276: Acquired state lock file
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: daemon.go:353: adjusting startup timeout by 1m25s (pessimistic estimate of 30s plus 5s per snap)
Nov 26 15:55:18 kayttaja-VirtualBox snapd[940]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
Nov 26 15:55:18 kayttaja-VirtualBox systemd[1]: Started snapd.service - Snap Daemon.
Nov 26 16:05:18 kayttaja-VirtualBox snapd[940]: devicemgr.go:2562: no NTP sync after 10m0s, trying auto-refresh anyway
Nov 26 16:05:19 kayttaja-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firefox", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Nov 26 16:38:47 kayttaja-VirtualBox snapd[940]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration"
Nov 26 17:41:48 kayttaja-VirtualBox snapd[940]: main.go:168: Exiting on terminated signal.
Nov 26 17:41:48 kayttaja-VirtualBox systemd[1]: Stopping snapd.service - Snap Daemon...
Nov 26 17:41:51 kayttaja-VirtualBox snapd[940]: overlord.go:515: Released state lock file
Nov 26 17:41:51 kayttaja-VirtualBox systemd[1]: snapd.service: Deactivated successfully.
Nov 26 17:41:51 kayttaja-VirtualBox systemd[1]: Stopped snapd.service - Snap Daemon.
Nov 26 17:41:51 kayttaja-VirtualBox systemd[1]: snapd.service: Consumed 1.438s CPU time, 40.0M memory peak, 0B memory swap peak.
-- Boot cca62760942c4a52b933fe21e5fa42ef --
Nov 26 17:41:59 kayttaja-VirtualBox systemd[1]: Starting snapd.service - Snap Daemon...
Nov 26 17:41:59 kayttaja-VirtualBox snapd[934]: overlord.go:271: Acquiring state lock file
Nov 26 17:41:59 kayttaja-VirtualBox snapd[934]: overlord.go:276: Acquired state lock file
Nov 26 17:41:59 kayttaja-VirtualBox snapd[934]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-49-generic.
Nov 26 17:41:59 kayttaja-VirtualBox snapd[934]: daemon.go:353: adjusting startup time...

[Mika Haaja (mika32)]

Another machine updated to firefox version 133.0 today. 12 days after release. This machine has also been powered on daily beyond the snap refresh check. Now when I checked it, snapd had updated to version 2.66.1 on the 26th of last month. But it also has the deb version installed, which is still version 2.65.3. This confused me into looking at the wrong version.

I updated the bug description to be more descriptive of the problem.

snap refresh --time
timer: 00:00~24:00/4
last: tänään 08:08 EET
next: n/a

snap changes
Tunniste Tila Muodostettu Valmis Yhteenveto
321 Done 2 days ago, at 11:15 EET 2 days ago, at 11:15 EET Automaattisesti päivitä snap "thunderbird"
322 Done tänään 08:08 EET tänään 08:09 EET Automaattisesti päivitä snap "firefox"

snap info firefox
name: firefox
summary: Mozilla Firefox web browser
publisher: Mozilla✓
store-url: https://snapcraft.io/firefox
contact: https://support.mozilla.org/kb/file-bug-report-or-feature-request-mozilla
license: unset
description: |
  Firefox is a powerful, extensible web browser with support for modern web
  application technologies.
commands:
  - firefox
  - firefox.geckodriver
snap-id: 3wdHCAVyZEmYsCMFDE9qt92UV8rC8Wdk
tracking: latest/stable
refresh-date: tänään 08:09 EET
channels:
  latest/stable: 133.0-2 2024-11-26 (5361) 287MB -
  latest/candidate: 133.0-2 2024-12-06 (5423) 287MB -
  latest/beta: 134.0b7-1 2024-12-07 (5426) 289MB -
  latest/edge: 135.0a1 2024-12-07 (5430) 294MB -
  esr/stable: 128.5.1esr-1 2024-11-29 (5385) 283MB -
  esr/candidate: 128.5.1esr-1 2024-11-29 (5385) 283MB -
  esr/beta: ↑
  esr/edge: ↑
installed: 133.0-2 (5361) 287MB -

-- Boot bcd5e7abe4a6402f9d4b5ee642872786 --
marras 26 17:59:57 D1402IA snapd[1404]: overlord.go:271: Acquiring state lock file
marras 26 17:59:57 D1402IA snapd[1404]: overlord.go:276: Acquired state lock file
marras 26 17:59:57 D1402IA snapd[1404]: daemon.go:250: started snapd/2.65.3+24.04 (series 16; classic) ubuntu/24.04 (amd64) linux/6.8.0-48-generic.
marras 26 17:59:57 D1402IA snapd[1404]: daemon.go:353: adjusting startup timeout by 2m15s (pessimistic estimate of 30s plus 5s per snap)
marras 26 17:59:57 D1402IA snapd[1404]: backends.go:58: AppArmor status: apparmor is enabled and all features are available
marras 26 17:59:56 D1402IA systemd[1]: Starting snapd.service - Snap Daemon...
marras 26 17:59:57 D1402IA systemd[1]: Started snapd.service - Snap Daemon.
marras 26 18:00:32 D1402IA snapd[1404]: storehelpers.go:1019: cannot refresh: snap has no updates available: "bare", "core", "core18", "core20", "core22", "cups", "firefox", "firmware-updater", "freecad", "gimp", "gnome-3-28-1804", "gnome-3-38-2004", "gnome-42-2204", "gtk-common-themes", "gtk2-common-themes", "hunspell-dictionaries-1-7-2004", "kde-frameworks-5-99-qt-5-15-7-core20", "kf5-5-108-qt-5-15-10-core22", "snap-store", "thunderbird"
marras 26 18:00:38 D1402IA snapd[1404]: daemon.go:548: gracefully waiting for running hooks
marras 26 18:00:38...

[Maciej Borzecki (maciek-borzecki)]

Hi,

Can you elaborate on what is the desired behavior as you see it? As I commented before, the store reports no updates, most likely due to how phased rollouts are configured by the publisher (Mozilla). To complicate this further, snapd only really has a chance to attempt refresh just once during startup, as your VMs are shut down after a couple of hours. There are various knobs to control updates, see https://snapcraft.io/docs/managing-updates but again, those are client side only (snapd), and have no effect on the store. Perhaps you could try change the schedule one that will try to refresh more often. Ultimately, if you are concerned about not receiving firefox updates in a timely manner, consider running `snap refresh firefox` manually.

[Mika Haaja (mika32)]

Hi.

Thanks for your reply.

I think the maximum interval between installing security updates from a release is a few days. This is also recommended by the Finnish national cyber security centre, critical updates should be installed at least days, not weeks.

In cases where the computer has not been on for days, updates should be installed during the first automatic snap refresh. This should not be affected by how many hours the computer is on, or how often the automatic snap refresh is performed per day. If the application is open during the update, the user should be notified of the availability of the update, as is currently the case. And the user can then decide whether to update immediately or later.

I noted in my previous answer that all of these installations where this update delay has occurred are not machines that I use.

To clarify, phased rollouts are progressive releases, so this documentation applies to that? https://snapcraft.io/docs/progressive-releases

But to solve the bug itself.
The problem I have with solving this is that I don't know how automatic snap refresh should work in the background, and at what point in the update chain phased rollouts enter. I haven't found any documentation on how this chain works.

The store (App Center) reports Firefox updates are available when this problem occurs, but the updates can only be installed manually. Firefox updates don't install automatically right away, only with a long delay.

Another problem I have with solving this is that the logs don't tell me anything more specific, especially what's happening in the background. At first I thought that apparmor was blocking Firefox's automatic update, but apparently this log message is normal.
audit: type=1400 audit(1722155142.985:282): apparmor="DENIED" operation="open" class="file" profile="snap-update-ns.firefox" name="/proc/9393/maps" pid=9393 comm="5" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
A similar log message is also in this old bug: https://bugs.launchpad.net/ubuntu/+source/firefox/+bug/1993359

Thanks for your help.

[Mika Haaja (mika32)]

Today I got to see one computer with this update problem. I don't normally use this computer myself. Ubuntu 24.04 fresh install installed on June 9th. Firefox was version 132.0.2. The computer has been started 10 times since Firefox 133.0 was released. Automatic snap refresh has been performed 8 times during these 17 days. All other snap applications were up to date.

I ran "snap refresh firefox" manually on this computer.

As I recall, I last ran Firefox updates on this computer manually 23 days ago. Even then, the Firefox update was about a week late.

I don't have any logs to provide, as it's not my computer.

The use of this computer has been very much the same, where I have encountered this Firefox update problem in several installations. In other words, very normal computer use for an older person who doesn't use the computer all the time.
The use of the computer is based solely on taking care of some necessary thing.

[Pirouette Cacahuète (lissyx)]

I checked with release managers and we dont use phasing for snap firefox, so it's not the root cause here for the store to not return an update

[Mika Haaja (mika32)]

Hi.
Thank you for your help.

Firefox just updated on the virtual machine 133.0.3 for 4 days from the release.
I noticed a line in the logs that did not appear when the update has failed.
Dec 14:14:47:47: Use-Virtualbox Systemd [1]: Reloading Requested from Client Pid 3508 ('Systemctl') (Unit snapd.service) ...

The virtual machine has been on daily.

snap changes
ID Status Spawn Ready Summary
60 Done today at 21:14 EET today at 21:14 EET Automaattisesti päivitä snap "firefox"

snap refresh --time
timer: 00:00~24:00/4
last: today at 21:14 EET
next: tomorrow at 00:03 EET

snap info firefox
name: firefox
summary: Mozilla Firefox web browser
publisher: Mozilla✓
store-url: https://snapcraft.io/firefox
contact: https://support.mozilla.org/kb/file-bug-report-or-feature-request-mozilla
license: unset
description: |
  Firefox is a powerful, extensible web browser with support for modern web
  application technologies.
commands:
  - firefox
  - firefox.geckodriver
snap-id: 3wdHCAVyZEmYsCMFDE9qt92UV8rC8Wdk
tracking: latest/stable
refresh-date: today at 21:14 EET
channels:
  latest/stable: 133.0.3-1 2024-12-10 (5437) 286MB -
  latest/candidate: 133.0.3-1 2024-12-10 (5437) 286MB -
  latest/beta: 134.0b10-1 2024-12-13 (5460) 287MB -
  latest/edge: 135.0a1 2024-12-14 (5463) 294MB -
  esr/stable: 128.5.2esr-1 2024-12-12 (5452) 283MB -
  esr/candidate: 128.5.2esr-1 2024-12-12 (5452) 283MB -
  esr/beta: ↑
  esr/edge: ↑
installed: 133.0.3-1 (5437) 286MB -

Journalctl
Dec 14 21:14:41 kayttaja-VirtualBox snapd[996]: devicemgr.go:2566: no NTP sync after 10m0s, trying auto-refresh anyway
Dec 14 21:14:41 kayttaja-VirtualBox snapd[996]: storehelpers.go:1044: cannot refresh: snap has no updates available: "bare", "core", "core22", "firmware-updater", "gnome-42-2204", "gtk-common-themes", "snap-store", "snapd", "snapd-desktop-integration", "thunderbird"
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Reloading requested from client PID 3508 ('systemctl') (unit snapd.service)...
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Reloading...
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Reloading finished in 204 ms.
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Cannot find unit for notify message of PID 3508, ignoring.
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Mounting snap-firefox-5437.mount - Mount unit for firefox, revision 5437...
Dec 14 21:14:47 kayttaja-VirtualBox kernel: loop18: detected capacity change from 0 to 560488
Dec 14 21:14:47 kayttaja-VirtualBox systemd[1]: Mounted snap-firefox-5437.mount - Mount unit for firefox, revision 5437.
Dec 14 21:14:48 kayttaja-VirtualBox kernel: audit: type=1400 audit(1734203688.761:178): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping...

[Mika Haaja (mika32)]

I have been following this automatic update problem on several computers for some time now.
3 virtual machines named "24.04", "Firefox open", " Firefox closed". In addition, two normal installations, a laptop and a Nas.
The virtual machines and the laptop have been powered on over the automatic snap refresh almost daily. The Nas is powered on 24/7.
On the "Firefox open" machine, I have always opened Firefox first after starting the machine, so Firefox has always been open during the automatic snap refresh.
On the "Firefox closed" machine, Firefox has always been closed.

I have noticed that Firefox being open has no effect on the update delay. I have not found any common factor for the update delays. I have now also noticed the same problem with Thunderbird, but it is not as bad as the Firefox update delay. That is why I also updated the bug description.

The logs still have not revealed anything useful, so I will not add them.

Are these phased rollouts defined on Canonical's side perhaps? But the same update delay is also occurring on a machine that is powered on 24/7.

As an additional note, I did two new installations yesterday. One of the computers updated Firefox the same day, and the other computer's Firefox is still at version 129.0.2. The only difference between the installations is that I removed Thunderbird from the computer after the installation, where Firefox automatically updated to the latest version.

On this computer, where Firefox has not yet been updated, Thunderbird is also still not updated. Automatic snap refresh has gone through four times since the installation on this computer.

Below is the information I have collected about the updates. I haven't listed all the other snap updates because they haven't had any update issues.

Thunderbird 128.6.0esr-1 published 19.12-24
19.12-24 Updated to a laptop. Not to three virtual machines.
20.12-24 updated to "Firefox open" machine.
22.12-24 "24.04" was updated, "Firefox closed" was not updated.
23.12-24 Not updated.
25.12-24 Not updated.
26.12-24 Not updated.
27.12-24 Not updated.
29.12-24 Not updated.
30.12-24 Not updated.
31.12-24 Not updated.
2.1-25 Not updated.
3.1-25 Not updated.
4.1-25 Not updated.
5.1-25 "Firefox closed" machine updated.

Firefox 134.0 published 7.1-25
7.1-25 Not updated.
8.1-25 Not updated.
9.1-25 Not updated. Snapd was updated to version 2.67 on the "24.04" machine, without it being a release? Snapd was also updated on Nas.
10.1-25 Not updated. Snapd was updated to version 2.67 on the "Firefox open" machine.
11.1-25 Not updated. Snapd updated to version 2.67 with "Firefox closed" and on a laptop.
12.1-25 Not updated.
13.1-25 Not updated.
Firefox 134.0.1 published 14.1-25
14.1-25 Not updated.
15.1-25 Not updated.
16.1-25 Not updated.
17.1-25 Not updated.
18.1-25 Not updated.
19.1-25 Not updated.
20.1-25 Not updated.
21.1-25 Not updated. The laptop's snap GIMP was updated. GIMP was released the same day. Nas announced a Firefox update. Firefox was updated to version 134.0.1 after the shutdown, when 134.0.2 had already been released this evening.
Firefox 134.0.2 published 21.1-25
22.1-25 Firefox updated directly from version 133.0.3 to version...

[Mika Haaja (mika32)]

Laptop Firefox was updated finaly yesterday.

Continuation of the previous update listing.
Thunderbird 128.6.1esr-3 published 27.1-25
28.1-25 Not updated.
29.1-25 Not updated.
30.1-25 Not updated. "Firefox open" Thunderbird was updated to 128.6.1esr-3 version.
31.1-25 Not updated. "Firefox closed" and Laptop Thunderbird was updated to 128.6.1esr-3 version.
1.2-25 Not updated.
2.2-25 Not updated. "24.04" Thunderbird was updated to 128.6.1esr-3 version.
3.2-25 Laptop Firefox was updated directly from 133.0.3 to 134.0.2. 27 days after the release of Firefox 134.0.
Firefox 135.0 published 4.2-25
4.2-25 "24.04" virtual machine's Firefox was updated to 135.0 version. Not for others.

New Ubuntu 24.04.1 installation. Installed 26.1.25, Firefox 129.0.2
26.1-25 Not updated.
27.1-25 Not updated.
28.1-25 Not updated.
29.1-25 Not updated.
30.1-25 Not updated.
31.1-25 Not updated. Thunderbird was updated to 128.6.1esr-3 version.
1.2-25 Not updated.
2.2-25 Not updated.
3.2-25 Not updated.
4.2-25 Not updated.

[Przemysław Suliga (suligap)]

> Are these phased rollouts defined on Canonical's side perhaps?
> But the same update delay is also occurring on a machine that
> is powered on 24/7.

The Snap Store does indeed have an additional mechanism that lets it protect the infrastructure from being overwhelmed by releases of high profile snaps. For popular snaps like firefox and thunderbird which are not progressively released this can result in bigger delays for receiving automatic updates than it would in case of a proper progressive release. It's also not deterministic which can explain the observed behavior.

[Mika Haaja (mika32)]

Hi.
Thank you for your help.

That sounds like the exact reason. And I can understand the reason behind this mechanism.
Could this also explain why I have often noticed that the last unupdated machines are updated just before the next release moves to the release channel?

The only problem is this really long delay with these automatic updates. Is it possible to shorten this time somehow?

Maybe something has already happened. 3/6 installations I've monitored already updated Firefox to version 135.0.

Edit. Nas also announced an update just after writing this. So the updates are currently 4/6.

[Przemysław Suliga (suligap)]

Hi, no problem.

> Could this also explain why I have often noticed that the last
> unupdated machines are updated just before the next release moves
> to the release channel?

That's not obviously related, no.

We have some levers that can be adjusted/tuned to make the delays shorter and we'll keep this report and feedback in mind. Thanks a lot for raising this.

[Mika Haaja (mika32)]

Hi.

> That's not obviously related, no.

It's probably just a coincidence then.

> We have some levers that can be adjusted/tuned to make the delays shorter and we'll keep this report and feedback in
> mind. Thanks a lot for raising this.

That sounds good. Two installations I've monitored, haven't updated yet. I can monitor the situation, and let you know when those are up to date.
No problem. The main thing is, the situation would get better.
Thanks a lot.

[Przemysław Suliga (suligap)]

This is both expected and not ideal behavior. So changing this to confirmed for now to have a place where we can track any related improvements we can do.

[Mika Haaja (mika32)]

Hi.
I've tested the latest machines for updating. I'm reporting on this a little late because I wanted to see how the updates went on the other problematic computers I mentioned earlier. I think the update situation seems much better now in at least on computers that are powered on almoust daily.

Continuation of the previous update listings.
Virtual machines.
5.2-25 Not updated.
6.2-25 "Firefox closed" and Laptop Firefox was updated to 135.0 version. "Firefox open" and Nas not yet updated.
In the evening Nas announced a Firefox update. Firefox was updated to version 135.0 after the shutdown.
7.2-25 Not updated.
8.2-25 Not updated.
10.2-25 "Firefox open" announced a Firefox update. Firefox was updated to version 135.0 after the shutdown.

New Ubuntu 24.04.1 installation.
5.2-25 Not updated.
6.2-25 Not updated.
7.2-25 Not updated.
8.2-25 Firefox was updated from 129.0.2 to 135.0 version.

I also rolled back two VMs to December.
10.2-25 First snap auto refresh. In "Firefox closed", updated four snap applications. One of which was Thunderbird. And in the "Firefox open", three snap applications. Firefox did not update in either VM.
10.2-25 Second snap auto refresh updated more snap apps in "Firefox closed" VM. The other one didn't make more auto snap updates.
11.2-25 Third snap auto refresh, didn't make more snap updates in either VM.

So this would suggest that the problem still affects computers that are rarely powered on.

>This is both expected and not ideal behavior. So changing this to confirmed for now to have a place where
> we can track any related improvements we can do.

Thank you for your help. I appreciate it.
If there is still a need to test something, I thought I would keep these test virtual machines for a while.