lxc exec not working in xenial

[kevin gunn]

My host is on the very latest Xenial as of yesterday Feb9,2016

My work flow has been...
$ newgrp lxd
$ lxc images:ubuntu/xenial/amd64 xen
$ lxc start xen
$ lxc exec xen -- /bin/bash

at the moment, the image creation works, i can list my images - and it says they are running
however, upon exec i'm not logged onto the shell - no output, even if i pass --verbose=true

[Tycho Andersen (tycho-s)]

I've heard reports of this on ppc64el as well; I thought it was just there, but perhaps not.

[Stéphane Graber (stgraber)]

On a clean Xenial install here:

ubuntu@canonical-lxd:~$ lxc remote add images images.linuxcontainers.org
ubuntu@canonical-lxd:~$ lxc init images:ubuntu/xenial/amd64 xen
Creating xen
Retrieving image: 100%
ubuntu@canonical-lxd:~$ lxc start xen
ubuntu@canonical-lxd:~$ lxc exec xen -- /bin/bash
root@xen:~#

[kevin gunn (kgunn72)]

any hints on how can i debug further - i was heavily relying on this, and after updating yesterday it doesn't work.

[Serge Hallyn (serge-hallyn)]

What do the following show exactly:

ps -ef

lxc info xen

for the 'Init:' line in the previous output,

ls -l /proc/<pid>/root/proc

strace -f -oxx lxc exec xen -- bash

(and attach the 'xx' file which that created)

[kevin gunn (kgunn72)]

thanks! here's the first few queries

kg@kg-MacBookPro:~$ lxc start xen
kg@kg-MacBookPro:~$ lxc list
+------+---------+----------------------+------+-----------+-----------+
| NAME | STATE | IPV4 | IPV6 | EPHEMERAL | SNAPSHOTS |
+------+---------+----------------------+------+-----------+-----------+
| xen | RUNNING | 192.168.30.81 (eth0) | | NO | 0 |
+------+---------+----------------------+------+-----------+-----------+
kg@kg-MacBookPro:~$ lxc exec xen -- /bin/bash
kg@kg-MacBookPro:~$ ps -ef
UID PID PPID C STIME TTY TIME CMD
root 1 0 0 14:49 ? 00:00:06 /sbin/init splash
root 2 0 0 14:49 ? 00:00:00 [kthreadd]
root 3 2 0 14:49 ? 00:00:00 [ksoftirqd/0]
root 5 2 0 14:49 ? 00:00:00 [kworker/0:0H]
root 7 2 0 14:49 ? 00:00:02 [rcu_sched]
root 8 2 0 14:49 ? 00:00:00 [rcu_bh]
root 9 2 0 14:49 ? 00:00:00 [migration/0]
root 10 2 0 14:49 ? 00:00:00 [watchdog/0]
root 11 2 0 14:49 ? 00:00:00 [watchdog/1]
root 12 2 0 14:49 ? 00:00:00 [migration/1]
root 13 2 0 14:49 ? 00:00:00 [ksoftirqd/1]
root 15 2 0 14:49 ? 00:00:00 [kworker/1:0H]
root 16 2 0 14:49 ? 00:00:00 [watchdog/2]
root 17 2 0 14:49 ? 00:00:00 [migration/2]
root 18 2 0 14:49 ? 00:00:00 [ksoftirqd/2]
root 20 2 0 14:49 ? 00:00:00 [kworker/2:0H]
root 21 2 0 14:49 ? 00:00:00 [watchdog/3]
root 22 2 0 14:49 ? 00:00:00 [migration/3]
root 23 2 0 14:49 ? 00:00:00 [ksoftirqd/3]
root 25 2 0 14:49 ? 00:00:00 [kworker/3:0H]
root 26 2 0 14:49 ? 00:00:00 [kdevtmpfs]
root 27 2 0 14:49 ? 00:00:00 [netns]
root 28 2 0 14:49 ? 00:00:00 [perf]
root 29 2 0 14:49 ? 00:00:00 [khungtaskd]
root 30 2 0 14:49 ? 00:00:00 [writeback]
root 31 2 0 14:49 ? 00:00:00 [ksmd]
root 32 2 0 14:49 ? 00:00:00 [khugepaged]
root 33 2 0 14:49 ? 00:00:00 [crypto]
root 34 2 0 14:49 ? 00:00:00 [kintegrityd]
root 35 2 0 14:49 ? 00:00:00 [bioset]
root 36 2 0 14:49 ? 00:00:00 [kblockd]
root 37 2 0 14:49 ? 00:00:00 [ata_sff]
root 38 2 0 14:49 ? 00:00:00 [md]
root 39 2 0 14:49 ? 00:00:00 [devfreq_wq]
root 44 2 0 14:49 ? 00:00:00 [kswapd0]
root 45 2 0 14:49 ? 00:00:00 [vmstat]
root 46 2 0 14:49 ? 00:00:00 [fsnotify_mark]
root 47 2 0 14:49 ? 00:00:00 [ecryptfs-kthrea]
root 62 2 0 14:49 ? 00:00:00 [kthrotld]
root 63 2 0 14:49 ? 00:00:00 [acpi_thermal_pm]
root 64 2 0 14:49 ? 00:00:00 [bioset]
root 65 2 0 14:49 ? 00:00:00 [bioset]
root 66 2 0 14:49 ? 00:00:00 [bioset]
root 67 2...

