Snap with configure hook cannot be updated in lxc

kyrofa 2017-05-11 19:32:47 UTC #1

The latest Nextcloud snap in stable does not have any hooks. The revision in the candidate channel, however, introduces the configure hook.

Say I have the stable one installed:

$ sudo snap install nextcloud

This installed revision 1284. And I update to the candidate (revision 1311):

$ sudo snap refresh --candidate nextcloud

I get this:

$ sudo snap refresh --candidate nextcloud
error: cannot perform the following tasks:
- Run configure hook of "nextcloud" snap if present (run hook "configure": cannot snap-exec: cannot find installed snap "nextcloud" at revision 1311)

Here’s the change:

$ snap change 27
Status  Spawn                 Ready                 Summary
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:35Z  Download snap "nextcloud" (1311) from channel "candidate"
Done    2017-05-11T19:23:21Z  2017-05-11T19:24:33Z  Fetch and check assertions for snap "nextcloud" (1311)
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:41Z  Mount snap "nextcloud" (1311)
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:40Z  Stop snap "nextcloud" services
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:39Z  Remove aliases for snap "nextcloud"
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:39Z  Make current revision for snap "nextcloud" unavailable
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:38Z  Copy snap "nextcloud" data
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:38Z  Setup snap "nextcloud" (1311) security profiles
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:36Z  Make snap "nextcloud" (1311) available to the system
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:36Z  Set automatic aliases for snap "nextcloud"
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:35Z  Setup snap "nextcloud" aliases
Undone  2017-05-11T19:23:21Z  2017-05-11T19:24:35Z  Start snap "nextcloud" (1311) services
Done    2017-05-11T19:23:21Z  2017-05-11T19:24:33Z  Clean up "nextcloud" (1311) install
Error   2017-05-11T19:23:21Z  2017-05-11T19:24:33Z  Run configure hook of "nextcloud" snap if present

......................................................................
Run configure hook of "nextcloud" snap if present

2017-05-11T19:24:33Z ERROR run hook "configure": cannot snap-exec: cannot find installed snap "nextcloud" at revision 1311

What’s happening? The services for revision 1311 have already started… how can it not be found?

$ snap --version
snap    2.24.1
snapd   2.24.1
series  16
ubuntu  16.04
kernel  4.4.0-77-generic

Call for testing: Nextcloud snap v11.0.3snap2

kyrofa 2017-05-11 19:54:22 UTC #2

Note that this is on lxc. I just tested this on normal Ubuntu and the upgrade went smoothly. I see denials like this on the host, wonder if this is confinement-related?

May 11 12:16:30 parallax kernel: [468834.501315] audit: type=1400 audit(1494530190.565:4275): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=10118 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.501325] audit: type=1400 audit(1494530190.565:4276): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=10118 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.585179] audit: type=1400 audit(1494530190.649:4277): apparmor="DENIED" operation="exec" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/bin/systemctl" pid=10181 comm="mysql.server" requested_mask="x" denied_mask="x" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.619522] audit: type=1400 audit(1494530190.681:4278): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.php-fpm" name="/run/systemd/journal/stdout" pid=10182 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.619531] audit: type=1400 audit(1494530190.681:4279): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.php-fpm" name="/run/systemd/journal/stdout" pid=10182 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.736088] audit: type=1400 audit(1494530190.801:4280): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.renew-certs" name="/run/systemd/journal/stdout" pid=10304 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.736098] audit: type=1400 audit(1494530190.801:4281): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.renew-certs" name="/run/systemd/journal/stdout" pid=10304 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
May 11 12:16:30 parallax kernel: [468834.849331] audit: type=1400 audit(1494530190.913:4282): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-nextcloud-migration-test_<var-lib-lxd>" profile="snap.nextcloud.apache" name="/run/systemd/journal/stdout" pid=10408 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000

kyrofa 2017-05-11 19:56:46 UTC #3

This might explain why updates have not gone so smoothly on lxc so far: none of the services ever come back up, requiring a container reboot. It was never fatal to the installation until now though, when the hook MUST run during installation.

jdstrand 2017-05-11 20:06:59 UTC #4

The ‘stdout’ denial is likely just noise, but it is fixed in snapd 2.25.

The systemctl denial is likely not harmless since the snap is trying to use systemctl, and that isn’t allowed (allowing it provides confinement escape) so whatever it tried to do didn’t happen. IIRC, snapd may be providing a convenient way for a snap to manage its own services. I don’t know the status of that work.

kyrofa 2017-05-11 20:10:37 UTC #5

Yeah I’m probably restarting mysql incorrectly, but it seems to work fine (both on none-lxc and lxc, as long as I’m not updating), so that’s also non-fatal. There must be something else going on.

jdstrand 2017-05-11 20:11:12 UTC #6

Well, it isn’t ‘just noise’. The snap is trying to log stuff but that is failing (that won’t cause the snap to fail though). This also means you aren’t getting the log messages to help you debug the issue. Update to snapd 2.25 and try your tests again. I suspect you’ll get better debugging output.

kyrofa 2017-05-11 20:49:29 UTC #7

