Mount snap "snapcraft" (1591) ([start snap-snapcraft-1591.mount] failed with exit status 1:

[Alan Pope 🍺🐧🐱 🦄]

I just issued a snap refresh on my laptop and got this when updating snapcraft. Other snaps updated okay. Seems like a horribly technical error message.

alan@hal:~$ snap refresh
error: cannot perform the following tasks:
- Mount snap "snapcraft" (1591) ([start snap-snapcraft-1591.mount] failed with exit status 1: Job for snap-snapcraft-1591.mount failed.
See "systemctl status snap-snapcraft-1591.mount" and "journalctl -xe" for details.
)

I have no idea what's going on.

130 alan@hal:~$ systemctl status snap-snapcraft-1591.mount
● snap-snapcraft-1591.mount
   Loaded: not-found (Reason: No such file or directory)
   Active: failed (Result: protocol) since Fri 2018-05-18 12:39:17 BST; 1min 49s ago

May 18 12:39:17 hal systemd[1]: Mounting Mount unit for snapcraft...
May 18 12:39:17 hal systemd[1]: snap-snapcraft-1591.mount: Mount process finished, but there is no mount.
May 18 12:39:17 hal systemd[1]: snap-snapcraft-1591.mount: Failed with result 'protocol'.
May 18 12:39:17 hal systemd[1]: Failed to mount Mount unit for snapcraft.

Here's the recent snap changes..

Status Spawn Ready Summary
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:12Z Ensure prerequisites for "goxel" are available
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:30Z Download snap "goxel" (531) from channel "edge"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:30Z Fetch and check assertions for snap "goxel" (531)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Mount snap "goxel" (531)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Run pre-refresh hook of "goxel" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Stop snap "goxel" services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Remove aliases for snap "goxel"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Make current revision for snap "goxel" unavailable
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:32Z Copy snap "goxel" data
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Setup snap "goxel" (531) security profiles
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Make snap "goxel" (531) available to the system
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Automatically connect eligible plugs and slots of snap "goxel"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Set automatic aliases for snap "goxel"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Setup snap "goxel" aliases
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Run post-refresh hook of "goxel" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Start snap "goxel" (531) services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:33Z Remove data for snap "goxel" (509)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:34Z Remove snap "goxel" (509) from the system
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:34Z Clean up "goxel" (531) install
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:35Z Run configure hook of "goxel" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Ensure prerequisites for "snapcraft" are available
Undone 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Download snap "snapcraft" (1591) from channel "edge"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:19Z Fetch and check assertions for snap "snapcraft" (1591)
Error 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Mount snap "snapcraft" (1591)
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Run pre-refresh hook of "snapcraft" snap if present
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Stop snap "snapcraft" services
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Remove aliases for snap "snapcraft"
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Make current revision for snap "snapcraft" unavailable
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Copy snap "snapcraft" data
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Setup snap "snapcraft" (1591) security profiles
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Make snap "snapcraft" (1591) available to the system
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Automatically connect eligible plugs and slots of snap "snapcraft"
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Set automatic aliases for snap "snapcraft"
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Setup snap "snapcraft" aliases
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Run post-refresh hook of "snapcraft" snap if present
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Start snap "snapcraft" (1591) services
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Remove data for snap "snapcraft" (1574)
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Remove snap "snapcraft" (1574) from the system
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Clean up "snapcraft" (1591) install
Hold 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Run configure hook of "snapcraft" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:12Z Ensure prerequisites for "mattermost-desktop" are available
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:14Z Download snap "mattermost-desktop" (60) from channel "edge"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:16Z Fetch and check assertions for snap "mattermost-desktop" (60)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Mount snap "mattermost-desktop" (60)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Run pre-refresh hook of "mattermost-desktop" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:19Z Stop snap "mattermost-desktop" services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:19Z Remove aliases for snap "mattermost-desktop"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:19Z Make current revision for snap "mattermost-desktop" unavailable
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:21Z Copy snap "mattermost-desktop" data
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Setup snap "mattermost-desktop" (60) security profiles
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Make snap "mattermost-desktop" (60) available to the system
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Automatically connect eligible plugs and slots of snap "mattermost-desktop"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Set automatic aliases for snap "mattermost-desktop"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Setup snap "mattermost-desktop" aliases
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Run post-refresh hook of "mattermost-desktop" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Start snap "mattermost-desktop" (60) services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Clean up "mattermost-desktop" (60) install
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:24Z Run configure hook of "mattermost-desktop" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:12Z Ensure prerequisites for "qownnotes" are available
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:15Z Download snap "qownnotes" (966) from channel "stable"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:16Z Fetch and check assertions for snap "qownnotes" (966)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Mount snap "qownnotes" (966)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Run pre-refresh hook of "qownnotes" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Stop snap "qownnotes" services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:18Z Remove aliases for snap "qownnotes"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:19Z Make current revision for snap "qownnotes" unavailable
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:21Z Copy snap "qownnotes" data
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:21Z Setup snap "qownnotes" (966) security profiles
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:21Z Make snap "qownnotes" (966) available to the system
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:21Z Automatically connect eligible plugs and slots of snap "qownnotes"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:22Z Set automatic aliases for snap "qownnotes"
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:22Z Setup snap "qownnotes" aliases
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:22Z Run post-refresh hook of "qownnotes" snap if present
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:22Z Start snap "qownnotes" (966) services
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:22Z Remove data for snap "qownnotes" (954)
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Remove snap "qownnotes" (954) from the system
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Clean up "qownnotes" (966) install
Done 2018-05-18T11:39:12Z 2018-05-18T11:39:23Z Run configure hook of "qownnotes" snap if present

......................................................................
Mount snap "snapcraft" (1591)

2018-05-18T12:39:18+01:00 ERROR [start snap-snapcraft-1591.mount] failed with exit status 1: Job for snap-snapcraft-1591.mount failed.
See "systemctl status snap-snapcraft-1591.mount" and "journalctl -xe" for details.

[Paweł Stołowski (stolowski)]

This is an upstream issue around mount (a race likely) that we see from time to time in spread tests (and afair it was reproduced with a simple script, with no snapd involved). I don't think we can show any better error here. Zyga might know more.

[Zygmunt Krynicki (zyga)]

This is a bug in libmount. I'm tasked with fixing it this cycle. I will likely start working on it next week as it is getting more exposure with recent systemd update.

[Maciej Borzecki (maciek-borzecki)]

The problem can be reliably reproduced on Ubuntu 18.10, Fedora 28/29 and Arch using this script: https://gist.github.com/bboozzoo/d4b142229b1915ef7cc0cf8593599ad9

The basic variant, in parallel, creates mount units on the fly, calls systemd-reload, followed by start and stop. On my machine it takes one loop to fail with:

   systemd[1]: tmp-mounttest-mount-15.mount: Mount process finished, but there is no mount.
   systemd[1]: tmp-mounttest-mount-15.mount: Failed with result 'protocol'.
   systemd[1]: Failed to mount mount unit for test 15.

Note there are some variants in the script too. A variant where units are preloaded before was not seen to fail. Similarly, the variant using mount/umount directly. The variant using systemd-mount was flaky and is clearly missing some synchronization of the state information between systemd and systemd-mount.

[Maciej Borzecki (maciek-borzecki)]

Reported to systemd upstream: https://github.com/systemd/systemd/issues/10872

[Michael Vogt (mvo)]

The current PR that should workaround this bug in systemd is here: https://github.com/snapcore/snapd/pull/6331

[Zygmunt Krynicki (zyga)]

The pull request with a workaround for this bug has been merged into snapd in January of 2019. This version was released multiple times since then. I'm marking this bug as fix released.