[kevin gunn (kgunn72)]

and the strace

[Stéphane Graber (stgraber)]

sudo ls -lh /var/lib/lxd/containers/xen/rootfs/bin/bash
lxc exec xen --debug -- /bin/bash
lxc exec xen --debug -- /bin/sh

[kevin gunn (kgunn72)]

thanks guys.../bin/bash is there, here's the debug

kg@kg-MacBookPro:~$ sudo ls -lh /var/lib/lxd/containers/xen/rootfs/bin/bash
-rwxr-xr-x 1 100000 100000 1014K Aug 31 18:27 /var/lib/lxd/containers/xen/rootfs/bin/bash
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$ lxc exec xen --debug -- /bin/bash
DBUG[02-10|16:16:00] Posting {"command":["/bin/bash"],"environment":{"HOME":"/root","TERM":"xterm-256color","USER":"root"},"interactive":true,"wait-for-websocket":true}
 to http://unix.socket/1.0/containers/xen/exec
DBUG[02-10|16:16:00] Raw response: {"type":"async","status":"Operation created","status_code":100,"metadata":{"id":"5bf6d53f-2a80-42e3-b1b9-dd0af8a7ff48","class":"websocket","created_at":"2016-02-10T16:16:00.215763903-06:00","updated_at":"2016-02-10T16:16:00.215763903-06:00","status":"Running","status_code":103,"resources":{"containers":["/1.0/containers/xen"]},"metadata":{"fds":{"0":"8d5ad0388f8e0c01fa03aba878595de8a80010bf4edfdddb5bada4072701c327","control":"68992bf7b75f29f26e03c658bfaddd2222777f19b8ac4ab3f390c401a3794255"}},"may_cancel":false,"err":""},"operation":"/1.0/operations/5bf6d53f-2a80-42e3-b1b9-dd0af8a7ff48"}

DBUG[02-10|16:16:00] Window size is now: 128x41
DBUG[02-10|16:16:00] got message barrier
DBUG[02-10|16:16:00] 1.0/operations/5bf6d53f-2a80-42e3-b1b9-dd0af8a7ff48/wait
DBUG[02-10|16:16:00] Raw response: {"type":"sync","status":"Success","status_code":200,"metadata":{"id":"5bf6d53f-2a80-42e3-b1b9-dd0af8a7ff48","class":"websocket","created_at":"2016-02-10T16:16:00.215763903-06:00","updated_at":"2016-02-10T16:16:00.234663086-06:00","status":"Success","status_code":200,"resources":{"containers":["/1.0/containers/xen"]},"metadata":{"return":-1},"may_cancel":false,"err":""},"operation":""}

kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$
kg@kg-MacBookPro:~$ lxc exec xen --debug -- /bin/sh
DBUG[02-10|16:16:08] Posting {"command":["/bin/sh"],"environment":{"HOME":"/root","TERM":"xterm-256color","USER":"root"},"interactive":true,"wait-for-websocket":true}
 to http://unix.socket/1.0/containers/xen/exec
