Unexplained mount failure, protocol error, what we know so far

zyga-snapd · September 17, 2018, 12:21pm

I just observed this first hand on my Fedora 28 system. What I find interesting is that this system has just a handful of snaps installed. A subsequent snap refresh worked correctly. I was unable to find any more information in the log files.

snap refresh

[zyga@faroe ~]$ sudo snap refresh
error: cannot perform the following tasks:
- Mount snap "skype" (54) ([start var-lib-snapd-snap-skype-54.mount] failed with exit status 1: Job for var-lib-snapd-snap-skype-54.mount failed.
See "systemctl status var-lib-snapd-snap-skype-54.mount" and "journalctl -xe" for details.
)

snap changes

[zyga@faroe ~]$ snap changes
ID   Status  Spawn                Ready                Summary
30   Error   today at 14:00 CEST  today at 14:10 CEST  Refresh snaps "skype", "gtk-common-themes", "spotify", "lxd"

snap tasks 30

[zyga@faroe ~]$ snap tasks 30
Status  Spawn                Ready                Summary
Done    today at 14:00 CEST  today at 14:10 CEST  Ensure prerequisites for "skype" are available
Undone  today at 14:00 CEST  today at 14:10 CEST  Download snap "skype" (54) from channel "stable"
Done    today at 14:00 CEST  today at 14:09 CEST  Fetch and check assertions for snap "skype" (54)
Error   today at 14:00 CEST  today at 14:09 CEST  Mount snap "skype" (54)
Hold    today at 14:00 CEST  today at 14:09 CEST  Run pre-refresh hook of "skype" snap if present
Hold    today at 14:00 CEST  today at 14:09 CEST  Stop snap "skype" services
Hold    today at 14:00 CEST  today at 14:09 CEST  Remove aliases for snap "skype"
Hold    today at 14:00 CEST  today at 14:09 CEST  Make current revision for snap "skype" unavailable
Hold    today at 14:00 CEST  today at 14:09 CEST  Copy snap "skype" data
Hold    today at 14:00 CEST  today at 14:09 CEST  Setup snap "skype" (54) security profiles
Hold    today at 14:00 CEST  today at 14:09 CEST  Make snap "skype" (54) available to the system
Hold    today at 14:00 CEST  today at 14:09 CEST  Automatically connect eligible plugs and slots of snap "skype"
Hold    today at 14:00 CEST  today at 14:09 CEST  Set automatic aliases for snap "skype"
Hold    today at 14:00 CEST  today at 14:09 CEST  Setup snap "skype" aliases
Hold    today at 14:00 CEST  today at 14:09 CEST  Run post-refresh hook of "skype" snap if present
Hold    today at 14:00 CEST  today at 14:09 CEST  Start snap "skype" (54) services
Hold    today at 14:00 CEST  today at 14:09 CEST  Clean up "skype" (54) install
Hold    today at 14:00 CEST  today at 14:09 CEST  Run configure hook of "skype" snap if present
Done    today at 14:00 CEST  today at 14:00 CEST  Ensure prerequisites for "gtk-common-themes" are available
Done    today at 14:00 CEST  today at 14:04 CEST  Download snap "gtk-common-themes" (701) from channel "stable"
Done    today at 14:00 CEST  today at 14:04 CEST  Fetch and check assertions for snap "gtk-common-themes" (701)
Done    today at 14:00 CEST  today at 14:05 CEST  Mount snap "gtk-common-themes" (701)
Done    today at 14:00 CEST  today at 14:05 CEST  Run pre-refresh hook of "gtk-common-themes" snap if present
Done    today at 14:00 CEST  today at 14:05 CEST  Stop snap "gtk-common-themes" services
Done    today at 14:00 CEST  today at 14:05 CEST  Remove aliases for snap "gtk-common-themes"
Done    today at 14:00 CEST  today at 14:05 CEST  Make current revision for snap "gtk-common-themes" unavailable
Done    today at 14:00 CEST  today at 14:05 CEST  Copy snap "gtk-common-themes" data
Done    today at 14:00 CEST  today at 14:05 CEST  Setup snap "gtk-common-themes" (701) security profiles
Done    today at 14:00 CEST  today at 14:05 CEST  Make snap "gtk-common-themes" (701) available to the system
Done    today at 14:00 CEST  today at 14:05 CEST  Automatically connect eligible plugs and slots of snap "gtk-common-themes"
Done    today at 14:00 CEST  today at 14:05 CEST  Set automatic aliases for snap "gtk-common-themes"
Done    today at 14:00 CEST  today at 14:05 CEST  Setup snap "gtk-common-themes" aliases
Done    today at 14:00 CEST  today at 14:05 CEST  Run post-refresh hook of "gtk-common-themes" snap if present
Done    today at 14:00 CEST  today at 14:05 CEST  Start snap "gtk-common-themes" (701) services
Done    today at 14:00 CEST  today at 14:05 CEST  Clean up "gtk-common-themes" (701) install
Done    today at 14:00 CEST  today at 14:05 CEST  Run configure hook of "gtk-common-themes" snap if present
Done    today at 14:00 CEST  today at 14:00 CEST  Ensure prerequisites for "spotify" are available
Done    today at 14:00 CEST  today at 14:08 CEST  Download snap "spotify" (21) from channel "stable"
Done    today at 14:00 CEST  today at 14:09 CEST  Fetch and check assertions for snap "spotify" (21)
Done    today at 14:00 CEST  today at 14:09 CEST  Mount snap "spotify" (21)
Done    today at 14:00 CEST  today at 14:09 CEST  Run pre-refresh hook of "spotify" snap if present
Done    today at 14:00 CEST  today at 14:09 CEST  Stop snap "spotify" services
Done    today at 14:00 CEST  today at 14:09 CEST  Remove aliases for snap "spotify"
Done    today at 14:00 CEST  today at 14:09 CEST  Make current revision for snap "spotify" unavailable
Done    today at 14:00 CEST  today at 14:09 CEST  Copy snap "spotify" data
Done    today at 14:00 CEST  today at 14:09 CEST  Setup snap "spotify" (21) security profiles
Done    today at 14:00 CEST  today at 14:09 CEST  Make snap "spotify" (21) available to the system
Done    today at 14:00 CEST  today at 14:09 CEST  Automatically connect eligible plugs and slots of snap "spotify"
Done    today at 14:00 CEST  today at 14:09 CEST  Set automatic aliases for snap "spotify"
Done    today at 14:00 CEST  today at 14:09 CEST  Setup snap "spotify" aliases
Done    today at 14:00 CEST  today at 14:09 CEST  Run post-refresh hook of "spotify" snap if present
Done    today at 14:00 CEST  today at 14:09 CEST  Start snap "spotify" (21) services
Done    today at 14:00 CEST  today at 14:09 CEST  Clean up "spotify" (21) install
Done    today at 14:00 CEST  today at 14:09 CEST  Run configure hook of "spotify" snap if present
Done    today at 14:00 CEST  today at 14:00 CEST  Ensure prerequisites for "lxd" are available
Done    today at 14:00 CEST  today at 14:06 CEST  Download snap "lxd" (8636) from channel "stable"
Done    today at 14:00 CEST  today at 14:06 CEST  Fetch and check assertions for snap "lxd" (8636)
Done    today at 14:00 CEST  today at 14:06 CEST  Mount snap "lxd" (8636)
Done    today at 14:00 CEST  today at 14:06 CEST  Run pre-refresh hook of "lxd" snap if present
Done    today at 14:00 CEST  today at 14:06 CEST  Stop snap "lxd" services
Done    today at 14:00 CEST  today at 14:07 CEST  Remove aliases for snap "lxd"
Done    today at 14:00 CEST  today at 14:07 CEST  Make current revision for snap "lxd" unavailable
Done    today at 14:00 CEST  today at 14:07 CEST  Copy snap "lxd" data
Done    today at 14:00 CEST  today at 14:08 CEST  Setup snap "lxd" (8636) security profiles
Done    today at 14:00 CEST  today at 14:08 CEST  Make snap "lxd" (8636) available to the system
Done    today at 14:00 CEST  today at 14:08 CEST  Automatically connect eligible plugs and slots of snap "lxd"
Done    today at 14:00 CEST  today at 14:08 CEST  Set automatic aliases for snap "lxd"
Done    today at 14:00 CEST  today at 14:09 CEST  Setup snap "lxd" aliases
Done    today at 14:00 CEST  today at 14:09 CEST  Run post-refresh hook of "lxd" snap if present
Done    today at 14:00 CEST  today at 14:09 CEST  Start snap "lxd" (8636) services
Done    today at 14:00 CEST  today at 14:09 CEST  Remove data for snap "lxd" (8393)
Done    today at 14:00 CEST  today at 14:09 CEST  Remove snap "lxd" (8393) from the system
Done    today at 14:00 CEST  today at 14:09 CEST  Clean up "lxd" (8636) install
Done    today at 14:00 CEST  today at 14:09 CEST  Run configure hook of "lxd" snap if present

