Snap does not start after reboot

$ snap version
snap 2.30
snapd 2.30
series 16
kernel 4.15.17-xm4x_test+

I get the same error after an automatic snap refresh attempt for my snap wpe-webkit-mir-kiosk.

snap version:

snap    2.41
snapd   2.41
series  16
kernel  4.4.0-1120-raspi2

This is the output of snap logs wpe-webkit-mir-kiosk.browser:

2019-09-17T09:07:08Z wpe-webkit-mir-kiosk.browser[6941]: snap-update-ns failed with code 1: File exists
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Main process exited, code=exited, status=1/FAILURE
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Unit entered failed state.
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Failed with result 'exit-code'.
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Service hold-off time over, scheduling restart.
2019-09-17T09:07:08Z systemd[1]: Stopped Service for snap application wpe-webkit-mir-kiosk.browser.
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Start request repeated too quickly.
2019-09-17T09:07:08Z systemd[1]: Failed to start Service for snap application wpe-webkit-mir-kiosk.browser.
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Unit entered failed state.
2019-09-17T09:07:08Z systemd[1]: snap.wpe-webkit-mir-kiosk.browser.service: Failed with result 'start-limit-hit'.

dmesg | grep AppArmor:

[504978.659153] audit: type=1400 audit(1568711443.466:158): apparmor="DENIED" operation="rmdir" profile="snap.wpe-webkit-mir-kiosk.browser" name="/root/snap/wpe-webkit-mir-kiosk/25/" pid=14358 comm="rmdir" requested_mask="d" denied_mask="d" fsuid=0 ouid=0

sudo cat /sys/kernel/security/apparmor/profiles:

glancr@glancr:~$ sudo cat /sys/kernel/security/apparmor/profiles
snap.wpe-webkit-mir-kiosk.hook.install (enforce)
[…]
snap.wpe-webkit-mir-kiosk.browser (enforce)
snap.wpe-webkit-mir-kiosk.hook.configure (enforce)
[…]
snap-update-ns.wpe-webkit-mir-kiosk (enforce)
[…]

ls -lah /var/lib/snapd/apparmor/profiles:

-rw-r--r-- 1 root root 54K Sep 13 14:55 /var/lib/snapd/apparmor/profiles/snap-update-ns.wpe-webkit-mir-kiosk

Looks like the profile exists and is loaded, so it seems to be something else.

What’s the output from snap changes wpe-webkit-mir-kiosk and then snap tasks $NUM for each change number from snap changes above?

Changes:

ID   Status  Spawn                Ready                Summary
35   Error   today at 05:04 CEST  today at 05:05 CEST  Auto-refresh snaps "wpe-webkit-mir-kiosk", "mir-kiosk"
46   Done    today at 11:07 CEST  today at 11:07 CEST  Running service command
49   Done    today at 11:24 CEST  today at 11:24 CEST  Disable "wpe-webkit-mir-kiosk" snap
51   Done    today at 11:26 CEST  today at 11:26 CEST  Enable "wpe-webkit-mir-kiosk" snap

The last three were initiated manually by the affected user upon request.

