0 140 Done today at 18:19 UTC today at 18:19 UTC run-hook Run prepare-device hook
0 141 Done today at 18:19 UTC today at 18:20 UTC generate-device-key Generate device key
0 142 Doing today at 18:19 UTC 0001-01-01 request-serial Request device serial
Hmm, actually can show the output from --change=1 ?
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…