DBUG[02-10|16:16:08] Raw response: {"type":"async","status":"Operation created","status_code":100,"metadata":{"id":"6dd3cafb-d3fa-4b63-b280-bcca2bf02370","class":"websocket","created_at":"2016-02-10T16:16:08.704284737-06:00","updated_at":"2016-02-10T16:16:08.704284737-06:00","status":"Running","status_code":103,"resources":{"containers":["/1.0/containers/xen"]},"metadata":{"fds":{"0":"3f39ed8e61eacdc6868ba4a227218dcb3c6c57d09ccd1e8eafd76dbd5ab6fba4","control":"33564bde9ad301a6b5f737d4bb7c6e57d2f0d048a7e52c9a7ce0f737b6a13a8a"}},"may_cancel":false,"err":""},"operation":"/1.0/operations/6dd3cafb-d3fa-4b63-b280-bcca2bf02370"}

DBUG[02-10|16:16:08] Window size is now: 128x41
DBUG[02-10|16:16:08] got message barrier
DBUG[02-10|16:16:08] 1.0/operations/6dd3cafb-d3fa-4b63-b280-bcca2bf02370/wait
DBUG[02-10|16:16:08] Raw response: {"type":"sync","status":"Success","status_code":200,"metadata":{"id":"6dd3cafb-d3fa-4b63-b280-bcca2bf02370","class":"websocket","created_at":"2016-02-10T16:16:08.704284737-06:00","updated_at":"2016-02-10T16:16:08.723466987-06:00","st...

[Stéphane Graber (stgraber)]

Okay, so the binary is there but it's failing to execute for some reason... The return = -1 hints that the kernel failed to exec the binary.

Can you paste "dmesg" and also try
lxc exec xen /bin/static-sh

[Stéphane Graber (stgraber)]

Nevermind the static-sh thing, it's not installed by default in that image.

[Stéphane Graber (stgraber)]

The following may be interesting too:
sudo chroot /var/lib/lxd/containers/xen/rootfs /bin/bash

[kevin gunn (kgunn72)]

dmesg

kg@kg-MacBookPro:~$ lxc exec xen -- /bin/bash
kg@kg-MacBookPro:~$ dmesg
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 4.4.0-2-generic (buildd@lgw01-12) (gcc version 5.3.1 20160121 (Ubuntu 5.3.1-7ubuntu1) ) #16-Ubuntu SMP Thu Jan 28 15:44:21 UTC 2016 (Ubuntu 4.4.0-2.16-generic 4.4.0)
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.4.0-2-generic root=UUID=a717fc35-6e65-4458-a3d7-2036796d0b45 ro quiet splash vt.handoff=7
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] x86/fpu: Using 'eager' FPU context switches.
[ 0.000000] e820: BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000008dfff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000008e000-0x000000000008ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000090000-0x000000000009ffff] usable
[ 0.000000] BIOS-e820: [mem 0x00000000000a0000-0x00000000000bffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000001fffffff] usable
[ 0.000000] BIOS-e820: [mem 0x0000000020000000-0x00000000201fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000020200000-0x0000000040003fff] usable
[ 0.000000] BIOS-e820: [mem 0x0000000040004000-0x0000000040004fff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000040005000-0x000000008ad13fff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008ad14000-0x000000008ad52fff] ACPI NVS
[ 0.000000] BIOS-e820: [mem 0x000000008ad53000-0x000000008ad68fff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008ad69000-0x000000008ad8efff] ACPI data
[ 0.000000] BIOS-e820: [mem 0x000000008ad8f000-0x000000008ae3afff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008ae3b000-0x000000008ae8efff] reserved
[ 0.000000] BIOS-e820: [mem 0x000000008ae8f000-0x000000008aecdfff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008aece000-0x000000008aefefff] reserved
[ 0.000000] BIOS-e820: [mem 0x000000008aeff000-0x000000008af91fff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008af92000-0x000000008affefff] reserved
[ 0.000000] BIOS-e820: [mem 0x000000008afff000-0x000000008affffff] usable
[ 0.000000] BIOS-e820: [mem 0x000000008b000000-0x000000008f9fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000e00f8000-0x00000000e00f8fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000ffe70000-0x00000000ffe9ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000016f5fffff] usable
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] efi: EFI v1.10 by Apple
[ ...

[kevin gunn (kgunn72)]

huh app armor denial in dmesg?

also, the sudo chroot /var/lib/lxd/containers/xen/rootfs /bin/bash
seemed to work

[Stéphane Graber (stgraber)]

We got a similar report on IRC where "systemctl restart cgmanager" somehow helped, does that make any difference for you?

[kevin gunn (kgunn72)]

it is quite possible - so ironically i had to enable & start cgmanager for testing unity8-desktop, there's a bug where apps fail to launch on the unity8-desktop-session-mir bug 1535058

so i had restarted it already, and just tried to lxc exec and it worked fine.
i will reboot sometime later, and see if the failure occurs again.
but highly suspect this is related.

[kevin gunn (kgunn72)]

so i updated and rebooted, but my cgmanager is already running.
so i did lxc exec just fine.
would be nice to link the fix to this...but otherwise, i'd consider this bug closed

[Serge Hallyn (serge-hallyn)]

Thanks. fwiw we need at least up to commit 3939a22a481 from
git to fix this. I'll mark it fix committed as the fix is in
git and ppa, and will hit xenial with the next merge.

[Serge Hallyn (serge-hallyn)]

  Apparently the fixes we need should already be in the xenial lxc packages. Could you please try (in one root terminal)

systemctl stop cgmanager

then see whether you're still able to start apps?

(If not, then in that terminal again do 'systemctl start cgmanager')

[kevin gunn (kgunn72)]

so i did
kg@kg-MacBookPro:~$ sudo systemctl stop cgmanager
kg@kg-MacBookPro:~$ sudo systemctl status cgmanager.service
● cgmanager.service - Cgroup management daemon
   Loaded: loaded (/lib/systemd/system/cgmanager.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2016-02-16 09:40:43 CST; 3s ago
  Process: 871 ExecStart=/sbin/cgmanager -m name=systemd (code=killed, signal=TERM)
 Main PID: 871 (code=killed, signal=TERM)

Feb 16 08:07:40 kg-MacBookPro systemd[1]: Started Cgroup management daemon.
Feb 16 09:40:43 kg-MacBookPro systemd[1]: Stopping Cgroup management daemon...
Feb 16 09:40:43 kg-MacBookPro systemd[1]: Stopped Cgroup management daemon.
kg@kg-MacBookPro:~$ newgrp lxd
kg@kg-MacBookPro:~$ lxc start xen
kg@kg-MacBookPro:~$ lxc list
+------+---------+------+------+-----------+-----------+
| NAME | STATE | IPV4 | IPV6 | EPHEMERAL | SNAPSHOTS |
+------+---------+------+------+-----------+-----------+
| xen | RUNNING | | | NO | 0 |
+------+---------+------+------+-----------+-----------+
kg@kg-MacBookPro:~$ lxc exec xen -- /bin/bash
root@xen:~#
root@xen:~# exit
exit
kg@kg-MacBookPro:~$ exit
exit
Hasta la vista, baby
kg@kg-MacBookPro:~$ sudo systemctl status cgmanager.service
● cgmanager.service - Cgroup management daemon
   Loaded: loaded (/lib/systemd/system/cgmanager.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2016-02-16 09:40:57 CST; 3min 22s ago
 Main PID: 8858 (cgmanager)
    Tasks: 0 (limit: 512)
   Memory: 248.0K
      CPU: 6ms
   CGroup: /system.slice/cgmanager.service
           ‣ 8858 /sbin/cgmanager -m name=systemd

Feb 16 09:40:57 kg-MacBookPro systemd[1]: Started Cgroup management daemon.

so seems it started on it's own

[Serge Hallyn (serge-hallyn)]

Oh, yeah, systemd will start it when lxd starts. Please start lxd first
(by doing a 'lxc list'), then stop cgmanager and try again.