SOLVED (docker issue) - Multiple broken snaps - Firefox, Brave, Slack etc

Multiple snaps have broken after updating yesterday and refuse to start.

Version:

snap --version
snap    2.57.1
snapd   2.57.1
series  16
ubuntu  22.04
kernel  5.15.0-47-generic

Update:

> sudo snap refresh
All snaps up to date.

Output for Firefox:

> SNAPD_DEBUG=1 snap run firefox
2022/09/14 18:09:14.803202 tool_linux.go:204: DEBUG: restarting into "/snap/snapd/current/usr/bin/snap"
2022/09/14 18:09:14.811837 logger.go:184: DEBUG: -- snap startup {"stage":"start", "time":"1663135754.811824"}
2022/09/14 18:09:14.818175 cmd_run.go:1037: DEBUG: executing snap-confine from /snap/snapd/16778/usr/lib/snapd/snap-confine
2022/09/14 18:09:14.820847 cmd_run.go:440: DEBUG: SELinux not enabled
2022/09/14 18:09:14.823119 cmd_run.go:1055: WARNING: cannot start document portal: Expected portal at "/run/user/1000/doc", got "/home/gavinf/.cache/doc"
2022/09/14 18:09:14.823204 tracking.go:46: DEBUG: creating transient scope snap.firefox.firefox
2022/09/14 18:09:14.823215 tracking.go:186: DEBUG: using session bus
2022/09/14 18:09:14.826850 tracking.go:294: DEBUG: StartTransientUnit failed with "org.freedesktop.DBus.Error.Spawn.ChildExited": [Process org.freedesktop.systemd1 exited with status 1]
2022/09/14 18:09:14.827204 cmd_run.go:1224: DEBUG: snapd cannot track the started application
2022/09/14 18:09:14.827233 cmd_run.go:1225: DEBUG: snap refreshes will not be postponed by this process
2022/09/14 18:09:14.827257 logger.go:184: DEBUG: -- snap startup {"stage":"snap to snap-confine", "time":"1663135754.827249"}
DEBUG: -- snap startup {"stage":"snap-confine enter", "time":"1663135754.830033"}
DEBUG: umask reset, old umask was   02
DEBUG: security tag: snap.firefox.firefox
DEBUG: executable:   /usr/lib/snapd/snap-exec
DEBUG: confinement:  non-classic
DEBUG: base snap:    core20
DEBUG: ruid: 1000, euid: 0, suid: 0
DEBUG: rgid: 1000, egid: 1000, sgid: 1000
DEBUG: apparmor label on snap-confine is: /snap/snapd/16778/usr/lib/snapd/snap-confine
DEBUG: apparmor mode is: enforce
DEBUG: -- snap startup {"stage":"snap-confine mount namespace start", "time":"1663135754.830767"}
DEBUG: creating lock directory /run/snapd/lock (if missing)
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: opening lock directory /run/snapd/lock
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: opening lock file: /run/snapd/lock/.lock
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: sanity timeout initialized and set for 30 seconds
DEBUG: acquiring exclusive lock (scope (global), uid 0)
DEBUG: sanity timeout reset and disabled
DEBUG: ensuring that snap mount directory is shared
DEBUG: unsharing snap namespace directory
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: releasing lock 5
DEBUG: opened snap-update-ns executable as file descriptor 5
DEBUG: opened snap-discard-ns executable as file descriptor 6
DEBUG: creating lock directory /run/snapd/lock (if missing)
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: opening lock directory /run/snapd/lock
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: opening lock file: /run/snapd/lock/firefox.lock
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: sanity timeout initialized and set for 30 seconds
DEBUG: acquiring exclusive lock (scope firefox, uid 0)
DEBUG: sanity timeout reset and disabled
DEBUG: initializing mount namespace: firefox
DEBUG: setting up device cgroup
DEBUG: libudev has current tags support
DEBUG: device /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1 has matching current tag
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: get bpf object at path /sys/fs/bpf/snap/snap_firefox_firefox
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: found existing device map
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: get next key for map 8
DEBUG: found 30 existing entries in devices map
DEBUG: delete key for c 143:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 1:5
DEBUG: delete elem in map 8
DEBUG: delete key for c 5:2
DEBUG: delete elem in map 8
DEBUG: delete key for c 226:0
DEBUG: delete elem in map 8
DEBUG: delete key for c 1:7
DEBUG: delete elem in map 8
DEBUG: delete key for c 81:0
DEBUG: delete elem in map 8
DEBUG: delete key for c 81:3
DEBUG: delete elem in map 8
DEBUG: delete key for c 195:0
DEBUG: delete elem in map 8
DEBUG: delete key for c 195:255
DEBUG: delete elem in map 8
DEBUG: delete key for c 136:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 10:239
DEBUG: delete elem in map 8
DEBUG: delete key for c 1:3
DEBUG: delete elem in map 8
DEBUG: delete key for c 140:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 1:8
DEBUG: delete elem in map 8
DEBUG: delete key for c 1:9
DEBUG: delete elem in map 8
DEBUG: delete key for c 81:2
DEBUG: delete elem in map 8
DEBUG: delete key for c 138:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 226:129
DEBUG: delete elem in map 8
DEBUG: delete key for c 5:0
DEBUG: delete elem in map 8
DEBUG: delete key for c 142:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 226:1
DEBUG: delete elem in map 8
DEBUG: delete key for c 141:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 504:0
DEBUG: delete elem in map 8
DEBUG: delete key for c 5:1
DEBUG: delete elem in map 8
DEBUG: delete key for c 195:254
DEBUG: delete elem in map 8
DEBUG: delete key for c 137:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 81:1
DEBUG: delete elem in map 8
DEBUG: delete key for c 10:200
DEBUG: delete elem in map 8
DEBUG: delete key for c 139:-1
DEBUG: delete elem in map 8
DEBUG: delete key for c 226:128
DEBUG: delete elem in map 8
DEBUG: set_effective_identity uid:0 (change: no), gid:0 (change: yes)
DEBUG: load program of type 0xf, 33 instructions
DEBUG: set_effective_identity uid:0 (change: no), gid:1000 (change: yes)
DEBUG: v2 allow c 1:3
DEBUG: v2 allow c 1:5
DEBUG: v2 allow c 1:7
DEBUG: v2 allow c 1:8
DEBUG: v2 allow c 1:9
DEBUG: v2 allow c 5:0
DEBUG: v2 allow c 5:1
DEBUG: v2 allow c 5:2
DEBUG: v2 allow c 136:4294967295
DEBUG: v2 allow c 137:4294967295
DEBUG: v2 allow c 138:4294967295
DEBUG: v2 allow c 139:4294967295
DEBUG: v2 allow c 140:4294967295
DEBUG: v2 allow c 141:4294967295
DEBUG: v2 allow c 142:4294967295
DEBUG: v2 allow c 143:4294967295
DEBUG: v2 allow c 195:0
DEBUG: v2 allow c 195:255
DEBUG: v2 allow c 504:0
DEBUG: v2 allow c 195:254
DEBUG: v2 allow c 10:239
DEBUG: v2 allow c 10:200
DEBUG: inspecting type of device: /dev/dri/card1
DEBUG: v2 allow c 226:1
DEBUG: device /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-DP-5 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-DP-5
DEBUG: device /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-HDMI-A-1 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-HDMI-A-1
DEBUG: device /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-eDP-2 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/card1/card1-eDP-2
DEBUG: device /sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/drm/renderD129 has matching current tag
DEBUG: inspecting type of device: /dev/dri/renderD129
DEBUG: v2 allow c 226:129
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0 has matching current tag
DEBUG: inspecting type of device: /dev/dri/card0
DEBUG: v2 allow c 226:0
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-1 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-1
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-2 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-2
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-3 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-3
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-4 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-DP-4
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-eDP-1 has matching current tag
DEBUG: cannot get major/minor numbers for syspath /sys/devices/pci0000:00/0000:00:02.0/drm/card0/card0-eDP-1
DEBUG: device /sys/devices/pci0000:00/0000:00:02.0/drm/renderD128 has matching current tag
DEBUG: inspecting type of device: /dev/dri/renderD128
DEBUG: v2 allow c 226:128
DEBUG: device /sys/devices/pci0000:00/0000:00:14.0/usb3/3-7/3-7:1.0/video4linux/video0 has matching current tag
DEBUG: inspecting type of device: /dev/video0
DEBUG: v2 allow c 81:0
DEBUG: device /sys/devices/pci0000:00/0000:00:14.0/usb3/3-7/3-7:1.0/video4linux/video1 has matching current tag
DEBUG: inspecting type of device: /dev/video1
DEBUG: v2 allow c 81:1
DEBUG: device /sys/devices/pci0000:00/0000:00:14.0/usb3/3-7/3-7:1.2/video4linux/video2 has matching current tag
DEBUG: inspecting type of device: /dev/video2
DEBUG: v2 allow c 81:2
DEBUG: device /sys/devices/pci0000:00/0000:00:14.0/usb3/3-7/3-7:1.2/video4linux/video3 has matching current tag
DEBUG: inspecting type of device: /dev/video3
DEBUG: v2 allow c 81:3
DEBUG: device /sys/devices/virtual/mem/full has matching current tag
DEBUG: inspecting type of device: /dev/full
DEBUG: v2 allow c 1:7
DEBUG: process in cgroup /user.slice/user-1000.slice/session-2.scope
/user.slice/user-1000.slice/session-2.scope is not a snap cgroup

