Refresh failing after some days of downtime

popey · July 19, 2019, 2:55pm

Been on holiday for a week. Got back and did a snap refresh and it seems wedged.

snap changes and snap version both hang.

snap refresh has been sat for some minutes (15 or more).

alan@KinkPad-K450:~/Pictures$ snap refresh
Consider re-refresh of "remmina", "bitwise", "review-tools", "raven-reader", "corsixth", "shotcut", "polar-bookshelf", "lxd", "opentoonz-morevna", "obs-studio", "libreoffice", "opento…

$ lsb_release -a
No LSB modules are available.
Distributor ID: neon
Description:    KDE neon Plasma LTS Edition 5.12
Release:        18.04
Codename:       bionic

$ uname -a
Linux KinkPad-K450 4.18.0-24-generic #25~18.04.1-Ubuntu SMP Thu Jun 20 11:13:08 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Jul 19 15:50:04 KinkPad-K450 systemd[1]: Starting Snappy daemon...
Jul 19 15:50:04 KinkPad-K450 snapd[31277]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:50:04 KinkPad-K450 snapd[31277]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:50:05 KinkPad-K450 snapd[31277]: helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
Jul 19 15:50:26 KinkPad-K450 snapd[31277]: helpers.go:283: removed stale connections: minecraft:unity7 core:unity7
Jul 19 15:50:26 KinkPad-K450 snapd[31277]: helpers.go:145: error trying to compare the snap system key: system-key missing on disk
Jul 19 15:51:35 KinkPad-K450 systemd[1]: snapd.service: Start operation timed out. Terminating.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: State 'stop-sigterm' timed out. Killing.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Killing process 31277 (snapd) with signal SIGKILL.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Main process exited, code=killed, status=9/KILL
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: Failed to start Snappy daemon.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Triggering OnFailure= dependencies.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Scheduled restart job, restart counter is at 11.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: Stopped Snappy daemon.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Found left-over process 977 (apparmor_parser) in control group while starting unit. Ignoring.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: snapd.service: Found left-over process 978 (apparmor_parser) in control group while starting unit. Ignoring.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Jul 19 15:51:43 KinkPad-K450 systemd[1]: Starting Snappy daemon...
Jul 19 15:51:43 KinkPad-K450 snapd[1014]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:51:43 KinkPad-K450 snapd[1014]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:51:43 KinkPad-K450 snapd[1014]: helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
Jul 19 15:52:10 KinkPad-K450 snapd[1014]: helpers.go:283: removed stale connections: minecraft:unity7 core:unity7
Jul 19 15:52:10 KinkPad-K450 snapd[1014]: helpers.go:145: error trying to compare the snap system key: system-key missing on disk
Jul 19 15:53:13 KinkPad-K450 systemd[1]: snapd.service: Start operation timed out. Terminating.
Jul 19 15:53:21 KinkPad-K450 systemd[1]: snapd.service: State 'stop-sigterm' timed out. Killing.
Jul 19 15:53:21 KinkPad-K450 systemd[1]: snapd.service: Killing process 1014 (snapd) with signal SIGKILL.
Jul 19 15:53:21 KinkPad-K450 systemd[1]: snapd.service: Main process exited, code=killed, status=9/KILL
Jul 19 15:53:21 KinkPad-K450 systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 19 15:53:21 KinkPad-K450 systemd[1]: Failed to start Snappy daemon.
Jul 19 15:53:21 KinkPad-K450 systemd[1]: snapd.service: Triggering OnFailure= dependencies.
Jul 19 15:53:22 KinkPad-K450 systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
Jul 19 15:53:22 KinkPad-K450 systemd[1]: snapd.service: Scheduled restart job, restart counter is at 12.
Jul 19 15:53:22 KinkPad-K450 systemd[1]: Stopped Snappy daemon.
Jul 19 15:53:22 KinkPad-K450 systemd[1]: Starting Snappy daemon...
Jul 19 15:53:22 KinkPad-K450 snapd[2990]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:53:22 KinkPad-K450 snapd[2990]: AppArmor status: apparmor is enabled and all features are available
Jul 19 15:53:22 KinkPad-K450 snapd[2990]: helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
Jul 19 15:53:43 KinkPad-K450 snapd[2990]: helpers.go:283: removed stale connections: minecraft:unity7 core:unity7
Jul 19 15:53:43 KinkPad-K450 snapd[2990]: helpers.go:145: error trying to compare the snap system key: system-key missing on disk

popey · July 19, 2019, 3:04pm

$ systemctl stop snapd.*
$ sudo SNAPD_DEBUG=1 /usr/lib/snapd/snapd
[sudo] password for alan: 
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:03:14.824218 cmd_linux.go:224: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:03:15.040454 helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
2019/07/19 16:03:34.472109 helpers.go:283: removed stale connections: minecraft:unity7 core:unity7
2019/07/19 16:03:34.519738 helpers.go:145: error trying to compare the snap system key: system-key missing on disk

popey · July 19, 2019, 3:07pm

Time passed then…