snap tasks 35 output
Status  Spawn                Ready                Summary
Done    today at 05:04 CEST  today at 05:05 CEST  Ensure prerequisites for "wpe-webkit-mir-kiosk" are available
Undone  today at 05:04 CEST  today at 05:05 CEST  Download snap "wpe-webkit-mir-kiosk" (25) from channel "stable"
Done    today at 05:04 CEST  today at 05:05 CEST  Fetch and check assertions for snap "wpe-webkit-mir-kiosk" (25)
Undone  today at 05:04 CEST  today at 05:05 CEST  Mount snap "wpe-webkit-mir-kiosk" (25)
Undone  today at 05:04 CEST  today at 05:05 CEST  Run pre-refresh hook of "wpe-webkit-mir-kiosk" snap if present
Undone  today at 05:04 CEST  today at 05:05 CEST  Stop snap "wpe-webkit-mir-kiosk" services
Undone  today at 05:04 CEST  today at 05:05 CEST  Remove aliases for snap "wpe-webkit-mir-kiosk"
Undone  today at 05:04 CEST  today at 05:05 CEST  Make current revision for snap "wpe-webkit-mir-kiosk" unavailable
Undone  today at 05:04 CEST  today at 05:05 CEST  Copy snap "wpe-webkit-mir-kiosk" data
Error   today at 05:04 CEST  today at 05:05 CEST  Setup snap "wpe-webkit-mir-kiosk" (25) security profiles
Hold    today at 05:04 CEST  today at 05:05 CEST  Make snap "wpe-webkit-mir-kiosk" (25) available to the system
Hold    today at 05:04 CEST  today at 05:05 CEST  Automatically connect eligible plugs and slots of snap "wpe-webkit-mir-kiosk"
Hold    today at 05:04 CEST  today at 05:05 CEST  Set automatic aliases for snap "wpe-webkit-mir-kiosk"
Hold    today at 05:04 CEST  today at 05:05 CEST  Setup snap "wpe-webkit-mir-kiosk" aliases
Hold    today at 05:04 CEST  today at 05:05 CEST  Run post-refresh hook of "wpe-webkit-mir-kiosk" snap if present
Hold    today at 05:04 CEST  today at 05:05 CEST  Start snap "wpe-webkit-mir-kiosk" (25) services
Hold    today at 05:04 CEST  today at 05:05 CEST  Clean up "wpe-webkit-mir-kiosk" (25) install
Hold    today at 05:04 CEST  today at 05:05 CEST  Run configure hook of "wpe-webkit-mir-kiosk" snap if present
Hold    today at 05:04 CEST  today at 05:05 CEST  Run health check of "wpe-webkit-mir-kiosk" snap
Done    today at 05:04 CEST  today at 05:04 CEST  Ensure prerequisites for "mir-kiosk" are available
Done    today at 05:04 CEST  today at 05:04 CEST  Download snap "mir-kiosk" (2132) from channel "stable"
Done    today at 05:04 CEST  today at 05:04 CEST  Fetch and check assertions for snap "mir-kiosk" (2132)
Done    today at 05:04 CEST  today at 05:04 CEST  Mount snap "mir-kiosk" (2132)
Done    today at 05:04 CEST  today at 05:04 CEST  Run pre-refresh hook of "mir-kiosk" snap if present
Done    today at 05:04 CEST  today at 05:04 CEST  Stop snap "mir-kiosk" services
Done    today at 05:04 CEST  today at 05:04 CEST  Remove aliases for snap "mir-kiosk"
Done    today at 05:04 CEST  today at 05:04 CEST  Make current revision for snap "mir-kiosk" unavailable
Done    today at 05:04 CEST  today at 05:04 CEST  Copy snap "mir-kiosk" data
Done    today at 05:04 CEST  today at 05:05 CEST  Setup snap "mir-kiosk" (2132) security profiles
Done    today at 05:04 CEST  today at 05:05 CEST  Make snap "mir-kiosk" (2132) available to the system
Done    today at 05:04 CEST  today at 05:05 CEST  Automatically connect eligible plugs and slots of snap "mir-kiosk"
Done    today at 05:04 CEST  today at 05:05 CEST  Set automatic aliases for snap "mir-kiosk"
Done    today at 05:04 CEST  today at 05:05 CEST  Setup snap "mir-kiosk" aliases
Done    today at 05:04 CEST  today at 05:05 CEST  Run post-refresh hook of "mir-kiosk" snap if present
Done    today at 05:04 CEST  today at 05:05 CEST  Start snap "mir-kiosk" (2132) services
Done    today at 05:04 CEST  today at 05:05 CEST  Clean up "mir-kiosk" (2132) install
Done    today at 05:04 CEST  today at 05:05 CEST  Run configure hook of "mir-kiosk" snap if present
Done    today at 05:04 CEST  today at 05:05 CEST  Run health check of "mir-kiosk" snap
Done    today at 05:04 CEST  today at 05:05 CEST  Consider re-refresh of "wpe-webkit-mir-kiosk", "mir-kiosk"

