snapd service never completes on boot off focal cloudimg

[Louis Bouchard]

When starting a VM using focal-server-cloudimg-amd64-disk-kvm.img, the snapd service never terminates during boot.

It reports the following on the console :
[FAILED] Failed to mount Mount unit for snapd, revision 7264.
See 'systemctl status snap-snapd-7264.mount' for details.
         Mounting Mount unit for snapd, revision 7264...
[FAILED] Failed to mount Mount unit for snapd, revision 7264.
See 'systemctl status snap-snapd-7264.mount' for details.

here is the output of systemctl status :

root@focal-cloudinit:~# systemctl status snap-snapd-7264.mount
● snap-snapd-7264.mount
     Loaded: not-found (Reason: Unit snap-snapd-7264.mount not found.)
     Active: failed (Result: exit-code) since Wed 2020-04-22 12:53:47 UTC; 1min 51s ago

Apr 22 12:53:47 focal-cloudinit systemd[1]: Mounting Mount unit for snapd, revision 7264...
Apr 22 12:53:47 focal-cloudinit mount[948]: mount: /snap/snapd/7264: mount failed: Operation not permitted.
Apr 22 12:53:47 focal-cloudinit systemd[1]: snap-snapd-7264.mount: Mount process exited, code=exited, status=1/FAILURE
Apr 22 12:53:47 focal-cloudinit systemd[1]: snap-snapd-7264.mount: Failed with result 'exit-code'.
Apr 22 12:53:47 focal-cloudinit systemd[1]: Failed to mount Mount unit for snapd, revision 7264.

journalctl has the following info :

root@focal-cloudinit:~# systemctl status snap-snapd-7264.mount
● snap-snapd-7264.mount
     Loaded: not-found (Reason: Unit snap-snapd-7264.mount not found.)
     Active: failed (Result: exit-code) since Wed 2020-04-22 12:53:47 UTC; 1min 51s ago

Apr 22 12:53:47 focal-cloudinit systemd[1]: Mounting Mount unit for snapd, revision 7264...
Apr 22 12:53:47 focal-cloudinit mount[948]: mount: /snap/snapd/7264: mount failed: Operation not permitted.
Apr 22 12:53:47 focal-cloudinit systemd[1]: snap-snapd-7264.mount: Mount process exited, code=exited, status=1/FAILURE
Apr 22 12:53:47 focal-cloudinit systemd[1]: snap-snapd-7264.mount: Failed with result 'exit-code'.
Apr 22 12:53:47 focal-cloudinit systemd[1]: Failed to mount Mount unit for snapd, revision 7264.
root@focal-cloudinit:~# journalctl -o short-precise -u snapd
-- Logs begin at Wed 2020-04-22 12:53:19 UTC, end at Wed 2020-04-22 12:55:26 UTC. --
Apr 22 12:53:34.403192 focal-cloudinit systemd[1]: Starting Snap Daemon...
Apr 22 12:53:35.838680 focal-cloudinit snapd[471]: AppArmor status: apparmor is enabled and all features are available
Apr 22 12:53:35.951309 focal-cloudinit snapd[471]: daemon.go:343: started snapd/2.44.3+20.04 (series 16; classic) ubuntu/20.04 (amd64) linu>
Apr 22 12:53:35.969592 focal-cloudinit snapd[471]: main.go:129: system does not fully support snapd: cannot mount squashfs image using "squ>
Apr 22 12:53:35.969592 focal-cloudinit snapd[471]: daemon.go:436: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per>
Apr 22 12:53:36.145500 focal-cloudinit snapd[471]: helpers.go:105: error trying to compare the snap system key: system-key missing on disk
Apr 22 12:53:36.206822 focal-cloudinit systemd[1]: Started Snap Daemon.
Apr 22 12:53:42.697450 focal-cloudinit systemd[1]: snapd.service: Got notification message from PID 815, but reception only permitted for m>
Apr 22 12:53:44.393863 focal-cloudinit snapd[471]: handlers.go:495: Reported install problem for "snapd" as 4c06c57a-8498-11ea-a2d7-fa163e6>
Apr 22 12:53:47.602056 focal-cloudinit systemd[1]: snapd.service: Got notification message from PID 947, but reception only permitted for m>
Apr 22 12:53:48.057024 focal-cloudinit snapd[471]: handlers.go:495: Reported install problem for "snapd" as already-reported