......................................................................
Mount snap "skype" (54)

2018-09-17T14:09:51+02:00 ERROR [start var-lib-snapd-snap-skype-54.mount] failed with exit status 1: Job for var-lib-snapd-snap-skype-54.mount failed.
See "systemctl status var-lib-snapd-snap-skype-54.mount" and "journalctl -xe" for details.

systemctl status var-lib-snapd-snap-skype-54.mount

● var-lib-snapd-snap-skype-54.mount
   Loaded: not-found (Reason: No such file or directory)
   Active: failed (Result: protocol) since Mon 2018-09-17 14:09:45 CEST; 4min 7s ago

wrz 17 14:09:41 faroe systemd[1]: Mounting Mount unit for skype, revision 54...
wrz 17 14:09:45 faroe systemd[1]: var-lib-snapd-snap-skype-54.mount: Mount process finished, but there is no mount.
wrz 17 14:09:45 faroe systemd[1]: var-lib-snapd-snap-skype-54.mount: Failed with result 'protocol'.
wrz 17 14:09:45 faroe systemd[1]: Failed to mount Mount unit for skype, revision 54.

snap version

snap    2.35-1.fc28
snapd   2.35-1.fc28
series  16
fedora  28
kernel  4.17.19-200.fc28.x86_64

zyga-snapd · September 20, 2018, 2:31pm

