containers won't start after lxc and apparmor upgrades in trusty

[Alex Muntada]

On January 19 lxc and apparmor were upgraded on our VPN servers:

2017-01-19 06:30:36 upgrade libdbus-1-3:amd64 1.6.18-0ubuntu4.4 1.6.18-0ubuntu4.5
2017-01-19 06:30:37 upgrade python3-lxc:amd64 1.0.8-0ubuntu0.4 1.0.9-0ubuntu2
2017-01-19 06:30:38 upgrade libapparmor1:amd64 2.8.95~2430-0ubuntu5.3 2.10.95-0ubuntu2.5~14.04.1
2017-01-19 06:30:38 upgrade libapparmor-perl:amd64 2.8.95~2430-0ubuntu5.3 2.10.95-0ubuntu2.5~14.04.1
2017-01-19 06:30:38 upgrade apparmor:amd64 2.8.95~2430-0ubuntu5.3 2.10.95-0ubuntu2.5~14.04.1
2017-01-19 06:30:39 upgrade lxc-templates:amd64 1.0.8-0ubuntu0.4 1.0.9-0ubuntu2
2017-01-19 06:30:40 upgrade liblxc1:amd64 1.0.8-0ubuntu0.4 1.0.9-0ubuntu2
2017-01-19 06:30:40 upgrade lxc:amd64 1.0.8-0ubuntu0.4 1.0.9-0ubuntu2
2017-01-19 06:30:41 upgrade libseccomp2:amd64 2.1.0+dfsg-1 2.1.1-1ubuntu1~trusty3
2017-01-19 06:30:42 upgrade dbus:amd64 1.6.18-0ubuntu4.4 1.6.18-0ubuntu4.5

The day after, the servers were rebooted and the application containers running the OpenVPN instances failed to start:

+ lxc-execute -n network-vpn -f /server/network.vpn/lxc/lxc.conf -- /server/network.vpn/lxc/lxc-start.sh
lxc-execute: utils.c: safe_mount: 1391 No such file or directory - Failed to mount proc onto /proc
lxc-execute: conf.c: tmp_proc_mount: 4132 No such file or directory - failed to mount /proc in the container.
lxc-execute: lsm/apparmor.c: apparmor_process_label_get: 80 No such file or directory - opening /proc/1/attr/current
lxc-execute: lsm/apparmor.c: apparmor_process_label_set: 191 No such file or directory - failed to change apparmor profile to lxc-container-default
lxc-execute: sync.c: __sync_wait: 57 An error occurred in another process (expected sequence number 5)
lxc-execute: start.c: __lxc_start: 1149 failed to spawn 'network-vpn'
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing hugetlb:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing perf_event:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing blkio:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing freezer:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing devices:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing memory:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing name=systemd:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing cpuacct:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing cpu:lxc/network-vpn
lxc-execute: cgmanager.c: cgm_remove_cgroup: 523 call to cgmanager_remove_sync failed: invalid request
lxc-execute: cgmanager.c: cgm_remove_cgroup: 525 Error removing cpuset:lxc/network-vpn

We had to downgrade lxc, apparmor and related packages to the latest version from trusty-security instead of trusty-updates to get the VPN up and running again.

Details:

No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 14.04.5 LTS
Release: 14.04
Codename: trusty

3.13.0-107-generic #154-Ubuntu SMP Tue Dec 20 09:57:27 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

Any clue about what's going on?

Thanks,
Alex

[Alex Muntada (alex.muntada)]

lxc.conf with obfuscated IP addresses.

[Alex Muntada (alex.muntada)]

This is what I get on a trusty vagrant box with latest kernel, lxc and apparmor from trusty-updates:

root@vagrant-ubuntu-trusty-64:~# lxc-execute --name guest -- echo foobar
lxc-execute: utils.c: safe_mount: 1391 No such file or directory - Failed to mount proc onto /proc
lxc-execute: conf.c: tmp_proc_mount: 4132 No such file or directory - failed to mount /proc in the container.
lxc-execute: lsm/apparmor.c: apparmor_process_label_get: 80 No such file or directory - opening /proc/1/attr/current
lxc-execute: lsm/apparmor.c: apparmor_process_label_set: 191 No such file or directory - failed to change apparmor profile to lxc-container-default
lxc-execute: sync.c: __sync_wait: 57 An error occurred in another process (expected sequence number 5)
lxc-execute: start.c: __lxc_start: 1149 failed to spawn 'guest'

This is what I get on a trusty vagrant box with lxc and apparmor from trusty-security:

root@vagrant-ubuntu-trusty-64:~# lxc-execute --name test -- echo foobar
lxc: cgmanager.c: lxc_cgmanager_escape: 331 call to cgmanager_move_pid_abs_sync(hugetlb) failed: Escape request from different namespace requires a proxy
init.lxc: initutils.c: mount_fs: 36 failed to mount /proc : Device or resource busy
foobar

Note that no foobar is shown in the first scenario, so something seems broken on the recent updates.

[Alex Muntada (alex.muntada)]

Running as root: strace -f -o lxc-execute.log -- lxc-execute --name test -- echo foobar

...
3274 access("/var/lib/lxc", X_OK) = 0
3274 open("/proc/self/mountinfo", O_RDONLY) = 7
3274 fstat(7, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
3274 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd5e4334000
3274 read(7, "74 73 8:1 / / rw,relatime - ext4"..., 1024) = 1024
3274 read(7, "release-agent.cpu\n86 83 0:25 / /"..., 1024) = 1024
3274 read(7, "odev,noexec,relatime - cgroup sy"..., 1024) = 490
3274 read(7, "", 1024) = 0
3274 close(7) = 0
3274 munmap(0x7fd5e4334000, 4096) = 0
3274 mount("", "/", NULL, MS_REC|MS_SLAVE, NULL) = 0
3274 access("echo", F_OK) = -1 ENOENT (No such file or directory)
3274 readlink("/proc/self", "3274", 20) = 4
3274 umount("/proc", MNT_DETACH) = 0
3274 open("/", O_RDONLY) = 7

========== Problem starts here? ==========

3274 openat(7, "proc", O_RDONLY|O_NOFOLLOW) = 8
3274 close(7) = 0
3274 mount("proc", "/proc/self/fd/8", "proc", 0, NULL) = -1 ENOENT (No such file or directory)

========== Errors start to show ==========

3274 close(8) = 0
3274 write(3, " lxc-execute 1485521866.885 E"..., 138) = 138
3274 write(2, "lxc-execute: ", 13) = 13
3274 write(2, "utils.c: safe_mount: 1391 ", 26) = 26
3274 write(2, "No such file or directory - Fail"..., 59) = 59
...

I'm not sure why this mount call fails, but it may be related to apparmor since running without it works fine, even with latest lxc updates:

vagrant@vagrant-ubuntu-trusty-64:~$ sudo lxc-execute --name test --define lxc.aa_profile=unconfined echo foobar
lxc-execute: utils.c: safe_mount: 1391 No such file or directory - Failed to mount proc onto /proc
lxc-execute: conf.c: tmp_proc_mount: 4132 No such file or directory - failed to mount /proc in the container.
lxc-execute: lsm/apparmor.c: apparmor_process_label_get: 80 No such file or directory - opening /proc/1/attr/current
lxc-execute: lsm/apparmor.c: apparmor_process_label_get: 80 No such file or directory - opening /proc/1/attr/current
foobar

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[linas (linasvepstas)]

fwiw: me too - I'm hitting a related bug; same timeframe I assume similar reasons. Debugging now.

[Stéphane Graber (stgraber)]

anyone still affected by this?

[Alex Muntada (alex.muntada)]

IIRC the issue was gone after upgrading to xenial.