As a side effect, this blocks execution of the cloud-config & cloud-final services that depend on it.

[Dan Watkins (oddbloke)]

As snapd (still, see bug 1796987) doesn't log to Ubuntu's logging utility, you'll also need to gather information from their logging system. Run `snap changes` to get the ID of the change that failed, then run `snap change $id` to retrieve the logs from wherever snapd stores them.

[Louis Bouchard (louis)]

Here is Dan's requested data :

root@focal-cloudinit:~# snap changes
ID Status Spawn Ready Summary
1 Error today at 13:37 UTC today at 13:37 UTC Initialize system state
2 Done today at 13:37 UTC today at 13:37 UTC Initialize device
3 Error today at 13:37 UTC today at 13:37 UTC Initialize system state
4 Error today at 13:42 UTC today at 13:42 UTC Initialize system state

root@focal-cloudinit:~# snap change 4
Status Spawn Ready Summary
Done today at 13:42 UTC today at 13:42 UTC Ensure prerequisites for "snapd" are available
Undone today at 13:42 UTC today at 13:42 UTC Prepare snap "/var/lib/snapd/seed/snaps/snapd_7264.snap" (7264)
Error today at 13:42 UTC today at 13:42 UTC Mount snap "snapd" (7264)
Hold today at 13:42 UTC today at 13:42 UTC Copy snap "snapd" data
Hold today at 13:42 UTC today at 13:42 UTC Setup snap "snapd" (7264) security profiles
Hold today at 13:42 UTC today at 13:42 UTC Make snap "snapd" (7264) available to the system
Hold today at 13:42 UTC today at 13:42 UTC Automatically connect eligible plugs and slots of snap "snapd"
Hold today at 13:42 UTC today at 13:42 UTC Set automatic aliases for snap "snapd"
Hold today at 13:42 UTC today at 13:42 UTC Setup snap "snapd" aliases
Hold today at 13:42 UTC today at 13:42 UTC Run install hook of "snapd" snap if present
Hold today at 13:42 UTC today at 13:42 UTC Start snap "snapd" (7264) services
Hold today at 13:42 UTC today at 13:42 UTC Run configure hook of "core" snap if present
Hold today at 13:42 UTC today at 13:42 UTC Ensure prerequisites for "core18" are available
Hold today at 13:42 UTC today at 13:42 UTC Prepare snap "/var/lib/snapd/seed/snaps/core18_1705.snap" (1705)
Hold today at 13:42 UTC today at 13:42 UTC Mount snap "core18" (1705)
Hold today at 13:42 UTC today at 13:42 UTC Copy snap "core18" data
Hold today at 13:42 UTC today at 13:42 UTC Setup snap "core18" (1705) security profiles
Hold today at 13:42 UTC today at 13:42 UTC Make snap "core18" (1705) available to the system
Hold today at 13:42 UTC today at 13:42 UTC Automatically connect eligible plugs and slots of snap "core18"
Hold today at 13:42 UTC today at 13:42 UTC Set automatic aliases for snap "core18"
Hold today at 13:42 UTC today at 13:42 UTC Setup snap "core18" aliases
Hold today at 13:42 UTC today at 13:42 UTC Run install hook of "core18" snap if present
Hold today at 13:42 UTC today at 13:42 UTC Start snap "core18" (1705) services
Hold today at 13:42 UTC today at 13:42 UTC Run health check of "core18" snap
Hold today at 13:42 UTC today at 13:42 UTC Ensure prerequisites for "lxd" are available
Hold today at 13:42 UTC today at 13:42 UTC Prepare snap "/var/lib/snapd/seed/snaps/lxd_14709.snap" (14709)
Hold today at 13:42 UTC today at 13:42 UTC Mount snap "lxd" (14709)
Hold today at 13:42 UTC today at 13:42 UTC Copy snap "lxd" data
Hold today at 13:42 UTC today at 13:42 UTC Setup snap "lxd" (14709) security profiles
Hold today at 13:42 UTC today at 13:42 UTC Make snap "lxd" (14709)...

[Louis Bouchard (louis)]

Hello,
Sorry for the noise. As it turns out, booting a pristine UCI without our modification works fine. I'll go check my crap.
...Louis