Good idea. I updated to v2.25 and the host log starts only showing the (expected) exec denial and several status updates for the profiles being reloaded. However, finally got some interesting stuff in the container log:

May 11 20:33:08 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 38 on Do: Fetch and check assertions for snap "nextcloud" (1311)
May 11 20:33:11 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 39 on Do: Mount snap "nextcloud" (1311)
May 11 20:33:11 nextcloud-test systemd[1]: Reloading.
May 11 20:33:11 nextcloud-test systemd[1]: apt-daily.timer: Adding 11h 37min 41.017147s random time.
May 11 20:33:11 nextcloud-test systemd[1]: Reloading.
May 11 20:33:11 nextcloud-test systemd[1]: apt-daily.timer: Adding 7h 39min 6.086629s random time.
May 11 20:33:11 nextcloud-test systemd[1]: Mounting Mount unit for nextcloud...
May 11 20:33:11 nextcloud-test systemd[1]: Mounted Mount unit for nextcloud.
May 11 20:33:11 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 40 on Do: Stop snap "nextcloud" services
May 11 20:33:12 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.redis-server...
May 11 20:33:12 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.redis-server.
May 11 20:33:12 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.mysql...
May 11 20:33:12 nextcloud-test /usr/bin/snap[15354]: cmd.go:114: DEBUG: not restarting into "/snap/core/current/usr/bin/snap" ([VERSION=2.24 2.24]): older than "/usr/bin/snap" (2.25)
May 11 20:33:12 nextcloud-test snap[15354]: Shutting down MySQL
May 11 20:33:14 nextcloud-test snap[15354]: .. *
May 11 20:33:14 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.mysql.
May 11 20:33:14 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.nextcloud-cron...
May 11 20:33:14 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.nextcloud-cron.
May 11 20:33:15 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.renew-certs...
May 11 20:33:15 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.renew-certs.
May 11 20:33:15 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.mdns-publisher...
May 11 20:33:15 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.mdns-publisher.
May 11 20:33:15 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.php-fpm...
May 11 20:33:15 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.php-fpm.
May 11 20:33:15 nextcloud-test systemd[1]: Stopping Service for snap application nextcloud.apache...
May 11 20:33:15 nextcloud-test /usr/bin/snap[15398]: cmd.go:114: DEBUG: not restarting into "/snap/core/current/usr/bin/snap" ([VERSION=2.24 2.24]): older than "/usr/bin/snap" (2.25)
May 11 20:33:16 nextcloud-test snap[15398]: Making sure nextcloud is setup...
May 11 20:33:46 nextcloud-test systemd[1]: snap.nextcloud.apache.service: Stopping timed out. Terminating.
May 11 20:33:46 nextcloud-test snap[15398]: Waiting for PHP...
May 11 20:33:46 nextcloud-test systemd[1]: Stopped Service for snap application nextcloud.apache.
May 11 20:33:46 nextcloud-test systemd[1]: snap.nextcloud.apache.service: Unit entered failed state.
May 11 20:33:46 nextcloud-test systemd[1]: snap.nextcloud.apache.service: Failed with result 'timeout'.
May 11 20:33:46 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 41 on Do: Remove aliases for snap "nextcloud"
May 11 20:33:46 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 42 on Do: Make current revision for snap "nextcloud" unavailable
May 11 20:33:46 nextcloud-test systemd[1]: Reloading.
May 11 20:33:46 nextcloud-test systemd[1]: apt-daily.timer: Adding 7h 33min 850.722ms random time.
May 11 20:33:46 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 8h 24min 48.506155s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 8h 43min 17.126644s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 10h 5min 54.322204s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 5h 46min 31.362046s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 2h 50min 19.096627s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 8h 49min 7.242529s random time.
May 11 20:33:47 nextcloud-test systemd[1]: Reloading.
May 11 20:33:47 nextcloud-test systemd[1]: apt-daily.timer: Adding 2h 51min 7.438941s random time.
May 11 20:33:47 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 43 on Do: Copy snap "nextcloud" data
May 11 20:33:49 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 44 on Do: Setup snap "nextcloud" (1311) security profiles
May 11 20:33:50 nextcloud-test /usr/lib/snapd/snapd[15022]: task.go:303: DEBUG: 2017-05-11T20:33:50Z INFO cannot auto connect nextcloud:network to core:network: (plug auto-connection), existing connection state "nextcloud:network core:network" in the way
May 11 20:33:50 nextcloud-test /usr/lib/snapd/snapd[15022]: task.go:303: DEBUG: 2017-05-11T20:33:50Z INFO cannot auto connect nextcloud:network-bind to core:network-bind: (plug auto-connection), existing connection state "nextcloud:network-bind core:network-bind" in the way
May 11 20:33:52 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 45 on Do: Make snap "nextcloud" (1311) available to the system
May 11 20:33:53 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 46 on Do: Set automatic aliases for snap "nextcloud"
May 11 20:33:53 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 47 on Do: Setup snap "nextcloud" aliases
May 11 20:33:53 nextcloud-test /usr/lib/snapd/snapd[15022]: taskrunner.go:367: DEBUG: Running task 48 on Do: Start snap "nextcloud" (1311) services
May 11 20:33:53 nextcloud-test systemd[1]: Reloading.
May 11 20:33:53 nextcloud-test systemd[1]: apt-daily.timer: Adding 3h 5min 30.624304s random time.
May 11 20:33:53 nextcloud-test systemd[1]: Reloading.
May 11 20:33:53 nextcloud-test systemd[1]: apt-daily.timer: Adding 7h 3min 38.086143s random time.
May 11 20:33:53 nextcloud-test systemd[1]: Started Service for snap application nextcloud.nextcloud-cron.
May 11 20:33:53 nextcloud-test /usr/bin/snap[15689]: cmd.go:114: DEBUG: not restarting into "/snap/core/current/usr/bin/snap" ([VERSION=2.24 2.24]): older than "/usr/bin/snap" (2.25)
May 11 20:33:53 nextcloud-test systemd[1]: Reloading.
May 11 20:33:53 nextcloud-test snap[15689]: cannot snap-exec: cannot read info for "nextcloud": cannot find installed snap "nextcloud" at revision 1311
May 11 20:33:53 nextcloud-test systemd[1]: apt-daily.timer: Adding 4h 15min 59.462536s random time.
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.nextcloud-cron.service: Main process exited, code=exited, status=1/FAILURE
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.nextcloud-cron.service: Unit entered failed state.
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.nextcloud-cron.service: Failed with result 'exit-code'.
May 11 20:33:53 nextcloud-test systemd[1]: Reloading.
May 11 20:33:53 nextcloud-test systemd[1]: apt-daily.timer: Adding 1h 1min 33.309968s random time.
May 11 20:33:53 nextcloud-test systemd[1]: Started Service for snap application nextcloud.renew-certs.
May 11 20:33:53 nextcloud-test /usr/bin/snap[15739]: cmd.go:114: DEBUG: not restarting into "/snap/core/current/usr/bin/snap" ([VERSION=2.24 2.24]): older than "/usr/bin/snap" (2.25)
May 11 20:33:53 nextcloud-test snap[15739]: cannot snap-exec: cannot read info for "nextcloud": cannot find installed snap "nextcloud" at revision 1311
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.renew-certs.service: Main process exited, code=exited, status=1/FAILURE
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.renew-certs.service: Unit entered failed state.
May 11 20:33:53 nextcloud-test systemd[1]: snap.nextcloud.renew-certs.service: Failed with result 'exit-code'.

