snap-confine (or some helper) can't open cgroup freezer tasks file

[Ian Johnson]

It's not clear to me how I got myself into this situation (nor really how I got out of it), but I was stuck being unable to install a simple test snap, because some helper inside snap-confine would consistently fail thusly:

$ SNAPD_DEBUG=1 SNAP_CONFINE_DEBUG=1 SNAP_REEXEC=0 snap install --dangerous test-post-refresh-disable-svcs_0.5_amd64.snap
2019/12/12 13:51:09.374431 cmd_linux.go:194: DEBUG: re-exec disabled by user
error: cannot perform the following tasks:
- Run install hook of "test-post-refresh-disable-svcs" snap if present (run hook "install":
-----
var/lib/snapd/lib/gl32/libEGL_nvidia.so.0 -> libEGL_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libEGL_nvidia.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libEGL_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGL.so.1 -> libGL.so.1.7.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGL.so.1.7.0 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGL.so.1.7.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLESv1_CM_nvidia.so.1 -> libGLESv1_CM_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLESv1_CM_nvidia.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGLESv1_CM_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLESv2_nvidia.so.2 -> libGLESv2_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLESv2_nvidia.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGLESv2_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLX_indirect.so.0 -> libGLX_mesa.so.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLX_nvidia.so.0 -> libGLX_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLX_nvidia.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGLX_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLX.so.0 -> libGLX.so.0.0.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLX.so.0.0.0 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGLX.so.0.0.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLdispatch.so.0 -> libGLdispatch.so.0.0.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libGLdispatch.so.0.0.0 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libGLdispatch.so.0.0.0
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libcuda.so -> libcuda.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libcuda.so.1 -> libcuda.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libcuda.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libcuda.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvcuvid.so -> libnvcuvid.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvcuvid.so.1 -> libnvcuvid.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvcuvid.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvcuvid.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-compiler.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-compiler.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-eglcore.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-eglcore.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-encode.so -> libnvidia-encode.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-encode.so.1 -> libnvidia-encode.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-encode.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-encode.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-fatbinaryloader.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-fatbinaryloader.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-fbc.so -> libnvidia-fbc.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-fbc.so.1 -> libnvidia-fbc.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-fbc.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-fbc.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-glcore.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-glcore.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-glsi.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-glsi.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ifr.so -> libnvidia-ifr.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ifr.so.1 -> libnvidia-ifr.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ifr.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-ifr.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ml.so -> libnvidia-ml.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ml.so.1 -> libnvidia-ml.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ml.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-ml.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-opencl.so.1 -> libnvidia-opencl.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-opencl.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-opencl.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ptxjitcompiler.so -> libnvidia-ptxjitcompiler.so.1
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ptxjitcompiler.so.1 -> libnvidia-ptxjitcompiler.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-ptxjitcompiler.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-ptxjitcompiler.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/libnvidia-tls.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/libnvidia-tls.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/tls/libnvidia-tls.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/tls/libnvidia-tls.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/vdpau/libvdpau_nvidia.so -> libvdpau_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/vdpau/libvdpau_nvidia.so.1 -> libvdpau_nvidia.so.390.116
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32/vdpau/libvdpau_nvidia.so.390.116 -> /var/lib/snapd/hostfs/usr/lib/i386-linux-gnu/vdpau/libvdpau_nvidia.so.390.116
DEBUG: remounting tmpfs as read-only /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/gl32
DEBUG: mounting tmpfs at /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/vulkan
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/vulkan/icd.d/nvidia_icd.json -> /var/lib/snapd/hostfs/usr/share/vulkan/icd.d/nvidia_icd.json
DEBUG: remounting tmpfs as read-only /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/vulkan
DEBUG: mounting tmpfs at /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/glvnd
DEBUG: creating symbolic link /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/glvnd/egl_vendor.d/10_nvidia.json -> /var/lib/snapd/hostfs/usr/share/glvnd/egl_vendor.d/10_nvidia.json
DEBUG: remounting tmpfs as read-only /tmp/snap.rootfs_TLHYwR/var/lib/snapd/lib/glvnd
DEBUG: performing operation: pivot_root /tmp/snap.rootfs_TLHYwR /tmp/snap.rootfs_TLHYwR//var/lib/snapd/hostfs
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: rmdir /var/lib/snapd/hostfs//tmp/snap.rootfs_TLHYwR
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: performing operation: (disabled) use debug build to see details
DEBUG: calling snapd tool snap-update-ns
DEBUG: waiting for snapd tool snap-update-ns to terminate
DEBUG: requesting changing of apparmor profile on next exec to snap-update-ns.test-post-refresh-disable-svcs
common.go:59: DEBUG: locking mount namespace of snap "test-post-refresh-disable-svcs"
common.go:80: DEBUG: freezing processes of snap "test-post-refresh-disable-svcs"
debug.go:34: DEBUG: desired mount profile: (none)
debug.go:34: DEBUG: current mount profile (before applying changes): (none)
change.go:501: DEBUG: desiredIDs: map[]
change.go:502: DEBUG: reuse: map[]
debug.go:45: DEBUG: mount changes needed: (none)
update.go:75: DEBUG: performing mount changes:
debug.go:34: DEBUG: current mount profile (after applying changes): (none)
common.go:88: DEBUG: unlocking mount namespace of snap "test-post-refresh-disable-svcs"
common.go:90: DEBUG: thawing processes of snap "test-post-refresh-disable-svcs"
DEBUG: snap-update-ns finished successfully
DEBUG: saved mount namespace meta-data to /run/snapd/ns/snap.test-post-refresh-disable-svcs.info
DEBUG: sending command 1 to helper process (pid: 103769)
DEBUG: waiting for response from helper
DEBUG: sanity timeout reset and disabled
DEBUG: helper process received command 1
DEBUG: capturing per-snap mount namespace
DEBUG: mount namespace of process 103755 preserved as test-post-refresh-disable-svcs.mnt
DEBUG: helper process waiting for command
DEBUG: sanity timeout initialized and set for 30 seconds
cannot open file /sys/fs/cgroup/freezer/snap.test-post-refresh-disable-svcs/tasks: Permission denied
DEBUG:
-----)

(also it would fail the same way even if I didn't define those variables above)

I could not find where in the snap-confine codebase we actually try to open the tasks file, which is confusing to me, but this problem persisted no matter which channel of the core snap I was on, and even if I disabled re-exec and it ran with the version of snapd from deb. I confirmed that I didn't have any hacked around files lying around in the debian package install directories by running debsums and that said all the files matched their SHA sums.I also tried manually removing that cgroup freezer with `sudo rmdir /sys/fs/cgroup/freezer/snap.test-post-refresh-disable-svcs` which also did not change anything. The permissions of that file looked perfectly normal to me:

I finally rebuilt snapd from the releases/2.43 branch with `make hack install` in the cmd dir and then was able to install it and thereafter all installs worked.

I don't expect this bug to go much anywhere but figured I would report it anyways before moving on to other things.

[Paweł Stołowski (stolowski)]

Probably something for zyga to take a quick look at.