Cant install firefox update - Mount snap "firefox" (3600) (cannot find required base "core22")

[Jānis Kangarooo]

Clean 22.04.3 Kubuntu install with all updates in installation checked to install
Turns out firefox is not latest updated

Cant install firefox update - Mount snap "firefox" (3600) (cannot find required base "core22")

sudo snap refresh
[sudo] password for kng:
2024-01-04T20:58:50+02:00 INFO Waiting for automatic snapd restart...
error: cannot perform the following tasks:
- Mount snap "firefox" (3600) (cannot find required base "core22")

[Jānis Kangarooo (kangarooo)]

Doing again
sudo snap refresh
it installed
But base users wont notice and wont know that it didnt work

[Sergio Cazzolato (sergio-j-cazzolato)]

Hi, thanks for raising this.

It could be caused by some temporal issue in the snaps store. Could you please share the journal log for snapd unit please `sudo journalctl -u snapd`.

[Pirouette Cacahuète (lissyx)]

This is also reproducing intermittently on TaskCluster as seen on https://bugzilla.mozilla.org/show_bug.cgi?id=1873359, unfortunately collecting journalctl there is more complicated.

[Pirouette Cacahuète (lissyx)]

[task 2024-01-09T06:40:24.047Z] executing ['bash', '-cx', 'export TASKCLUSTER_ROOT_DIR=$PWD && cd $MOZ_FETCHES_DIR/ && (./tests.sh || sudo journalctl -u snapd --boot --no-pager)']
[task 2024-01-09T06:40:24.052Z] + export TASKCLUSTER_ROOT_DIR=/home/ubuntu/tasks/task_170478222076275
[task 2024-01-09T06:40:24.052Z] + TASKCLUSTER_ROOT_DIR=/home/ubuntu/tasks/task_170478222076275
[task 2024-01-09T06:40:24.052Z] + cd /home/ubuntu/tasks/task_170478222076275/fetches/
[task 2024-01-09T06:40:24.054Z] + ./tests.sh
[task 2024-01-09T06:40:24.057Z] + pwd
[task 2024-01-09T06:40:24.057Z] /home/ubuntu/tasks/task_170478222076275/fetches
[task 2024-01-09T06:40:24.058Z] + ARTIFACT_DIR=/home/ubuntu/tasks/task_170478222076275/builds/worker/artifacts/
[task 2024-01-09T06:40:24.058Z] + mkdir -p /home/ubuntu/tasks/task_170478222076275/builds/worker/artifacts/
[task 2024-01-09T06:40:24.061Z] + sudo snap refresh
[task 2024-01-09T06:40:53.841Z] 2024-01-09T06:40:45Z INFO Waiting for automatic snapd restart...
[task 2024-01-09T06:41:44.558Z] error: cannot perform the following tasks:
[task 2024-01-09T06:41:44.559Z] - Mount snap "firefox" (3600) (cannot find required base "core22")
[task 2024-01-09T06:41:44.565Z] + sudo journalctl -u snapd --boot --no-pager
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:08 ubuntu-2204 systemd[1]: Starting Snap Daemon...
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:16 ubuntu-2204 snapd[870]: overlord.go:272: Acquiring state lock file
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:16 ubuntu-2204 snapd[870]: overlord.go:277: Acquired state lock file
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:17 ubuntu-2204 snapd[870]: daemon.go:247: started snapd/2.60.3 (series 16; classic) ubuntu/22.04 (amd64) linux/5.15.0-70-generic.
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:17 ubuntu-2204 snapd[870]: daemon.go:340: adjusting startup timeout by 1m5s (pessimistic estimate of 30s plus 5s per snap)
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:18 ubuntu-2204 snapd[870]: backends.go:58: AppArmor status: apparmor is enabled and all features are available (using snapd provided apparmor_parser)
[task 2024-01-09T06:41:44.677Z] Jan 09 06:36:19 ubuntu-2204 systemd[1]: Started Snap Daemon.
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:26 ubuntu-2204 snapd[870]: storehelpers.go:773: cannot refresh: snap has no updates available: "bare", "gtk-common-themes", "lxd"
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:26 ubuntu-2204 snapd[870]: storehelpers.go:773: cannot refresh: snap has no updates available: "bare", "firefox", "gtk-common-themes", "lxd", "snapd"
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:26 ubuntu-2204 snapd[870]: snapstate.go:1883: cannot refresh snap "core20": snap "core20" has "refresh-snap" change in progress
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:26 ubuntu-2204 snapd[870]: snapstate.go:1883: cannot refresh snap "gnome-3-38-2004": snap "gnome-3-38-2004" has "refresh-snap" change in progress
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:43 ubuntu-2204 snapd[870]: daemon.go:521: gracefully waiting for running hooks
[task 2024-01-09T06:41:44.677Z] Jan 09 06:40:43 ubuntu-2204 snapd[870]: daemon.go:523: done waiting for running hooks
[task 2024-01-09T06:41...

[Pirouette Cacahuète (lissyx)]

The issue is still there ; I've been suggested to post on the snapcraft forum but so far not more traction.
I was also pointed at https://status.snapcraft.io/ but I dont really see matching issues although there are a few mentions of the serch API being down.

Can we get more logs somehow ? The ones I extracted are not super helpful.

[Pirouette Cacahuète (lissyx)]

I'm wondering if it is really a snap store issue, I see ` latest/stable: 2.61.1 2024-01-04 (20671) 42MB -`
So `snapd` 2.61.1 shipped on jan 4th and sherrifs also reported it started to fail the same day: https://bugzilla.mozilla.org/show_bug.cgi?id=1873359#c1

[Pirouette Cacahuète (lissyx)]

I have been able to reproduce with 2.60.3 as well. It rather looks like when I issue several concurrent tasks this triggers the problem. Server-side throttling or limitation ?

[Ernest Lotter (ernestl)]

Hi, I would like to inspect in more details the tasks related to the change for the case that failed.

Can someone who please provide the output of:
1) snap changes
2) snap debug state /var/lib/snapd/state.json --change=<failed change>`

[Pirouette Cacahuète (lissyx)]

got some repros: https://firefox-ci-tc.services.mozilla.com/tasks/AkV2CefsRVy4tI_n5Ebs6A/runs/0/logs/public/logs/live_backing.log (see failures in the task group https://firefox-ci-tc.services.mozilla.com/tasks/groups/bNrPJbgVSaem6_Xlga4iFQ)

[Pirouette Cacahuète (lissyx)]

2024-01-18T13:08:54Z INFO Waiting for automatic snapd restart...
error: cannot perform the following tasks:
- Mount snap "firefox" (3626) (cannot find required base "core22")
1
Change ID 10
Lanes ID Status Spawn Ready Kind Summary
0 336 Done today at 12:03 UTC today at 12:04 UTC check-rerefresh Handling re-refresh of "gnome-3-38-2004" as needed
13 315 Done today at 12:03 UTC today at 12:03 UTC prerequisites Ensure prerequisites for "gnome-3-38-2004" are available
13 316 Done today at 12:03 UTC today at 12:04 UTC download-snap Download snap "gnome-3-38-2004" (143) from channel "latest/stable"
13 317 Done today at 12:03 UTC today at 12:04 UTC validate-snap Fetch and check assertions for snap "gnome-3-38-2004" (143)
13 318 Done today at 12:03 UTC today at 12:04 UTC mount-snap Mount snap "gnome-3-38-2004" (143)
13 319 Done today at 12:03 UTC today at 12:04 UTC run-hook Run pre-refresh hook of "gnome-3-38-2004" snap if present
13 320 Done today at 12:03 UTC today at 12:04 UTC stop-snap-services Stop snap "gnome-3-38-2004" services
13 321 Done today at 12:03 UTC today at 12:04 UTC remove-aliases Remove aliases for snap "gnome-3-38-2004"
13 322 Done today at 12:03 UTC today at 12:04 UTC unlink-current-snap Make current revision for snap "gnome-3-38-2004" unavailable
13 323 Done today at 12:03 UTC today at 12:04 UTC copy-snap-data Copy snap "gnome-3-38-2004" data
13 324 Done today at 12:03 UTC today at 12:04 UTC setup-profiles Setup snap "gnome-3-38-2004" (143) security profiles
13 325 Done today at 12:03 UTC today at 12:04 UTC link-snap Make snap "gnome-3-38-2004" (143) available to the system
13 326 Done today at 12:03 UTC today at 12:04 UTC auto-connect Automatically connect eligible plugs and slots of snap "gnome-3-38-2004"
13 327 Done today at 12:03 UTC today at 12:04 UTC set-auto-aliases Set automatic aliases for snap "gnome-3-38-2004"
13 328 Done today at 12:03 UTC today at 12:04 UTC setup-aliases Setup snap "gnome-3-38-2004" aliases
13 329 Done today at 12:03 UTC today at 12:04 UTC run-hook Run post-refresh hook of "gnome-3-38-2004" snap if present
13 330 Done today at 12:03 UTC today at 12:04 UTC start-snap-services Start snap "gnome-3-38-2004" (143) services
13 331 Done today at 12:03 UTC today at 12:04 UTC clear-snap Remove data for snap "gnome-3-38-2004" (137)
13 332 Done today at 12:03 UTC today at 12:04 UTC discard-snap Remove snap "gnome-3-38-2004" (137) from the system
13 333 Done today at 12:03 UTC today at 12:04 UTC cleanup Clean up "gnome-3-38-2004" (143) install
13 334 Done today at 12:03 UTC today at 12:04 UTC run-hook Run configure hook of "gnome-3-38-2004" snap if present
13 335 Done today at 12:03 UTC today at 12:04 UTC run-hook Run health check of "gnome-3-38-2004" snap
---
336 Handling re-refresh ...

[Ernest Lotter (ernestl)]

Thanks for the additional info. Looks same as my reproducer.

Simplest reproducer found: Refresh both snapd and firefox

-----------------------
`snap list`
Name Version Rev Tracking Publisher Notes
bare 1.0 5 latest/stable canonical✓ base
core20 20231123 2105 latest/stable canonical✓ base
firefox 116.0.2-1 2987 latest/stable mozilla✓ -
gnome-3-38-2004 0+git.efb213a 143 latest/stable/… canonical✓ -
gtk-common-themes 0.1-81-g442e511 1535 latest/stable/… canonical✓ -
snapd 2.59.5 19457 latest/stable canonical✓ snapd
-------------------------

`snap refresh snapd firefox`

What should happen is that firstly snapd refreshes and restarts, then firefox starts with checking prerequisite snaps which should identify needing `core22` and `gnome-42-2204`. Additional tasks should be injected to install these. If there is an issue with injecting tasks to install the prerequisites, this should lead to error that puts all dependant tasks in the change on hold (except if it can be undone).

The problem seems to be that the firefox prerequisite step fails to inject tasks to install `core22` and `gnome-42-2204`, but seemingly without error, and so the task runner continues with the next firefox installation steps and fails on mount because core22 is indeed missing.

- I do not see this behaviour when only updating firefox with either snapd 2.59.5 or 2.61.1 running.
- This really does not look like a snap store issue.

[Ernest Lotter (ernestl)]

Found the root cause:

(1) snapd prior to 2.60.3 DOES NOT insert snap target version information into the update install setup

(2) and in 2.60.3 and later conflict detection was added to detect if snapd is downgraded within the same change where the assumption is made that target version info of "" MEANS DOWNGRADE

(3) And when this all happens in the same change, the error is not reported and the prerequisite install steps silently skipped

As a result, in this specific case, we do not see prerequisite install steps as expected for either `gnome-42-2204` or `core22` and also not error, so the firefox install continues and only error when mount step correctly does not find the base `core22` that should have been installed as prerequisite.

Working on solution to:
(1) at least indicate whenever injecting tasks for prerequisites are skipped without error
(2) prevent this problem when refreshing from snapd prior to 2.60.3 to after

[Pirouette Cacahuète (lissyx)]

Would it suggest also that if we have already an updated snapd version we wont have problem? Our CI will get new wayland images soon, so they should be baked with newer version of snapd. If that's the case then I could ask for an update of the existing ones.

[Ernest Lotter (ernestl)]

Yes, the code and my testing agree that >= 2.60.3 does not produce this issue.

I am working on improvements as well, to be more explicit when a conflict results in skipping of installation step(s), and also to ensure the conflict detection criteria does not impact unintended scenarios.

[Zygmunt Krynicki (zyga)]

I've picked up this bug and I'll start by adding a test reproducing the case so that we can explore one of the few ways the team have come up to solve it.

[Zygmunt Krynicki (zyga)]

This is now fixed by https://github.com/snapcore/snapd/pull/13589

[Zygmunt Krynicki (zyga)]

This has been merged in https://github.com/snapcore/snapd/pull/13589 and will be released in 2.61.2