Snap's daemons have no log when running in lxc

I have an Ubuntu 16.04 lxc container:

$ snap --version
snap    2.23.6
snapd   2.23.6
series  16
ubuntu  16.04
kernel  4.4.0-72-generic

I also have an Ubuntu 16.04 laptop:

$ snap --version
snap    2.23.6
snapd   2.23.6
series  16
ubuntu  16.04
kernel  4.4.0-72-generic

When I install the Nextcloud snap on my laptop, looking at the log of one of its daemons looks like this:

$ systemctl status snap.nextcloud.mysql.service 
● snap.nextcloud.mysql.service - Service for snap application nextcloud.mysql
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.mysql.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2017-04-13 15:07:45 PDT; 3min 2s ago
 Main PID: 8020 (start_mysql)
    Tasks: 30
   Memory: 284.4M
      CPU: 2.712s
   CGroup: /system.slice/snap.nextcloud.mysql.service
           ├─8020 /bin/sh /snap/nextcloud/1182/bin/start_mysql
           ├─8372 /bin/sh /snap/nextcloud/1182/bin/mysqld_safe --datadir=/var/snap/nextcloud/1182/mysql
           ├─8542 /snap/nextcloud/1182/bin/mysqld --basedir=/snap/nextcloud/1182 --datadir=/var/snap/ne
           └─9055 sleep 1

Apr 13 15:07:53 Pandora snap[8020]: The sys schema is already up to date (version 1.5.0).
Apr 13 15:07:53 Pandora snap[8020]: Checking databases.
Apr 13 15:07:53 Pandora snap[8020]: sys.sys_config                                     OK
Apr 13 15:07:53 Pandora snap[8020]: Upgrade process completed successfully.
Apr 13 15:07:53 Pandora snap[8020]: Checking if update is needed.
Apr 13 15:07:53 Pandora snap[8020]: Restarting mysql server after upgrade...
Apr 13 15:07:53 Pandora snap[8020]: Shutting down MySQL
Apr 13 15:07:55 Pandora snap[8020]: .. *
Apr 13 15:07:55 Pandora snap[8020]: Starting MySQL
Apr 13 15:07:56 Pandora snap[8020]: . *

You see MySQL doing stuff. When I run the same command in the lxc container:

$ systemctl status snap.nextcloud.mysql.service 
● snap.nextcloud.mysql.service - Service for snap application nextcloud.mysql
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.mysql.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2017-04-13 21:57:55 UTC; 13min ago
 Main PID: 3955 (start_mysql)
    Tasks: 31
   Memory: 864.0M
      CPU: 2.917s
   CGroup: /system.slice/snap.nextcloud.mysql.service
           ├─3955 /bin/sh /snap/nextcloud/1182/bin/start_mysql
           ├─4003 /bin/sh /snap/nextcloud/1182/bin/mysqld_safe --datadir=/var/snap/nextcloud/1182/mysql -
           ├─4254 /snap/nextcloud/1182/bin/mysqld --basedir=/snap/nextcloud/1182 --datadir=/var/snap/next
           └─5368 sleep 1

Apr 13 21:57:55 nextcloud systemd[1]: Started Service for snap application nextcloud.mysql.
Apr 13 21:57:55 nextcloud /usr/bin/snap[3955]: cmd.go:111: DEBUG: restarting into "/snap/core/current/usr

That’s it. Initially I thought it hit an error somewhere, but no: Nextcloud seems to work fine in both places. It’s just that none of the services show any output: not in syslog, not in systemd. That makes it very difficult to debug if something goes wrong.

Any idea what’s going on here?

is the journald process running inside the container ?

It seems so:

$ ps ax | grep journald
   55 ?        Ss     0:00 /lib/systemd/systemd-journald
14842 ?        S+     0:00 grep --color=auto journald

And it’s not like there’s NO log there: it gets the “DEBUG: restarting into[…]” message. But nothing from the daemons themselves. Weird eh?

That sound like something @stgraber might have a good idea.

