Cannot mount squashfs image using "squashfs": ... Operation not permitted

Archlinux. I installed snapd from the AUR. squashfs-tools was installed as a dependency, but I explicitly installed squashfuse for good measure. I have rebooted since I installed snapd and since the last kernel update was installed.

$ uname -r && pacman -Q linux
5.3.7-arch1-1-ARCH
linux 5.3.7.arch1-1
$ snap --version
snap    2.42-2
snapd   2.42-2
series  16
arch    -
kernel  5.3.7-arch1-1-ARCH
$ snap changes
ID   Status  Spawn                   Ready                   Summary
1    Done    yesterday at 23:52 PDT  yesterday at 23:52 PDT  Initialize system state
$ grep squashfs /proc/filesystems
     squashfs

SELinux is not installed.

$ /usr/bin/sestatus
-bash: /usr/bin/sestatus: No such file or directory

When attempting to install any snap, I am met with this error:

$ sudo snap install hello_world
error: system does not fully support snapd: cannot mount squashfs image using "squashfs": mount:
       /tmp/sanity-mountpoint-408355398: mount failed: Operation not permitted.
$ sudo su root
# snap install hello_world
error: system does not fully support snapd: cannot mount squashfs image using "squashfs": mount:
       /tmp/sanity-mountpoint-408355398: mount failed: Operation not permitted.

There are no new messages in dmesg that are interesting. journalctl -xe shows nothing relevant except sudo logging the attempt.

In IRC I was asked to try this, to no avail:

snap download hello-world && mkdir test && sudo mount -o squashfs hello-world*.snap test/

A possibly related forum post is here, but in my case I seem to have no interesting log output.

$ sudo journalctl -u snapd
-- Logs begin at Mon 2019-08-12 19:01:02 PDT, end at Tue 2019-10-22 13:33:48 PDT. --
Oct 21 23:52:07 iris systemd[1]: Starting Snappy daemon...
Oct 21 23:52:07 iris snapd[2489509]: AppArmor status: apparmor not enabled
Oct 21 23:52:07 iris snapd[2489509]: daemon.go:346: started snapd/2.42-2 (series 16; classic; devmode) arch/ (amd64) linux/5.3.5-arch1-1-ARCH.
Oct 21 23:52:07 iris snapd[2489509]: main.go:123: system does not fully support snapd: cannot mount squashfs image using "squashfs": mount: /tmp/sanity-mountpoint-003757754:>
Oct 21 23:52:07 iris snapd[2489509]: daemon.go:439: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per snap)
Oct 21 23:52:07 iris snapd[2489509]: helpers.go:104: error trying to compare the snap system key: system-key missing on disk
Oct 21 23:52:07 iris systemd[1]: Started Snappy daemon.
Oct 21 23:52:12 iris snapd[2489509]: daemon.go:540: gracefully waiting for running hooks
Oct 21 23:52:12 iris snapd[2489509]: daemon.go:542: done waiting for running hooks
Oct 21 23:52:12 iris snapd[2489509]: daemon stop requested to wait for socket activation
Oct 21 23:52:12 iris systemd[1]: snapd.service: Succeeded.
Oct 21 23:52:39 iris systemd[1]: Starting Snappy daemon...
Oct 21 23:52:39 iris snapd[2491116]: AppArmor status: apparmor not enabled
Oct 21 23:52:39 iris snapd[2491116]: patch.go:64: Patching system state level 6 to sublevel 1...
Oct 21 23:52:39 iris snapd[2491116]: patch.go:64: Patching system state level 6 to sublevel 2...
Oct 21 23:52:39 iris snapd[2491116]: daemon.go:346: started snapd/2.42-2 (series 16; classic; devmode) arch/ (amd64) linux/5.3.5-arch1-1-ARCH.
Oct 21 23:52:39 iris snapd[2491116]: main.go:123: system does not fully support snapd: cannot mount squashfs image using "squashfs": mount: /tmp/sanity-mountpoint-862431413:>
Oct 21 23:52:39 iris snapd[2491116]: daemon.go:439: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per snap)

CC @mborzecki