......................................................................
Setup snap "wpe-webkit-mir-kiosk" (25) security profiles

2019-09-17T05:05:19+02:00 ERROR cannot setup mount for snap "wpe-webkit-mir-kiosk": cannot update mount namespace of snap "wpe-webkit-mir-kiosk": cannot update preserved namespace of snap "wpe-webkit-mir-kiosk": cannot update snap namespace: device or resource busy
2019-09-17T05:05:19+02:00 ERROR cannot update mount namespace of snap "wpe-webkit-mir-kiosk": cannot update preserved namespace of snap "wpe-webkit-mir-kiosk": cannot update snap namespace: device or resource busy

......................................................................
Consider re-refresh of "wpe-webkit-mir-kiosk", "mir-kiosk"

2019-09-17T05:05:28+02:00 INFO No re-refreshes found.
snap tasks 46 output

Status Spawn Ready Summary
Done today at 11:07 CEST today at 11:07 CEST restart of [wpe-webkit-mir-kiosk.browser]

snap tasks 49 output

Status Spawn Ready Summary
Done today at 11:24 CEST today at 11:24 CEST Stop snap “wpe-webkit-mir-kiosk” (19) services
Done today at 11:24 CEST today at 11:24 CEST Remove aliases for snap “wpe-webkit-mir-kiosk”
Done today at 11:24 CEST today at 11:24 CEST Make snap “wpe-webkit-mir-kiosk” (19) unavailable to the system
Done today at 11:24 CEST today at 11:24 CEST Remove security profiles of snap “wpe-webkit-mir-kiosk”

snap tasks 51 output

Status Spawn Ready Summary
Done today at 11:26 CEST today at 11:26 CEST Prepare snap “wpe-webkit-mir-kiosk” (19)
Done today at 11:26 CEST today at 11:26 CEST Setup snap “wpe-webkit-mir-kiosk” (19) security profiles
Done today at 11:26 CEST today at 11:26 CEST Make snap “wpe-webkit-mir-kiosk” (19) available to the system
Done today at 11:26 CEST today at 11:26 CEST Setup snap “wpe-webkit-mir-kiosk” aliases
Done today at 11:26 CEST today at 11:26 CEST Start snap “wpe-webkit-mir-kiosk” (19) services
Done today at 11:26 CEST today at 11:26 CEST Automatically connect eligible plugs and slots of snap “wpe-webkit-mir-kiosk”


Make snap “wpe-webkit-mir-kiosk” (19) available to the system

2019-09-17T11:26:30+02:00 INFO added auto-connect task

@zyga-snapd we have mount namespace updating issues from above. Unclear if it’s a dup or not however, I seem to remember EBUSY being mentioned by you recently…

2019-09-17T05:05:19+02:00 ERROR cannot setup mount for snap "wpe-webkit-mir-kiosk": cannot update mount namespace of snap "wpe-webkit-mir-kiosk": cannot update preserved namespace of snap "wpe-webkit-mir-kiosk": cannot update snap namespace: device or resource busy
2019-09-17T05:05:19+02:00 ERROR cannot update mount namespace of snap "wpe-webkit-mir-kiosk": cannot update preserved namespace of snap "wpe-webkit-mir-kiosk": cannot update snap namespace: device or resource busy

As requested by @zyga-snapd on IRC, here’s the snap.yaml for wpe-webkit-mir-kiosk. I’ll put together a test snap with the same layouts ASAP.

name: wpe-webkit-mir-kiosk
version: 2.24.3
summary: *snip*
description: |
  *snip*