2019/07/19 16:05:41.577260 activation.go:64: DEBUG: socket "/run/snapd.socket" was not activated; listening
2019/07/19 16:05:41.577366 activation.go:64: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2019/07/19 16:05:41.578245 daemon.go:338: started snapd/2.40 (series 16; classic) neon/18.04 (amd64) linux/4.18.0-24-generic.
2019/07/19 16:05:41.714927 main.go:160: DEBUG: activation done in 2m26.875s
2019/07/19 16:05:41.739557 autorefresh.go:253: DEBUG: Next refresh scheduled for 2019-07-20T04:00:00+01:00.
2019/07/19 16:05:41.740403 catalogrefresh.go:88: DEBUG: Catalog refresh starting now; next scheduled for 2019-07-20 16:05:41.74013402 +0100 BST m=+86546.910910766.
2019/07/19 16:05:41.748078 retry.go:49: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/sections, attempt 1, elapsed time=7.12µs
2019/07/19 16:05:42.147667 retry.go:61: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/sections finished after 1 retries, elapsed time=399.602803ms, status: 200
2019/07/19 16:05:42.173955 retry.go:49: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/names?confinement=strict%2Cclassic, attempt 1, elapsed time=8.091µs
2019/07/19 16:05:42.451340 retry.go:61: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/names?confinement=strict%2Cclassic finished after 1 retries, elapsed time=277.395508ms, status: 200
2019/07/19 16:05:42.703265 catalogrefresh.go:92: DEBUG: Catalog refresh succeeded.
2019/07/19 16:05:44.548739 taskrunner.go:426: DEBUG: Running task 103671 on Doing: Consider re-refresh of "remmina", "bitwise", "review-tools", "raven-reader", "corsixth", "shotcut", "polar-bookshelf", "lxd", "opentoonz-morevna", "obs-studio", "libreoffice", "opentoonz", "snap-store", "mqtt-explorer", "fluffychat", "slack", "dosbox-x", "mumble", "minetest", "irccloud-desktop", "core", "core18", "mame", "gnome-twitch"
2019/07/19 16:05:44.548891 taskrunner.go:426: DEBUG: Running task 103203 on Doing: Automatically connect eligible plugs and slots of snap "core"
2019/07/19 16:05:44.862278 task.go:337: DEBUG: 2019-07-19T16:05:44+01:00 INFO cannot auto-connect slot core:avahi-observe to remmina:avahi-observe, candidates found: avahi:avahi-observe, core:avahi-observe
2019/07/19 16:05:46.053524 taskrunner.go:426: DEBUG: Running task 103204 on Do: Set automatic aliases for snap "core"
2019/07/19 16:05:46.054437 taskrunner.go:426: DEBUG: Running task 103671 on Doing: Consider re-refresh of "remmina", "bitwise", "review-tools", "raven-reader", "corsixth", "shotcut", "polar-bookshelf", "lxd", "opentoonz-morevna", "obs-studio", "libreoffice", "opentoonz", "snap-store", "mqtt-explorer", "fluffychat", "slack", "dosbox-x", "mumble", "minetest", "irccloud-desktop", "core", "core18", "mame", "gnome-twitch"
2019/07/19 16:05:47.022634 taskrunner.go:426: DEBUG: Running task 103205 on Do: Setup snap "core" aliases

Seems to be moving now…

popey · July 19, 2019, 3:21pm

Subsequent restart seems faster.

alan@KinkPad-K450:~$ sudo SNAPD_DEBUG=1 /usr/lib/snapd/snapd
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:16:43.793770 cmd_linux.go:224: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:16:44.867447 helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
2019/07/19 16:17:09.450168 activation.go:64: DEBUG: socket "/run/snapd.socket" was not activated; listening
2019/07/19 16:17:09.450222 activation.go:64: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2019/07/19 16:17:09.450538 daemon.go:338: started snapd/2.40 (series 16; classic) neon/18.04 (amd64) linux/4.18.0-24-generic.
2019/07/19 16:17:09.674469 main.go:160: DEBUG: activation done in 25.338s
2019/07/19 16:17:09.704095 autorefresh.go:253: DEBUG: Next refresh scheduled for 2019-07-20T04:00:00+01:00.

popey · July 19, 2019, 3:23pm

$ snap debug timings --startup=load-state
ID          Status        Doing      Undoing  Summary
load-state                    -            -  
 ^                        116ms            -    read snapd state from disk

popey · July 19, 2019, 3:29pm

Stopped snapd, removed /var/lib/snapd/system-key then restarted.

alan@KinkPad-K450:~$ sudo SNAPD_DEBUG=1 /usr/lib/snapd/snapd
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:27:14.307694 cmd_linux.go:224: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
AppArmor status: apparmor is enabled and all features are available
2019/07/19 16:27:14.531377 helpers.go:136: cannot add snap "s" to interface repository: invalid snap name: "s"
2019/07/19 16:27:33.147786 helpers.go:145: error trying to compare the snap system key: system-key missing on disk
2019/07/19 16:29:26.996857 activation.go:64: DEBUG: socket "/run/snapd.socket" was not activated; listening
2019/07/19 16:29:26.996994 activation.go:64: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2019/07/19 16:29:26.997523 daemon.go:338: started snapd/2.40 (series 16; classic) neon/18.04 (amd64) linux/4.18.0-24-generic.
2019/07/19 16:29:27.138422 main.go:160: DEBUG: activation done in 2m12.816s
2019/07/19 16:29:27.155834 autorefresh.go:253: DEBUG: Next refresh scheduled for 2019-07-20T04:00:00+01:00.

popey · July 19, 2019, 4:21pm

Forum wouldn’t let me post this volume of text… https://paste.ubuntu.com/p/wYXx3jB7zP/