It’s not really clear what is going on there. On the one hand, a mount by the user is successful, on the other snapd running as root gets EPERM. The difference is snapd trying to mount at a location under /tmp, but I don’t think it matters. Just for the record, can you post the output of snap debug sandbox-features?

Then can you add the following to snapd service overrides file?

# /etc/systemd/system/snapd.service.d/override.conf
[Service]
Environment=SNAPD_DEBUG=1
Environment=LIBMOUNT_DEBUG=all
Environment=LOOPDEV_DEBUG=all

Then systemctl daemon-reload && systemctl restart snapd, and post the log.

unless the permissions for /tmp would be wrong (but that would likely also cause other errors in the system)

$ stat /tmp
  File: /tmp
  Size: 400             Blocks: 0          IO Block: 4096   directory
Device: 30h/48d Inode: 3417        Links: 16
Access: (1777/drwxrwxrwt)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2019-10-22 16:51:53.655407822 -0700
Modify: 2019-10-23 10:01:20.409214469 -0700
Change: 2019-10-23 10:01:20.409214469 -0700
 Birth: -
$ snap debug sandbox-features
confinement-options:  devmode
dbus:                 mediated-bus-access
kmod:                 mediated-modprobe
mount:                freezer-cgroup-v1 layouts mount-namespace per-snap-persistency per-snap-profiles per-snap-updates per-snap-user-profiles stale-base-invalidation
seccomp:              bpf-actlog bpf-argument-filtering kernel:allow kernel:errno kernel:kill_process kernel:kill_thread kernel:log kernel:trace kernel:trap kernel:user_notif
udev:                 device-cgroup-v1 tagging
$ stat /etc/systemd/system/snapd.service.d
stat: cannot stat '/etc/systemd/system/snapd.service.d': No such file or directory
$ find /etc/systemd/ -iname "*snapd*"
/etc/systemd/system/sockets.target.wants/snapd.socket

Note that I did not find any snapd.service.d directory under /etc/systemd

you can just create it, systemd will pick up files from there …

Ah I misunderstood. Log is here: http://ix.io/1ZQZ

The relevant part of the log:

2797385: libmount: LOOP: [0x555d00479460]: not found; create a new loop device 
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: initialize context 
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: init: ignore ioctls 
2797385: libmount: LOOP: [0x555d00479460]: enabling AUTOCLEAR flag 
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: find_unused requested 
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: using loop scan 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: initialize 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: next 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: next: default check
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: loop0 name assigned
2797385: loopdev: ITER: [0x7ffc4d1aa760]: /dev/loop0 does not exist
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: loop1 name assigned 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: /dev/loop1 does not exist 
...
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: loop7 name assigned 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: /dev/loop7 does not exist 
2797385: loopdev: ITER: [0x7ffc4d1aa760]: next: scanning /dev 
2797385: loopdev: ITER: scan dir: /dev/ 
...
2797385: loopdev: CXT: [0x7ffc4d1aa5d0]: find_unused by scan [rc=1] 
...
2797385: libmount: CXT: [0x555d00479460]: mount: preparing failed 
2797385: libmount: CXT: [0x555d00479460]: excode: rc=1 message="mount failed: Operation not
permitted" mount: /tmp/sanity-mountpoint-326453316: mount failed: Operation not permitted. 

Which indicates that loopdev cannot for some reason access /dev/loop-control and goes into /dev/scanning mode. The difference is, in the loop-control mode mount would do LOOP_CTL_GET_FREE which allocates a new device when none are free. In the /dev scanning mode, it does not create new devices, but instead tries to use the existing ones, by trying some pre-determined set of device names.

This does not explain why mount invoked by snapd cannot access /dev/loop-control. On my vanilla Arch, with the default systemd setup and the service unit that came from the package, it can.

Looking at util-linux all it does is a simple stat on /dev/loop-control:

I would guess there’s some limitation applied in your local system configuration. Maybe check if PrivateDevices isn’t set by systemd on snapd.service.

Edit: and double check that the loop module can actually by loaded into the kernel.

sudo modprobe loop seems to have fixed it. I will leave it to others to decide if a more readable error should be printed in this case.

Thank you both very much for your help!