[12479.684770] audit: type=1400 audit(1492742089.314:958): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=20630 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
[12479.684794] audit: type=1400 audit(1492742089.314:959): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=20630 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
[12479.732456] audit: type=1400 audit(1492742089.362:960): apparmor="DENIED" operation="exec" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/bin/systemctl" pid=20651 comm="mysql.server" requested_mask="x" denied_mask="x" fsuid=100000 ouid=100000
[12479.746055] audit: type=1400 audit(1492742089.374:961): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746076] audit: type=1400 audit(1492742089.374:962): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="/usr/lib/snapd/snap-confine" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746106] audit: type=1400 audit(1492742089.374:963): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746120] audit: type=1400 audit(1492742089.374:964): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="/usr/lib/snapd/snap-confine" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746137] audit: type=1400 audit(1492742089.374:965): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746150] audit: type=1400 audit(1492742089.374:966): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="/usr/lib/snapd/snap-confine" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0
[12479.746165] audit: type=1400 audit(1492742089.374:967): apparmor="DENIED" operation="file_perm" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/apparmor/.null" pid=20630 comm="mysql.server" requested_mask="w" denied_mask="w" fsuid=100000 ouid=0

Some of those entries are just apparmor being overly verbose, but some of those are denials which prevent logging, specifically:

[12479.684770] audit: type=1400 audit(1492742089.314:958): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=20630 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
[12479.684794] audit: type=1400 audit(1492742089.314:959): apparmor="DENIED" operation="file_inherit" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/run/systemd/journal/stdout" pid=20630 comm="snap-exec" requested_mask="wr" denied_mask="wr" fsuid=100000 ouid=100000
[12479.732456] audit: type=1400 audit(1492742089.362:960): apparmor="DENIED" operation="exec" namespace="root//lxd-test_<var-lib-lxd>" profile="snap.nextcloud.mysql" name="/bin/systemctl" pid=20651 comm="mysql.server" requested_mask="x" denied_mask="x" fsuid=100000 ouid=100000

This looks like another case where apparmor doesn’t behave the same way inside a container as it does outside. There has been a number of those and the file_inherit ones are pretty common.

You’ll need to talk to John on the AppArmor team who will be able to tell you if there’s something that can be done at the kernel level to fix things without requiring profile changes or will at least be able to tell you what profile changes to do in snapd to avoid this problem.

@tyhicks @jdstrand

This is definitely a problem and I’ll fix that right now.

This should have nothing to do with logging. I suspect the snap is trying to control its daemon via the systemctl command and it should be modified to do this another way (we currently can’t finely mediate systemctl due to its design and implementation-- as was seen with previous interface PRs, granting this access spirals out into giving (essentially) device ownership to the snap).

In the meantime, can you try adding to /var/lib/snapd/apparmor/profiles/snap.nextcloud.mysql the following:

/run/systemd/journal/stdout rw,

then running:

$ sudo apparmor_parser -r /var/lib/snapd/apparmor/profiles/snap.nextcloud.mysql

and report back if logging is working?

@jdstrand indeed, adding that line seems to fix things, thank you!

@stgraber thanks for jumping in, I wasn’t even sure where to start debugging that :slight_smile: .

@niemeyer if there’s a difference in how snaps run in lxc versus outside, does the snapd team run any of their spread tests in lxc?

https://github.com/snapcore/snapd/pull/3218

We don’t run any tests in containers today.

Perhaps that would be worth investigating if snaps-in-lxc is an important story?

1 Like

Yes, I think it should be possible to run such tests recursively in spread but someone would have just sit and do it. I think it’s a very important test.

+1 on snaps-in-lxc is an important story, as there are some Network-attached storage companies are interested in running snapd in a container on their own linux distro.

1 Like

One problem with containers is that the test matrix grows significantly. Even if we test that Ubuntu 16.04 can run an Ubuntu 16.04 container and snapd there’s no guarantee that snapd in a random container on a random host does work. Still, we should start with something.

1 Like

@jdstrand’s PR is in.

Yes, let’s start with at least having some testing in LXD. It doesn’t have to be the full matrix when starting… just having some level of testing will be better than having none. We can then see how to improve the situation further once/if necessary.

2 Likes