base: core18
architectures:
- armhf
confinement: strict
grade: stable
layout:
  /etc/fonts/conf.avail:
    bind: $SNAP/etc/fonts/conf.avail
  /etc/ssl/certs/ca-certificates.crt:
    bind-file: $SNAP/etc/ssl/certs/ca-certificates.crt
  /usr/lib/arm-linux-gnueabihf/wpe-webkit-1.0:
    bind: $SNAP/usr/lib/arm-linux-gnueabihf/wpe-webkit-1.0
  /usr/libexec/wpe-webkit-1.0:
    bind: $SNAP/usr/wpe-webkit-1.0
  /usr/local/share/fonts:
    bind: $SNAP/usr/share/fonts
  /usr/share/fonts:
    bind: $SNAP/usr/share/fonts
slots:
  dbus-cogctl:
    bus: system
    interface: dbus
    name: com.igalia.Cog
apps:
  browser:
    command: snap/command-chain/snapcraft-runner $SNAP/command-browser.wrapper
    daemon: simple
    environment:
      FONTCONFIG_FILE: ${SNAP}/etc/fonts/fonts.conf
      FONTCONFIG_PATH: ${SNAP}/etc/fonts/conf.d
      LIBGL_DRIVERS_PATH: ${SNAP}/usr/lib/arm-linux-gnueabihf/dri
      XDG_CACHE_HOME: $SNAP_COMMON/cache
      XDG_CONFIG_DIRS: ${SNAP}/etc/xdg:$XDG_CONFIG_DIRS
      XDG_DATA_DIRS: ${SNAP}/usr/share:$XDG_DATA_DIRS
      XDG_DATA_HOME: ${SNAP}/usr/share
      XKB_CONFIG_ROOT: ${SNAP}/usr/share/X11/xkb
      __EGL_VENDOR_LIBRARY_DIRS: $SNAP/etc/glvnd/egl_vendor.d:$SNAP/usr/share/glvnd/egl_vendor.d
    plugs:
    - wayland
    - opengl
    - network
    - network-bind
    - upower-observe
    - avahi-observe
    - network-manager
    - hostname-control
    - process-control
    restart-condition: always
    slots:
    - dbus-cogctl
1 Like

@zyga-snapd Had a few minutes this morning to identify the layout which causes this error:

layout:
  /usr/lib/$SNAPCRAFT_ARCH_TRIPLET/wpe-webkit-1.0:
    bind: $SNAP/usr/lib/$SNAPCRAFT_ARCH_TRIPLET/wpe-webkit-1.0

I guess it has something to do with the $SNAPCRAFT_ARCH_TRIPLET variable in the mount point, but I’ll leave that up to your knowledge of snapd’s inner workings :slight_smile:

For reference, this is the full snapcraft.yaml I ran my tests on.

expand snapcraft.yaml
name: snapd-layouts-test
base: core18
version: "0.1"
summary: A test to debug snap-update-ns issues.
description: see above
grade: stable
confinement: strict

layout:
  /usr/libexec/wpe-webkit-1.0:
    bind: $SNAP/usr/wpe-webkit-1.0
  /usr/lib/$SNAPCRAFT_ARCH_TRIPLET/wpe-webkit-1.0:
    bind: $SNAP/usr/lib/$SNAPCRAFT_ARCH_TRIPLET/wpe-webkit-1.0
  /etc/fonts/conf.avail:
    bind: $SNAP/etc/fonts/conf.avail
  /etc/ssl/certs/ca-certificates.crt:
    bind-file: $SNAP/etc/ssl/certs/ca-certificates.crt
  /usr/share/fonts:
    bind: $SNAP/usr/share/fonts
  /usr/local/share/fonts: # wpe-webkit: Search ALL the fonts!
    bind: $SNAP/usr/share/fonts

parts:
  mypart:
    plugin: nil
    source: .

apps:
  browser:
    command: pwd
    daemon: simple
    restart-condition: always

To test which layout causes the error, I followed this procedure:

  1. Build the snap locally (amd64, snapcraft 3.8)
  2. Install it with --dangerous
  3. Attempt to refresh with the same snap file (snap install --dangerous snapd-layouts-test_0.1_amd64.snap), which produced the expected error:
error: cannot perform the following tasks:
- Setup snap "snapd-layouts-test" (unset) security profiles (cannot setup mount for snap "snapd-layouts-test": cannot update mount namespace of snap "snapd-layouts-test": cannot update preserved namespace of snap "snapd-layouts-test": cannot update snap namespace: device or resource busy)
- Setup snap "snapd-layouts-test" (unset) security profiles (cannot update mount namespace of snap "snapd-layouts-test": cannot update preserved namespace of snap "snapd-layouts-test": cannot update snap namespace: device or resource busy)

Once I commented the one layout mentioned above, the refresh went through fine.

Hope that helps to pin down the issue :slight_smile:

1 Like

Thank you, I may conver this to a bug report on launchpad so that I get a number for a regression test. I am sprinting this week but if I manage to I will start by writing a regression test.

Can you please clarify one thing: which of the bases did you use? core or core18? EDIT: I see core18 above so I think that settles it.

I can open an issue on LP myself if it helps to reduce your workload, just not sure if that belongs to snapd or somewhere else.

Yes, snapd please.

Done, let me know if you need additional details there. Thanks in advance! Layouts still rock :smile:

1 Like

I’m trying to reproduce this but I’m failing with

snap    2.42~pre1.1
snapd   2.42~pre1.1
series  16
ubuntu  19.10
kernel  5.3.0-10-generic

Perhaps this bug is fixed in the 2.42 pre already?

@zyga-snapd is this related to the pair of bugs I discovered a few weeks ago with layouts causing a snap to fail to install/refresh? I recall there was an issue with situations where the mount namespace transition was getting in a wonky state specifically on snaps that were already set-up.

I just tested against core snap from edge (2.42~pre.1.1) on the same 19.04/kernel 5.0.0-29-generic machine as before, and the error still occurs. I also set up a daily:19.10 multipass VM, refreshed core from edge channel (now 16-2.42~pre1.1, rev 7831) – but the error still occurs when I install the snap and then “refresh” it through a second installation attempt.

In that case the trigger is more complex and may involve an application holding a reference to an open file (e.g. a library). I will expand my test and see what I can get.

It seems like a different case because of the EBUSY error that is returned from the kernel.

I managed to reproduce the issue and I am investigating the details now.

EDIT: This is the log from a failed installation. I will attempt to reduce the number of layout entries to get the minimal reproducer. https://pastebin.ubuntu.com/p/vNGKk3pCS9/

The actual error is on remove of the directory:

2019/09/19 12:03:01.191050 change.go:329: DEBUG: THIS IS THE PATCHED COPY
2019/09/19 12:03:01.191067 change.go:341: DEBUG: mount --make-rprivate "/usr/lib/x86_64-linux-gnu/wpe-webkit-1.0" (error: <nil>)
2019/09/19 12:03:01.191133 change.go:347: DEBUG: umount "/usr/lib/x86_64-linux-gnu/wpe-webkit-1.0" (error: <nil>)
2019/09/19 12:03:01.191200 change.go:358: DEBUG: openPath "/usr/lib/x86_64-linux-gnu/wpe-webkit-1.0" (error: <nil>)
2019/09/19 12:03:01.191219 change.go:367: DEBUG: fstatfs 11 (error: <nil>)
2019/09/19 12:03:01.191283 change.go:393: DEBUG: remove "/usr/lib/x86_64-linux-gnu/wpe-webkit-1.0" (error: remove /usr/lib/x86_64-linux-gnu/wpe-webkit-1.0: device or resource busy)

The directory that failed to unmount is a self-mount-point:

root@x240:/# cat /proc/self/mountinfo  | grep /usr/lib/x86_64-linux-gnu/wpe-webkit-1.0
707 708 7:16 /usr/lib/x86_64-linux-gnu/wpe-webkit-1.0 /usr/lib/x86_64-linux-gnu/wpe-webkit-1.0 ro,nodev,relatime master:361 - squashfs /dev/loop16 ro

I’m looking at untangling this state now. It may be a composition of two separate errors.

I kind of feel this is related to https://bugs.launchpad.net/snapd/+bug/1843423