Install/refresh stuck at configure hook (Wekan)

[Jani Uusitalo]

Since some time over the holidays I've had problems refreshing/installing the Wekan snap [1] on my home server and also my desktop. The installation stalls at the configuration phase, which on the surface looks a bit like bug #1674193 [2], but here core gets installed just fine, and the hang occurs just alike if I first install just core, then the `wekan` snap separately.

    14.52 jani@saegusa:~$ sudo snap install wekan
    [sudo] salasana henkilölle jani:
    error: cannot perform the following tasks:
    - Run configure hook of "wekan" snap if present (run hook "configure": <exceeded maximum runtime of 5m0s>)

Installing other snaps works (the couple that I tried just to be able to say this did anyway).

I've reported this on the Wekan snap Github page [3], but there's been no confirmation from anyone else affected so far. Also, I'm unable to reproduce this myself in a VM and on at least one other (physical) desktop I have access to.

So naturally I've looked for differences between these systems, but so far the only correlating one I'm pretty sure of is an Apparmor denial:

    apparmor="DENIED" operation="open" profile="snap.wekan.mongodb" name="/sys/block/" pid=9478 comm="mongod" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

The two systems where Apparmor denies mongodb's access to /sys/block get stuck at the configure hook, whereas systems that don't deny access finish the configuration (and installation) successfully.

I have not tweaked any Apparmor configuration on any of these systems prior to this issue cropping up (not that I can remember anyway). I've also not touched anything snap-related, as Wekan was one of the first snaps I've ever tried and is (or would be) the only one (besides core) currently installed on these systems.

All systems are running Ubuntu 16.04, with my (affected) desktop having both HWE and -proposed enabled, my (affected) server running a 4.4-series kernel (no HWE or -proposed) and the other (unaffected) desktop having HWE but no -proposed. The (unaffected) VM starts with kernel 4.4 and remains unaffected if I upgrade it with HWE.

I'm submitting this from the (HWE+proposed-enabled) desktop, so any logs attached here are from one of the two affected systems. I'll of course provide other logs too if requested.

* [1] https://snapcraft.io/wekan/
* [2] https://bugs.launchpad.net/snappy/+bug/1674193
* [3] https://github.com/wekan/wekan-snap/issues/25

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: snapd 2.29.4.2
ProcVersionSignature: Ubuntu 4.13.0-30.33~16.04.1-generic 4.13.13
Uname: Linux 4.13.0-30-generic x86_64
ApportVersion: 2.20.1-0ubuntu2.15
Architecture: amd64
CurrentDesktop: Unity
Date: Mon Jan 22 15:44:20 2018
InstallationDate: Installed on 2016-10-13 (466 days ago)
InstallationMedia: Ubuntu-Server 16.04.1 LTS "Xenial Xerus" - Release amd64 (20160719)
SourcePackage: snapd
UpgradeStatus: No upgrade log present (probably fresh install)
mtime.conffile..etc.X11.Xsession.d.65snappy: 2018-01-19T18:18:12.001969
mtime.conffile..etc.apparmor.d.usr.lib.snapd.snap-confine.real: 2018-01-22T15:46:34.793893

[Jani Uusitalo (uusijani)]

Update: got snapd 2.31.1 from -proposed this morning, and replaced the customized /etc/apparmor.d/usr.lib.snapd.snap-confine.real with the package-provided version. This did not fix the issue unfortunately.

[Jamie Strandboge (jdstrand)]

The /sys/block access is being denied to your snap, not snap-confine. Access to /sys/block is provided via the hardware-observe interface. Does wekan plug hardware-observe? Is it shown as connected via 'snap interfaces'? If not, what happens if you connect it with 'snap connect'?

As for install/refresh being 'stuck', are (wekan) commands from the install/refresh hooks still running when it is 'stuck'? If so, it may not be handling an error condition gracefully.

[Jani Uusitalo (uusijani)]

The Apparmor denial seems to no longer occur with 2.31.1.

`snap interfaces` lists 'wekan' connected to network and network-bind, but not hardware-observe. I'm struggling with the correct syntax for manually connecting it to anything:

root@saegusa:~# snap connect wekan :hardware-observe
error: cannot resolve connection, plug snap name is empty
root@saegusa:~# snap connect wekan:wekan :hardware-observe
error: snap "wekan" has no plug named "wekan"
root@saegusa:~# snap connect wekan: :hardware-observe
error: invalid value: "wekan:" (want snap:name or snap)
root@saegusa:~# snap connect :wekan :hardware-observe
error: cannot resolve connection, plug snap name is empty

`snap interfaces` does list a 'wekan:mongodb-plug', which (if I'm reading the output right) is unattached. Attempting to connect that to hardware observe:

root@saegusa:~# snap connect wekan:mongodb-plug :hardware-observe
error: cannot connect wekan:mongodb-plug ("content" interface) to core:hardware-observe
       ("hardware-observe" interface)

There's also a 'wekan:mongodb-slot'. Attempting to connect mongodb-plug to that:

root@saegusa:~# snap connect wekan:mongodb-plug wekan:mongodb-slot
error: snap "wekan" has "install-snap" change in progress

That's true, since I'm only able to see those two during the time that the installation is stuck.

I'll attach the full output of `snap interfaces` below. It's the same output that `snap interfaces` produces on the VM without the issue (after installation, when the service is running).

As for the other question, there are wekan-related commands running when it's stuck (listing below). The service seems to be up and running already (I can open it in a browser) for the time it remains in the configuration phase, but when the hook times out it of course gets cancelled and the installation is undone.

root@saegusa:~# ps aux | grep wekan
root 10517 1.2 0.1 935608 23360 pts/22 Sl+ 17:45 0:00 snap install wekan
root 10782 0.0 0.0 18056 2760 ? Ss 17:45 0:00 /bin/bash /snap/wekan/124/bin/mongodb-control
root 10809 4.4 0.3 283812 54748 ? Sl 17:45 0:01 mongod --dbpath /var/snap/wekan/common --logpath /var/snap/wekan/common/mongodb.log --logappend --journal --unixSocketPrefix /var/snap/wekan/124/share --port 27019
root 10811 0.0 0.0 18052 2892 ? S 17:45 0:00 /bin/bash /snap/wekan/124/meta/hooks/configure
root 10871 0.0 0.0 18056 2676 ? Ss 17:45 0:00 /bin/bash /snap/wekan/124/bin/wekan-control
root 10898 7.6 0.6 1172036 103648 ? Sl 17:45 0:02 /snap/wekan/124/bin/node main.js
root 10975 0.0 0.0 15464 1012 pts/23 S+ 17:46 0:00 grep --color=auto wekan

[Jamie Strandboge (jdstrand)]

The output of snap interfaces indicates that wekan does not plug hardware-observe. If it did, you would see this in snap interfaces:

$ snap interfaces
Slot Plug
...
:hardware-observe -
...
- wekan:hardware-observe
...

See 'snap connect --help' for information on the syntax.

*If* wekan plugged hardware-observe, the syntax would be:
$ snap connect wekan:hardware-observe

[Jamie Strandboge (jdstrand)]

As for install/refresh getting stuck, it seems that the wekan hooks aren't exiting so snapd has no choice but to wait a while then timeout.

At this point, this seems like the issues are in the wekan snap: it needs to plug hardware-observe and needs to handle error conditions better in the hooks so the exit.

I'm going to mark this bug against snapd as Invalid. Please report back if you feel this is in error. Thank you for reporting a bug!

[Jani Uusitalo (uusijani)]

Alright, thanks Jamie!