And so on and so forth while everything falls over.

Some interesting tidbits:

May 11 20:33:50 nextcloud-test /usr/lib/snapd/snapd[15022]: task.go:303: DEBUG: 2017-05-11T20:33:50Z INFO cannot auto connect nextcloud:network to core:network: (plug auto-connection), existing connection state "nextcloud:network core:network" in the way
May 11 20:33:50 nextcloud-test /usr/lib/snapd/snapd[15022]: task.go:303: DEBUG: 2017-05-11T20:33:50Z INFO cannot auto connect nextcloud:network-bind to core:network-bind: (plug auto-connection), existing connection state "nextcloud:network-bind core:network-bind" in the way

More of this:

May 11 20:33:53 nextcloud-test snap[15689]: cannot snap-exec: cannot read info for "nextcloud": cannot find installed snap "nextcloud" at revision 1311

I definitely think that’s why the updates have been wonky. Just not sure WHY that’s happening. It’s easy to duplicate though: fire up an lxc container, install nextcloud from stable, then refresh to candidate.

evan 2017-05-11 22:36:00 UTC #8

1675747 covers restarting services inside a snap.

kyrofa 2017-05-11 23:08:50 UTC #9

Thanks, although note that’s not what’s happening here.

niemeyer 2017-05-12 00:28:32 UTC #10

We’ve fixed a few auto-connections issues recently, and have more polishing to do on the upcoming list.

@zyga, would you mind to have a look here to see if that’s one of the known cases?

zyga 2017-05-12 07:52:06 UTC #11

Those two are harmless non-error messages. They are removed in 2.26 as they were just confusing.[quote=“kyrofa, post:7, topic:556”]
May 11 20:33:53 nextcloud-test snap[15689]: cannot snap-exec: cannot read info for “nextcloud”: cannot find installed snap “nextcloud” at revision 1311
[/quote]

This one is more interesting. Let me dig and see

jdstrand 2017-05-12 11:48:38 UTC #12

Thanks Evan. I’ve updated that bug with a few details and possible ways to move forward.

kyrofa 2017-05-12 15:26:30 UTC #13

Please let me know what you learn! I may have to revert this feature before release. I’ll still have the problem of services not starting up after upgrade in lxc, but at least it won’t be fatal to the upgrade.

kyrofa 2017-05-15 20:13:21 UTC #14

Note that this issue applies to normal apps as well: nothing is runnable after an upgrade. I logged LP: #1690906 for this.

kyrofa 2017-05-22 21:59:09 UTC #15

Any update on this? It’s standing in the way of some important features.