To reproduce this issue please just run sudo make install with the following Makefile

numbers=$(shell seq 100)

.PHONY: all
all: $(foreach nr,$(numbers),test-$(nr)_1_all.snap)

test-%_1_all.snap:
	mkdir test-$*
	mkdir -p test-$*/meta
	echo "name: test-$*" > test-$*/meta/snap.yaml
	echo "version: 1" >> test-$*/meta/snap.yaml
	echo $* > test-$*/id
	snap pack test-$* .

.PHONY: install 
install: $(foreach nr,$(numbers),test-$(nr)_1_all.snap)
	echo $^ | xargs -n 1 -P $(words $(numbers)) snap install --dangerous

.PHONY: clean
clean:
	rm -rf test-*.snap test-*

I also looked at util-linux and I found a bug there. I will try to fix the bug locally and see if that fixes the issue.

zyga-snapd · September 20, 2018, 2:57pm

I added synchronization around mount and I can no longer reproduce the issue. I will now look at patching util-linux properly and propose this upstream.

mborzecki · November 20, 2018, 5:05pm

Some attempts were done to reproduce the problem by just using [u]mount, but so far without success. A reproducer that generates systemd mount units, does daemon-reload, start & stop can be found here: https://gist.github.com/bboozzoo/d4b142229b1915ef7cc0cf8593599ad9 so far it takes just 1-2 iterations for this to fail on Fedora, Arch, or Ubuntu 18.10

mborzecki · November 21, 2018, 12:56pm

Reported this to systemd:

https://github.com/systemd/systemd/issues/10872

Lin-Buo-Ren · December 2, 2018, 5:01pm

I have 45 snaps installed in my system and encountered this issue, is there any patches available?

mvo · December 10, 2018, 11:45am

We have an experimental patch in https://github.com/snapcore/snapd/pull/6243 that seems to fix the issue for good - however we need to clean this up some more, as it is it cannot be merged (code violates some design rules). But we plan to work on making it mergeable soon.

Lin-Buo-Ren · December 10, 2018, 12:14pm

Not sure what’s the cause, but I eventually remove and reinstall the entire snapd and all of my snaps to resolve this problem.

Lin-Buo-Ren · December 20, 2018, 4:38am

Is there any workarounds for this issue except removing and reinstalling snapd and all the previously installed snaps all together?

Lin-Buo-Ren · December 31, 2018, 12:42am

Ping again…I keep hitting this on KDE neon Developer Edition (based on Ubuntu 18.04), is there any workaround of this problem?

zyga-snapd · January 7, 2019, 11:20am

There is no need to remove snapd. Just repeat the operation. Alternatively you can manually mount the offending mount unit.

Lin-Buo-Ren · January 7, 2019, 1:29pm

Repeat the failed operation doesn’t work at my end… I end up installing another distro(ezgo 14, based on Kubuntu 18.04) and not encounter the issue since :-/

zyga-snapd · January 7, 2019, 1:30pm

What was the specific operation that was failing for you? Was it refresh? Installation of snaps? Something else perhaps?

Lin-Buo-Ren · January 7, 2019, 1:32pm

Installation of snaps, unfortunately I rm -rf'ed the entire system and can’t provide more info now.

zyga-snapd · January 7, 2019, 1:32pm

Which distribution release were you using when this issue was occurring?

Lin-Buo-Ren · January 7, 2019, 1:34pm

It was KDE neon Developer Edition (based on Ubuntu 18.04), not sure the exact release though(might be on the unstable branch) but it’s up-to-date.

mvo · January 14, 2019, 8:13am