Non snap installed apps like Chrome are working.

Any help appreciated :slight_smile:

Okay, so this appears to be a docker inflicted issue. Updating in case others encounter a similar problem.

2022/09/14 18:09:14.823119 cmd_run.go:1055: WARNING: cannot start document portal: Expected portal at "/run/user/1000/doc", got "/home/zeouter/.cache/doc"
2022/09/14 18:09:14.823204 tracking.go:46: DEBUG: creating transient scope snap.firefox.firefox
2022/09/14 18:09:14.823215 tracking.go:186: DEBUG: using session bus
2022/09/14 18:09:14.826850 tracking.go:294: DEBUG: StartTransientUnit failed with "org.freedesktop.DBus.Error.Spawn.ChildExited": [Process org.freedesktop.systemd1 exited with status 1]

These lines led me to review the boot logs in more detail:

> journalctl --boot | grep /run/user/1000
Sep 14 18:48:51 laptop systemd[1]: Stopping User Runtime Directory /run/user/1000...
Sep 14 18:48:51 laptop systemd[1]: Stopped User Runtime Directory /run/user/1000.
Sep 14 18:49:32 laptop systemd[1]: Starting User Runtime Directory /run/user/1000...
Sep 14 18:49:32 laptop systemd[1]: Finished User Runtime Directory /run/user/1000.
Sep 14 18:49:32 laptop systemd[2655]: pam_systemd(systemd-user:session): Runtime directory '/run/user/1000' is not owned by UID 1000, as it should.
Sep 14 18:49:32 laptop gdm-password][2648]: pam_systemd(gdm-password:session): Runtime directory '/run/user/1000' is not owned by UID 1000, as it should.
Sep 14 18:49:38 laptop slack.desktop[3244]: cmd_run.go:1055: WARNING: cannot start document portal: Expected portal at "/run/user/1000/doc", got "/home/zeouter/.cache/doc"

Turns out docker was overriding /run/user/1000/ and creating it with root ownership, even though it was not running any images… Disabling docker at startup solved the issue.