Just booted up an Antergos (Arch) VM today to confirm a bug, and when running snap refresh, it seems wedged on updating the core snap. Any ideas?
[alan@antergos-amd64 ~]$ sudo snap refresh
2017-05-18T10:02:52Z INFO snap "core" has bad plugs or slots: core-support-plug (unknown interface)
[-] Run configure hook of "core" snap if present
I’ve now seen similar on Linux Mint 18. Installed clean Linux Mint 18 and did an apt update and apt dist-upgrade then installed snapd:-
alan@mint18 ~ $ sudo apt install snapd
[sudo] password for alan:
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following additional packages will be installed:
apparmor libapparmor-perl squashfs-tools
Suggested packages:
apparmor-profiles apparmor-profiles-extra apparmor-docs apparmor-utils
The following NEW packages will be installed
apparmor libapparmor-perl snapd squashfs-tools
0 to upgrade, 4 to newly install, 0 to remove and 0 not to upgrade.
Need to get 10.3 MB of archives.
After this operation, 60.1 MB of additional disk space will be used.
Do you want to continue? [Y/n]
Get:1 http://archive.ubuntu.com/ubuntu xenial-updates/main amd64 libapparmor-perl amd64 2.10.95-0ubuntu2.6 [31.4 kB]
Get:2 http://archive.ubuntu.com/ubuntu xenial-updates/main amd64 apparmor amd64 2.10.95-0ubuntu2.6 [450 kB]
Get:3 http://archive.ubuntu.com/ubuntu xenial/main amd64 squashfs-tools amd64 1:4.3-3ubuntu2 [105 kB]
Get:4 http://archive.ubuntu.com/ubuntu xenial-updates/main amd64 snapd amd64 2.25 [9,706 kB]
Fetched 10.3 MB in 4s (2,509 kB/s)
Preconfiguring packages ...
Selecting previously unselected package libapparmor-perl.
(Reading database ... 222135 files and directories currently installed.)
Preparing to unpack .../libapparmor-perl_2.10.95-0ubuntu2.6_amd64.deb ...
Unpacking libapparmor-perl (2.10.95-0ubuntu2.6) ...
Selecting previously unselected package apparmor.
Preparing to unpack .../apparmor_2.10.95-0ubuntu2.6_amd64.deb ...
Unpacking apparmor (2.10.95-0ubuntu2.6) ...
Selecting previously unselected package squashfs-tools.
Preparing to unpack .../squashfs-tools_1%3a4.3-3ubuntu2_amd64.deb ...
Unpacking squashfs-tools (1:4.3-3ubuntu2) ...
Selecting previously unselected package snapd.
Preparing to unpack .../archives/snapd_2.25_amd64.deb ...
Unpacking snapd (2.25) ...
Processing triggers for systemd (229-4ubuntu17) ...
Processing triggers for ureadahead (0.100.0-19) ...
Processing triggers for man-db (2.7.5-1) ...
Setting up libapparmor-perl (2.10.95-0ubuntu2.6) ...
Setting up apparmor (2.10.95-0ubuntu2.6) ...
update-rc.d: warning: start and stop actions are no longer supported; falling back to defaults
diff: /var/lib/apparmor/profiles/.apparmor.md5sums: No such file or directory
Setting up squashfs-tools (1:4.3-3ubuntu2) ...
Setting up snapd (2.25) ...
Processing triggers for systemd (229-4ubuntu17) ...
Processing triggers for ureadahead (0.100.0-19) ...
Looks good:-
alan@mint18 ~ $ snap version
snap 2.25
snapd 2.25
series 16
linuxmint 18
kernel 4.4.0-21-generic
I tried to install a snap and now it’s hanging:-
alan@mint18 ~ $ sudo snap install emoj
2017-05-24T10:28:29+01:00 INFO cannot auto connect core:core-support-plug to core:core-support: (slot auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
2017-05-24T10:28:30+01:00 INFO cannot auto connect core:core-support-plug to core:core-support: (slot auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
[-] Mount snap "emoj" (1)
Been sat like this for a long time.
alan@mint18 ~ $ snap changes
ID Status Spawn Ready Summary
1 Done 2017-05-24T09:27:55Z 2017-05-24T09:27:55Z Initialize system state
2 Undoing 2017-05-24T09:28:07Z - Install "emoj" snap
alan@mint18 ~ $ snap change 2
Status Spawn Ready Summary
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Download snap "core" (1689) from channel "stable"
Done 2017-05-24T09:28:07Z 2017-05-24T10:33:34Z Fetch and check assertions for snap "core" (1689)
Undo 2017-05-24T09:28:07Z 2017-05-24T09:28:29Z Mount snap "core" (1689)
Undo 2017-05-24T09:28:07Z 2017-05-24T09:28:29Z Copy snap "core" data
Undoing 2017-05-24T09:28:07Z 2017-05-24T09:28:29Z Setup snap "core" (1689) security profiles
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Make snap "core" (1689) available to the system
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Setup snap "core" (1689) security profiles (phase 2)
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Set automatic aliases for snap "core"
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Setup snap "core" aliases
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Start snap "core" (1689) services
Done 2017-05-24T09:28:07Z 2017-05-24T10:33:34Z Run configure hook of "core" snap if present
Undone 2017-05-24T09:28:07Z 2017-05-24T09:28:35Z Download snap "emoj" (1) from channel "stable"
Done 2017-05-24T09:28:07Z 2017-05-24T10:33:34Z Fetch and check assertions for snap "emoj" (1)
Error 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Mount snap "emoj" (1)
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Copy snap "emoj" data
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Setup snap "emoj" (1) security profiles
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Make snap "emoj" (1) available to the system
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Set automatic aliases for snap "emoj"
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Setup snap "emoj" aliases
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Start snap "emoj" (1) services
Hold 2017-05-24T09:28:07Z 2017-05-24T09:28:34Z Run configure hook of "emoj" snap if present
......................................................................
Setup snap "core" (1689) security profiles
2017-05-24T10:28:29+01:00 INFO cannot auto connect core:core-support-plug to core:core-support: (slot auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
......................................................................
Make snap "core" (1689) available to the system
2017-05-24T10:28:29+01:00 INFO Requested daemon restart.
......................................................................
Setup snap "core" (1689) security profiles (phase 2)
2017-05-24T10:28:30+01:00 INFO cannot auto connect core:core-support-plug to core:core-support: (plug auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
2017-05-24T10:28:30+01:00 INFO cannot auto connect core:core-support-plug to core:core-support: (slot auto-connection), existing connection state "core:core-support-plug core:core-support" in the way
......................................................................
Mount snap "emoj" (1)
2017-05-24T10:28:34+01:00 ERROR [start snap-emoj-1.mount] failed with exit status 1: Job for snap-emoj-1.mount failed. See "systemctl status snap-emoj-1.mount" and "journalctl -xe" for details.
…and journalctl -xe…
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 11 on Undo: Start snap "core" (1689) services
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 10 on Undo: Setup snap "core" aliases
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 9 on Undo: Set automatic aliases for snap "core"
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 8 on Undo: Setup snap "core" (1689) security profiles (phase 2)
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 7 on Undo: Make snap "core" (1689) available to the system
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 6 on Undo: Setup snap "core" (1689) security profiles
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: handlers.go:204: Reported install problem for "core" as 5c8c4694-4063-11e7-b04a-fa163eec78fa OOPSID
May 24 10:28:35 mint18 snapd[3583]: 2017/05/24 10:28:35.746958 handlers.go:204: Reported install problem for "core" as 5c8c4694-4063-11e7-b04a-fa163eec78fa OOPSID
May 24 10:30:30 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/system-info 100.728µs 200
May 24 10:30:37 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/changes?select=all 238.596µs 200
May 24 10:31:59 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/changes?select=all 257.293µs 200
alan@mint18 ~ $ systemctl status snap-emoj-1.moun
● snap-emoj-1.moun.service
Loaded: not-found (Reason: No such file or directory)
Active: inactive (dead)
alan@mint18 ~ $ journalctl -xe
May 24 10:28:34 mint18 kernel: RAX: ffff880075c47a80 RBX: ffff880079e28480 RCX: ffff88007ab6fd80
May 24 10:28:34 mint18 kernel: RDX: 0000000000000000 RSI: 0000000000000049 RDI: 0000000000000000
May 24 10:28:34 mint18 kernel: RBP: ffff88007a0b3d78 R08: ffff88007c144900 R09: ffffffff813eadcc
May 24 10:28:34 mint18 kernel: R10: ffffea0001ec4000 R11: 0000000000002881 R12: ffff8800359ec180
May 24 10:28:34 mint18 kernel: R13: ffff88007a0b3dc0 R14: ffff880079e28480 R15: 0000000000000000
May 24 10:28:34 mint18 kernel: FS: 00007f17a34e3840(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
May 24 10:28:34 mint18 kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
May 24 10:28:34 mint18 kernel: CR2: 0000000000000010 CR3: 00000000772e1000 CR4: 00000000000406f0
May 24 10:28:34 mint18 kernel: Stack:
May 24 10:28:34 mint18 kernel: ffff880079e28480 ffff8800359ec180 ffff88007a0b3db0 ffffffff8123d1c0
May 24 10:28:34 mint18 kernel: ffff880075c47a80 ffff8800359ec180 ffff880077324740 0000000000000000
May 24 10:28:34 mint18 kernel: ffff88007a0b3e98 ffff88007a0b3df8 ffffffff8122def7 ffff880075c47c00
May 24 10:28:34 mint18 kernel: Call Trace:
May 24 10:28:34 mint18 kernel: [<ffffffff8123d1c0>] propagate_mnt+0x120/0x150
May 24 10:28:34 mint18 kernel: [<ffffffff8122def7>] attach_recursive_mnt+0x147/0x230
May 24 10:28:34 mint18 kernel: [<ffffffff8122e038>] graft_tree+0x58/0x90
May 24 10:28:34 mint18 kernel: [<ffffffff8122e0fe>] do_add_mount+0x8e/0xd0
May 24 10:28:34 mint18 kernel: [<ffffffff8122eed0>] do_mount+0x2c0/0xe00
May 24 10:28:34 mint18 kernel: [<ffffffff811eec10>] ? __kmalloc_track_caller+0x1d0/0x250
May 24 10:28:34 mint18 kernel: [<ffffffff8120e5c0>] ? __fput+0x190/0x220
May 24 10:28:34 mint18 kernel: [<ffffffff811abda2>] ? memdup_user+0x42/0x70
May 24 10:28:34 mint18 kernel: [<ffffffff8122fd3f>] SyS_mount+0x9f/0x100
May 24 10:28:34 mint18 kernel: [<ffffffff818244f2>] entry_SYSCALL_64_fastpath+0x16/0x71
May 24 10:28:34 mint18 kernel: Code: 39 90 d8 00 00 00 75 ec 8b b0 10 01 00 00 48 89 3d 20 e0 f8 00 48 89 05 21 e0 f8 00 39 b1 10 01 00 00 74 19 48 8b bf d8 00 00 00 <48> 8b 47 10 48 89 3d ff df f8 00 48 89 05 00 e0 f8 00 8b 43 30
May 24 10:28:34 mint18 kernel: RIP [<ffffffff8123cc9e>] propagate_one+0xbe/0x1c0
May 24 10:28:34 mint18 kernel: RSP <ffff88007a0b3d68>
May 24 10:28:34 mint18 kernel: CR2: 0000000000000010
May 24 10:28:34 mint18 kernel: fbcon_switch: detected unhandled fb_set_par error, error code -16
May 24 10:28:34 mint18 kernel: fbcon_switch: detected unhandled fb_set_par error, error code -16
May 24 10:28:34 mint18 kernel: ---[ end trace 027f828496eb5b15 ]---
May 24 10:28:34 mint18 systemd[1]: snap-emoj-1.mount: Mount process exited, code=killed status=9
May 24 10:28:34 mint18 systemd[1]: Failed to mount Mount unit for emoj.
-- Subject: Unit snap-emoj-1.mount has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit snap-emoj-1.mount has failed.
--
-- The result is failed.
May 24 10:28:34 mint18 systemd[1]: snap-emoj-1.mount: Unit entered failed state.
May 24 10:28:34 mint18 /usr/lib/snapd/snapd[3583]: task.go:303: DEBUG: 2017-05-24T10:28:34+01:00 ERROR [start snap-emoj-1.mount] failed with exit status 1: Job for snap-emoj-1.mount failed. See "systemctl status snap-emoj-1.mount" and "journalctl -xe" for details.
May 24 10:28:34 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 13 on Undo: Download snap "emoj" (1) from channel "stable"
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: handlers.go:204: Reported install problem for "emoj" as 5c300604-4063-11e7-9c8e-fa163e171d9b OOPSID
May 24 10:28:35 mint18 snapd[3583]: 2017/05/24 10:28:35.176665 handlers.go:204: Reported install problem for "emoj" as 5c300604-4063-11e7-9c8e-fa163e171d9b OOPSID
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 2 on Undo: Download snap "core" (1689) from channel "stable"
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 11 on Undo: Start snap "core" (1689) services
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 10 on Undo: Setup snap "core" aliases
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 9 on Undo: Set automatic aliases for snap "core"
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 8 on Undo: Setup snap "core" (1689) security profiles (phase 2)
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 7 on Undo: Make snap "core" (1689) available to the system
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: taskrunner.go:367: DEBUG: Running task 6 on Undo: Setup snap "core" (1689) security profiles
May 24 10:28:35 mint18 /usr/lib/snapd/snapd[3583]: handlers.go:204: Reported install problem for "core" as 5c8c4694-4063-11e7-b04a-fa163eec78fa OOPSID
May 24 10:28:35 mint18 snapd[3583]: 2017/05/24 10:28:35.746958 handlers.go:204: Reported install problem for "core" as 5c8c4694-4063-11e7-b04a-fa163eec78fa OOPSID
May 24 10:30:30 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/system-info 100.728µs 200
May 24 10:30:37 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/changes?select=all 238.596µs 200
May 24 10:31:59 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/changes?select=all 257.293µs 200
May 24 10:42:48 mint18 systemd[1]: Starting Cleanup of Temporary Directories...
-- Subject: Unit systemd-tmpfiles-clean.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-tmpfiles-clean.service has begun starting up.
May 24 10:42:48 mint18 systemd-tmpfiles[3792]: [/usr/lib/tmpfiles.d/var.conf:14] Duplicate line for path "/var/log", ignoring.
May 24 10:42:49 mint18 systemd[1]: Started Cleanup of Temporary Directories.
-- Subject: Unit systemd-tmpfiles-clean.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-tmpfiles-clean.service has finished starting up.
--
-- The start-up result is done.
May 24 10:43:38 mint18 mate-screensaver-dialog[3796]: pam_ecryptfs: seteuid error
May 24 10:43:38 mint18 mate-screensaver-dialog[3796]: gkr-pam: unlocked login keyring
May 24 10:47:14 mint18 /usr/lib/snapd/snapd[3583]: daemon.go:176: DEBUG: uid=1000;@ GET /v2/changes?select=all 258.423µs 200
May 24 11:17:01 mint18 CRON[3815]: pam_unix(cron:session): session opened for user root by (uid=0)
May 24 11:17:01 mint18 CRON[3816]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 24 11:17:01 mint18 CRON[3815]: pam_unix(cron:session): session closed for user root
May 24 11:33:19 mint18 unix_chkpwd[3829]: password check failed for user (alan)
May 24 11:33:19 mint18 mate-screensaver-dialog[3820]: pam_unix(mate-screensaver:auth): authentication failure; logname= uid=1000 euid=1000 tty=:0.0 ruser= rhost= user=alan
May 24 11:33:28 mint18 mate-screensaver-dialog[3820]: pam_ecryptfs: seteuid error
May 24 11:33:28 mint18 mate-screensaver-dialog[3820]: gkr-pam: unlocked login keyring
May 24 11:43:30 mint18 /usr/lib/snapd/snapd[3583]: snapmgr.go:422: No snaps to auto-refresh found
May 24 11:43:30 mint18 snapd[3583]: 2017/05/24 11:43:30.257464 snapmgr.go:422: No snaps to auto-refresh found
May 24 11:48:30 mint18 /usr/lib/snapd/snapd[3583]: snapmgr.go:496: DEBUG: Next refresh scheduled for 2017-05-24 22:30:37.102424034 +0100 BST.
May 24 12:17:01 mint18 CRON[3840]: pam_unix(cron:session): session opened for user root by (uid=0)
May 24 12:17:01 mint18 CRON[3841]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 24 12:17:01 mint18 CRON[3840]: pam_unix(cron:session): session closed for user root
May 24 13:17:01 mint18 CRON[3850]: pam_unix(cron:session): session opened for user root by (uid=0)
May 24 13:17:01 mint18 CRON[3851]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 24 13:17:01 mint18 CRON[3850]: pam_unix(cron:session): session closed for user root
May 24 14:17:01 mint18 CRON[3859]: pam_unix(cron:session): session opened for user root by (uid=0)
May 24 14:17:01 mint18 CRON[3860]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 24 14:17:01 mint18 CRON[3859]: pam_unix(cron:session): session closed for user root
May 24 14:25:29 mint18 mate-screensaver-dialog[3863]: pam_ecryptfs: seteuid error
May 24 14:25:29 mint18 mate-screensaver-dialog[3863]: gkr-pam: unlocked login keyring
May 24 14:32:58 mint18 systemd[1]: snapd.refresh.timer: Adding 5h 51min 22.048243s random time.
May 24 14:46:51 mint18 mate-screensaver-dialog[3882]: pam_ecryptfs: seteuid error
May 24 14:46:51 mint18 mate-screensaver-dialog[3882]: gkr-pam: unlocked login keyring
May 24 15:17:01 mint18 CRON[3899]: pam_unix(cron:session): session opened for user root by (uid=0)
May 24 15:17:01 mint18 CRON[3900]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 24 15:17:01 mint18 CRON[3899]: pam_unix(cron:session): session closed for user root
May 24 15:20:26 mint18 mate-screensaver-dialog[3903]: pam_ecryptfs: seteuid error
May 24 15:20:26 mint18 mate-screensaver-dialog[3903]: gkr-pam: unlocked login keyring
@popey Thanks. That is really a kernel crash. @zyga-snapd@niemeyer@mvo did you guys see such a crash (looks related to mount propagation) already before? Blind guess is that the Mint kernel might miss a patch for a bug or so.
This looks very much like a bug that was fixed in the Ubuntu kernel a few months ago. I cannot recall the number now but even if the bug is fixed Mint has the ill-defined policy of not updating the kernel.
@zyga-snapd Is there a chance that we can workaround this from the snap-confine side? I could guess we have similar problems in other scenarios where someone wants to run snapd but has a kernel without the bug fix applied. Is this bug fix already mainline and if with which kernel version was it released?
AFAIK there isn’t a bug for Mint yet. We can raise one but we first need to know if there is really a kernel patch missing or not. @zyga-snapd any chance that you can figure out if there is a patch on the kernel in Ubuntu for this?
This reminds us again that we really need to start tracking those snapd related patches in the kernel so we can get them applied elsewhere too.
I updated the Mint system I used with “apt update && apt dist-upgrade” so avoided (I believe) any blocks their Update Manager puts on kernels?
As you can see from my earlier comment I was using 4.4.0-21-generic, so not using the latest HWE kernel, but the latest (at the time), and having just booted it again, it’s on 4.4.0-53, and updating to 4.4.0-79 (from xenial-proposed).
Are the kernel issues only fixed in the HWE 4.8 series kernels?