We have merged a workaround for this issue into master now (PR was https://github.com/snapcore/snapd/pull/6331) - this will be part of the 2.37 release.

Lin-Buo-Ren · January 24, 2019, 7:17am

@zyga-snapd I’ve kinda reproduced the issue again, let’s see if we can dig it deeper.

Currently installed snap count: 34

The problem kinda emerged after I installed the core18 base snap, but who knows?

Lin-Buo-Ren · February 22, 2019, 5:16am

I now reproduced a similar issue again, but it seems to be another cause.

The snap install and snap try command fails with protocol error when the LXD container with disk device is started:

$ lxc start snapcraft-gallery-dl

$ sudo snap install hello
error: cannot perform the following tasks:
- Mount snap "hello" (20) ([start snap-hello-20.mount] failed with exit status 1: Job for snap-hello-20.mount failed.
See "systemctl status snap-hello-20.mount" and "journalctl -xe" for details.
)

$ snap changes | tail -n2
28   Error   today at 13:11 CST      today at 13:11 CST      Install "hello" snap

$ snap tasks 28
Status  Spawn               Ready               Summary
Done    today at 13:11 CST  today at 13:11 CST  Ensure prerequisites for "hello" are available
Undone  today at 13:11 CST  today at 13:11 CST  Download snap "hello" (20) from channel "stable"
Done    today at 13:11 CST  today at 13:11 CST  Fetch and check assertions for snap "hello" (20)
Error   today at 13:11 CST  today at 13:11 CST  Mount snap "hello" (20)
Hold    today at 13:11 CST  today at 13:11 CST  Copy snap "hello" data
Hold    today at 13:11 CST  today at 13:11 CST  Setup snap "hello" (20) security profiles
Hold    today at 13:11 CST  today at 13:11 CST  Make snap "hello" (20) available to the system
Hold    today at 13:11 CST  today at 13:11 CST  Automatically connect eligible plugs and slots of snap "hello"
Hold    today at 13:11 CST  today at 13:11 CST  Set automatic aliases for snap "hello"
Hold    today at 13:11 CST  today at 13:11 CST  Setup snap "hello" aliases
Hold    today at 13:11 CST  today at 13:11 CST  Run install hook of "hello" snap if present
Hold    today at 13:11 CST  today at 13:11 CST  Start snap "hello" (20) services
Hold    today at 13:11 CST  today at 13:11 CST  Run configure hook of "hello" snap if present

......................................................................
Mount snap "hello" (20)

2019-02-22T13:11:07+08:00 ERROR [start snap-hello-20.mount] failed with exit status 1: Job for snap-hello-20.mount failed.
See "systemctl status snap-hello-20.mount" and "journalctl -xe" for details.

$ systemctl status snap-hello-20.mount
● snap-hello-20.mount
   Loaded: not-found (Reason: No such file or directory)
   Active: failed (Result: protocol) since Fri 2019-02-22 13:11:06 CST; 2min 6s ago

 2月 22 13:11:06 brlin-main systemd[1]: Mounting Mount unit for hello, revision 20...
 2月 22 13:11:06 brlin-main systemd[1]: snap-hello-20.mount: Mount process finished, but there is no mount.
 2月 22 13:11:06 brlin-main systemd[1]: snap-hello-20.mount: Failed with result 'protocol'.
 2月 22 13:11:06 brlin-main systemd[1]: Failed to mount Mount unit for hello, revision 20.

$ lxc stop snapcraft-gallery-dl

$ sudo snap install hello
hello 2.10 from Canonical✓ installed

The LXD container is somehow interfering with the mounting of the snaps:

$ mount | grep gallerynsfs on /run/snapd/ns/gallery-dl.mnt type nsfs (rw)
/dev/sdb4 on /snap/gallery-dl/x4 type ext4 (ro,relatime,errors=remount-ro,data=ordered,x-gdu.hide)
/dev/sdb4 on /snap/gallery-dl/x5 type ext4 (ro,relatime,errors=remount-ro,data=ordered,x-gdu.hide)
/dev/sdb4 on /snap/gallery-dl/x6 type ext4 (ro,relatime,errors=remount-ro,data=ordered,x-gdu.hide)
/dev/sdb4 on /var/lib/lxd/devices/snapcraft-gallery-dl/disk.Snapcraft config.home-ubuntu-.config-snapcraft type ext4 (rw,relatime,errors=remount-ro,data=ordered)
/dev/sdb4 on /var/lib/lxd/devices/snapcraft-gallery-dl/disk.Source Tree of "gallery-dl - Command-line program to download image-galleries and -collections from several image hosting sites".home-ubuntu-gallery-dl type ext4 (rw,relatime,errors=remount-ro,data=ordered)
/dev/sdb4 on /var/lib/lxd/devices/snapcraft-gallery-dl/disk.Source Tree of "Unofficial Snap Packaging for gallery-dl".home-ubuntu-gallery-dl-snap type ext4 (rw,relatime,errors=remount-ro,data=ordered)

$ snap version
snap    2.37.2                                                             
snapd   2.37.2
series  16
ubuntu  18.04
kernel  4.15.0-45-generic

mvo · July 19, 2019, 10:08am

This is fixed upstream with https://github.com/systemd/systemd/pull/13097