It’s just hanging. No output. 
This command should not actually hang, if it’s taking a while with no output it’s probably just very slow. This command has a few performance issues so it will most likely take a few minutes for it to run unfortunately.
1 Like
We are now 35 minutes deep into this command. What is it doing? 
I’m really confused how it could be stuck, but bugs are a possibility here I suppose…
What is the size of the /var/lib/snapd/state.json file?
120K reported by du -h.
Weather Update:
I tried unpacking the snap, manually dropping the snap.yaml into kernel/unset/meta/snap.yaml and repacking it (like this), but it had no effect, because I noticed that for some reason, snapd was looking for the file, not in /snap/kernel/x1/ or /snap/kernel/current, but just in the /snap/kernel/ directory, which (and this is an uneducated guess) would never contain that file. Though, things might be different on initial boot.
There’s no way this is a bug, is it?
well, since all other images work it is unlikely to be a bug …
it could be an issue with your model assertion, the kernel itself or the gadget …
Since you have a root shell could you get journal logs for snapd and paste them here as well? i.e. journalctl -e --no-pager -u snapd ?
-- Logs begin at Fri 2020-06-12 13:04:39 UTC, end at Fri 2020-06-12 15:22:45 UTC. --
Jun 12 13:06:15 localhost systemd[1]: Starting Snap Daemon...
Jun 12 13:06:15 localhost snapd[3144]: AppArmor status: apparmor not enabled
Jun 12 13:06:15 localhost snapd[3144]: patch.go:64: Patching system state level 6 to sublevel 1...
Jun 12 13:06:15 localhost snapd[3144]: patch.go:64: Patching system state level 6 to sublevel 2...
Jun 12 13:06:15 localhost snapd[3144]: patch.go:64: Patching system state level 6 to sublevel 3...
Jun 12 13:06:15 localhost snapd[3144]: daemon.go:343: started snapd/2.45 (series 16; devmode) ubuntu-core/18 (armhf) linux/5.4.45-dirty.
Jun 12 13:06:16 localhost snapd[3144]: daemon.go:436: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per snap)
Jun 12 13:06:16 localhost snapd[3144]: helpers.go:961: cannot retrieve info for snap "kernel": cannot find installed snap "kernel" at revision unset: missing file /snap/kernel/unset/meta/snap.yaml
Jun 12 13:06:16 localhost systemd[1]: Started Snap Daemon.
Jun 12 13:06:19 localhost snapd[3144]: daemon.go:542: gracefully waiting for running hooks
Jun 12 13:06:19 localhost snapd[3144]: daemon.go:544: done waiting for running hooks
Jun 12 13:06:29 localhost systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
Jun 12 13:06:29 localhost systemd[1]: snapd.service: Scheduled restart job, restart counter is at 1.
Jun 12 13:06:29 localhost systemd[1]: Stopped Snap Daemon.
Jun 12 13:06:29 localhost systemd[1]: Starting Snap Daemon...
Jun 12 13:06:29 localhost snapd[3180]: AppArmor status: apparmor not enabled
Jun 12 13:06:29 localhost snapd[3180]: daemon.go:343: started snapd/2.45 (series 16; devmode) ubuntu-core/18 (armhf) linux/5.4.45-dirty.
Jun 12 13:06:29 localhost snapd[3180]: daemon.go:436: adjusting startup timeout by 35s (pessimistic estimate of 30s plus 5s per snap)
Jun 12 13:06:29 localhost snapd[3180]: helpers.go:961: cannot retrieve info for snap "kernel": cannot find installed snap "kernel" at revision unset: missing file /snap/kernel/unset/meta/snap.yaml
Jun 12 13:06:30 localhost systemd[1]: Started Snap Daemon.
Jun 12 13:06:40 localhost snapd[3180]: devicestate.go:177: installing unasserted kernel "kernel"
Jun 12 13:07:10 localhost snapd[3180]: devicestate.go:177: installing unasserted gadget "gadget"
Jun 12 13:07:42 localhost snapd[3180]: udevmon.go:149: udev event error: Unable to parse uevent, err: no buffer space available
Jun 12 13:08:20 localhost snapd[3180]: udevmon.go:149: udev event error: Unable to parse uevent, err: no buffer space available
Jun 12 13:08:37 localhost modprobe[3720]: FATAL: Module arp_tables not found in directory /lib/modules/5.4.45-dirty
Jun 12 13:09:27 localhost snapd[3180]: udevmon.go:149: udev event error: Unable to parse uevent, err: no buffer space available
Jun 12 13:11:03 localhost sudo[5889]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm /etc/netplan/00-snapd-config.yaml
Jun 12 13:11:03 localhost sudo[5889]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jun 12 13:11:03 localhost sudo[5889]: pam_unix(sudo:session): session closed for user root
Jun 12 13:11:03 localhost sudo[5891]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cat
Jun 12 13:11:03 localhost sudo[5891]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jun 12 13:11:03 localhost sudo[5891]: pam_unix(sudo:session): session closed for user root
Jun 12 13:11:03 localhost sudo[5893]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/netplan apply
Jun 12 13:11:03 localhost sudo[5893]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jun 12 13:11:20 localhost.localdomain sudo[5893]: pam_unix(sudo:session): session closed for user root
Jun 12 13:11:20 localhost.localdomain sudo[6053]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/su -c useradd --extrausers testuserboi -s /bin/bash -m
Jun 12 13:11:20 localhost.localdomain sudo[6053]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jun 12 13:11:21 localhost.localdomain su[6059]: Successful su for root by root
Also, I had the idea of looking into the source code to see where the error is being thrown.
So I went and had a look at the snapd source code, and found the line that prints the error message Jun 12 13:06:16 localhost snapd[3144]: helpers.go:961: cannot retrieve info for snap... // yada yada yada and it looks like the function that prints it is snapsWithSecurityProfiles(). There’s a comment at the top that says,
// snapsWithSecurityProfiles returns all snaps that have active
// security profiles: these are either snaps that are active, or about
// to be active (pending link-snap) with a done setup-profiles
IDK if this’ll lead to anything but I guess it’s another thing to learn about.
did your ubuntu-image command finish without any errors when you built the image btw ?
i’d actually expect snap prepare-image which is the function ubuntu-image calls internally to seed the snaps to fall over if it cant set a revision …
Well, I do get warnings about my snaps being installed from local snaps, but other than that, no.
WARNING: "kernel", "gadget", "base-files", "device-config" installed from local snaps disconnected from a store cannot be refreshed subsequently!
Copying "kernel/kernel_5.4_armhf.snap" (kernel)
Copying "gadget/gadget_0.1_armhf.snap" (gadget)
Copying "base-files/base-files_0.1_armhf.snap" (base-files)
Copying "device-config/device-config_0.1_armhf.snap" (device-config)
The command I use to build is ubuntu-image snap. What does snap prepare-image do differently?
yeah, the warnings look pretty normal, nothing special in there …
snap prepare-image it is an internally used command by ubuntu-image.
IIRC (@ijohnson may correct me) it creates the initial seed file that is then used when installing the snaps on first boot.
mmm the unset kernel revision may be a red herring here, see this message:
Jun 12 13:06:40 localhost snapd[3180]: devicestate.go:177: installing unasserted kernel "kernel"
which implies that snapd is installing the kernel snap fine. I have seen the prior message show up on successful boots, so that is possibly not your issue. Probably it’s a bug that that message shows up on the working installs I’ve seen, so it could be a bug that this message is showing up on your system when you have a perfectly fine working kernel snap in the seed. This message is very interesting though:
Jun 12 13:07:42 localhost snapd[3180]: udevmon.go:149: udev event error: Unable to parse uevent, err: no buffer space available
That may actually be the cause of your issue.
Can you try the following:
- unsquashfs the core18 snap again
- edit squashfs-root/etc/environment to add SNAPD_DEBUG=1
- re-squashfs the core18 snap
- build a fresh image with this core18 snap
- boot the image and get snapd logs again
1 Like
Sorry this took so long, I was in a meeting.
Here’s what I got:
Sorry for asking a dumb question but what exactly is the problem we are solving here again? Is it just that there is a message about “cannot find installed snap …” ? I don’t see any problems in your snapd log except maybe a network issue at the end with:
Jun 12 19:22:33 awesomedevicecore18 snapd[3176]: retry.go:61: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/names?confinement=strict finished after 1 retries, elapsed time=1.115604133s, status: too many requests
which actually may be normal with a catalog refresh, I’m not sure.
It takes 10 minutes for this box to boot up for the first time, and that is seemingly due to serial-getty timing out 8 times. I don’t know why that happens, but I figured it was related to the error in the title of this thread, so I asked about it. I think I have another forum post about specifically the serial-getty errors, which, though I thought I fixed them by updating the kernel, they simply occur later in boot.
By boot up do you mean it takes 10 minutes for console-conf to run? Or something else?
Also can you get a root shell again and after the 10 minutes do snap debug timings 1 and snap debug timings 2?
I mean it takes 10 minutes or so for me to land on the Press enter to configure... menu over serial.
Please hold for commands…
Here are the debug timings.
You have quite a ton of snaps pre-installed … if this is an arm CPU from the slower category then a few minutes for the initial snap seeding are not actually unusual …
a pi2/3 with only the three default snaps (kernel, gaget, core18) can easily take up to 1.5-2min for the firstboot seeding … each subsequent additional snap will add to this because checksums are processed here … less cores and slower speed will add to this …