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?
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.
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.
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.
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.
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.
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]
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.