lsh does not call PAM, breaking unprivileged lxc containers

[god]

Seems like I've hit the bug #1413927 but as requested in comments I'm filing new one.

lxc-start -n asterisk -l debug -F --logfile /dev/stdout

      lxc-start 1434992414.067 INFO lxc_start_ui - lxc_start.c:main:264 - using rcfile /home/x/.local/share/lxc/asterisk/config
      lxc-start 1434992414.067 INFO lxc_utils - utils.c:get_rundir:483 - XDG_RUNTIME_DIR isn't set in the environment.
      lxc-start 1434992414.067 WARN lxc_confile - confile.c:config_pivotdir:1768 - lxc.pivotdir is ignored. It will soon become an error.
      lxc-start 1434992414.069 INFO lxc_confile - confile.c:config_idmap:1376 - read uid map: type u nsid 0 hostid 100000 range 65536
      lxc-start 1434992414.069 INFO lxc_confile - confile.c:config_idmap:1376 - read uid map: type g nsid 0 hostid 100000 range 65536
      lxc-start 1434992414.069 WARN lxc_log - log.c:lxc_log_init:316 - lxc_log_init called with log already initialized
      lxc-start 1434992414.075 WARN lxc_cgmanager - cgmanager.c:cgm_get:963 - do_cgm_get exited with error
      lxc-start 1434992414.076 WARN lxc_start - start.c:lxc_check_inherited:224 - inherited fd 7
      lxc-start 1434992414.076 INFO lxc_lsm - lsm/lsm.c:lsm_init:48 - LSM security driver AppArmor
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .reject_force_umount # comment this to allow umount -f; not recommended.
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for reject_force_umount action 0
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:210 - Setting seccomp rule to reject force umounts
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for reject_force_umount action 0
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:parse_config_v2:438 - Adding non-compat rule bc nr1 == nr2 (-1, -1)
      lxc-start 1434992414.076 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:210 - Setting seccomp rule to reject force umounts

      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .[all].
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .kexec_load errno 1.
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for kexec_load action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for kexec_load action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:443 - Really adding compat rule bc nr1 == nr2 (283, 246)
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .open_by_handle_at errno 1.
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for open_by_handle_at action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for open_by_handle_at action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:443 - Really adding compat rule bc nr1 == nr2 (342, 304)
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .init_module errno 1.
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for init_module action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for init_module action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:443 - Really adding compat rule bc nr1 == nr2 (128, 175)
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .finit_module errno 1.
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for finit_module action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for finit_module action 327681
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:443 - Really adding compat rule bc nr1 == nr2 (350, 313)
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:316 - processing: .delete_module errno 1.
      lxc-start 1434992414.077 INFO lxc_seccomp - seccomp.c:parse_config_v2:419 - Adding non-compat rule for delete_module action 327681
      lxc-start 1434992414.078 INFO lxc_seccomp - seccomp.c:parse_config_v2:430 - Adding compat rule for delete_module action 327681
      lxc-start 1434992414.078 INFO lxc_seccomp - seccomp.c:parse_config_v2:443 - Really adding compat rule bc nr1 == nr2 (129, 176)
      lxc-start 1434992414.078 INFO lxc_seccomp - seccomp.c:parse_config_v2:451 - Merging in the compat seccomp ctx into the main one
      lxc-start 1434992414.078 INFO lxc_utils - utils.c:get_rundir:483 - XDG_RUNTIME_DIR isn't set in the environment.
      lxc-start 1434992414.078 DEBUG lxc_start - start.c:setup_signal_fd:259 - sigchild handler set
      lxc-start 1434992414.080 DEBUG lxc_console - console.c:lxc_console_peer_default:500 - opening /dev/tty for console peer
      lxc-start 1434992414.081 INFO lxc_caps - caps.c:lxc_caps_up:101 - Last supported cap was 36
      lxc-start 1434992414.081 DEBUG lxc_console - console.c:lxc_console_peer_default:506 - using '/dev/tty' as console
      lxc-start 1434992414.081 DEBUG lxc_console - console.c:lxc_console_sigwinch_init:179 - 974 got SIGWINCH fd 10
      lxc-start 1434992414.081 DEBUG lxc_console - console.c:lxc_console_winsz:88 - set winsz dstfd:6 cols:160 rows:25
      lxc-start 1434992414.155 INFO lxc_start - start.c:lxc_init:451 - 'asterisk' is initialized
      lxc-start 1434992414.157 DEBUG lxc_start - start.c:__lxc_start:1137 - Not dropping cap_sys_boot or watching utmp
      lxc-start 1434992414.158 INFO lxc_start - start.c:resolve_clone_flags:848 - Cloning a new user namespace
      lxc-start 1434992414.158 INFO lxc_cgroup - cgroup.c:cgroup_init:65 - cgroup driver cgmanager initing for asterisk
      lxc-start 1434992414.176 ERROR lxc_cgmanager - cgmanager.c:lxc_cgmanager_enter:694 - call to cgmanager_move_pid_sync failed: invalid request
lxc-start: cgmanager.c: lxc_cgmanager_enter: 694 call to cgmanager_move_pid_sync failed: invalid request
      lxc-start 1434992414.177 INFO lxc_utils - utils.c:get_rundir:483 - XDG_RUNTIME_DIR isn't set in the environment.
      lxc-start 1434992414.197 ERROR lxc_start - start.c:__lxc_start:1164 - failed to spawn 'asterisk'
lxc-start: start.c: __lxc_start: 1164 failed to spawn 'asterisk'
      lxc-start 1434992414.197 INFO lxc_utils - utils.c:get_rundir:483 - XDG_RUNTIME_DIR isn't set in the environment.
      lxc-start 1434992414.197 INFO lxc_utils - utils.c:get_rundir:483 - XDG_RUNTIME_DIR isn't set in the environment.
      lxc-start 1434992414.199 ERROR lxc_start_ui - lxc_start.c:main:344 - The container failed to start.
lxc-start: lxc_start.c: main: 344 The container failed to start.
      lxc-start 1434992414.200 ERROR lxc_start_ui - lxc_start.c:main:348 - Additional information can be obtained by setting the --logfile and --logpriority options.
lxc-start: lxc_start.c: main: 348 Additional information can be obtained by setting the --logfile and --logpriority options.

I have also added bridge configured with systemdnetworkd into /etc/lxc/lxc-usernet:
x veth ibr1 4

and corresponding file /etc/systemd/network/internalbridge1.netdev
[NetDev]
Name=ibr1
Kind=bridge

The container config:
# Distribution configuration
lxc.include = /usr/share/lxc/config/ubuntu.common.conf
lxc.include = /usr/share/lxc/config/ubuntu.userns.conf
lxc.arch = x86_64

# Container specific configuration
lxc.include = /etc/lxc/default.conf
lxc.id_map = u 0 100000 65536
lxc.id_map = g 0 100000 65536
lxc.rootfs = /home/x/.local/share/lxc/asterisk/rootfs
lxc.utsname = asterisk

# Network configuration
lxc.network.type = veth
lxc.network.link = ibr1
lxc.network.flags = up
lxc.network.name = internal
lxc.network.ipv4 = 10.1.1.2/24
lxc.network.ipv4.gateway = 10.1.1.1

[god (humper)]

That happens on x86_64 ubuntu 15.04 server btw. All the latest updates installed.

[god (humper)]

Btw, cgmanager is started and keep reporting junk which I fail to interpret:

systemctl status cgmanager
● cgmanager.service - Cgroup management daemon
   Loaded: loaded (/lib/systemd/system/cgmanager.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2015-06-22 16:57:30 CEST; 2h 25min ago
 Main PID: 589 (cgmanager)
   Memory: 724.0K
   CGroup: /system.slice/cgmanager.service
           ‣ 589 /sbin/cgmanager -m name=systemd

Jun 22 19:22:39 xnode cgmanager[589]: cgmanager: Invalid path /run/cgmanager/fs/hugetlb/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager:per_ctrl_move_pid_main: Invalid path /run/cgmanager/fs/hugetlb/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager: Invalid path /run/cgmanager/fs/memory/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager:per_ctrl_move_pid_main: Invalid path /run/cgmanager/fs/memory/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager: Invalid path /run/cgmanager/fs/net_cls/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager:per_ctrl_move_pid_main: Invalid path /run/cgmanager/fs/net_cls/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager: Invalid path /run/cgmanager/fs/perf_event/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager:per_ctrl_move_pid_main: Invalid path /run/cgmanager/fs/perf_event/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager: Invalid path /run/cgmanager/fs/none,name=systemd/system.slice/lsh-server.service/lxc/asterisk
Jun 22 19:22:39 xnode cgmanager[589]: cgmanager:per_ctrl_move_pid_main: Invalid path /run/cgmanager/fs/none,name=systemd/system.slice/lsh-server.se...c/asterisk
Hint: Some lines were ellipsized, use -l to show in full.

[Serge Hallyn (serge-hallyn)]

The cgmanager log shows:

Invalid path /run/cgmanager/fs/none,name=systemd/system.slice/lsh-server.service/lxc/asterisk

How are you logged in when you try to start the container?

To start an unprivileged container, you must be logged into a regular user session, so /proc/self/cgroup should look something like:

10:memory:/user.slice/user-1000.slice/session-c2.scope
9:perf_event:/user.slice/user-1000.slice/session-c2.scope
8:cpu,cpuacct:/user.slice/user-1000.slice/session-c2.scope
7:cpuset:/user.slice/user-1000.slice/session-c2.scope
6:net_cls,net_prio:/user.slice/user-1000.slice/session-c2.scope
5:blkio:/user.slice/user-1000.slice/session-c2.scope
4:hugetlb:/user.slice/user-1000.slice/session-c2.scope
3:devices:/user.slice/user-1000.slice/session-c2.scope
2:freezer:/user.slice/user-1000.slice/session-c2.scope
1:name=systemd:/user.slice/user-1000.slice/session-c2.scope

Instead you seem to be in /system.slice/lsh-server.service, which
you do not own. So as an unprivileged user you cannot create
new cgroups for yourself, which is why lxc is failing.

[god (humper)]

What is "regular user session"? Does ssh connection counts or it have to be local console login?

[Serge Hallyn (serge-hallyn)]

ssh connections should count for a regular user session.

[Launchpad Janitor (janitor)]

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

[Martin Pitt (pitti)]

So that seems to be an artifact of using lsh-server? After ssh'ing in, please copy&paste the output of "cat /proc/self/cgroups"

[god (humper)]

cat /proc/self/cgroups
cat: /proc/self/cgroups: No such file or directory

Hmm.. what ssh server have to do with this?

[Martin Pitt (pitti)]

I meant /proc/self/cgroup, sorry.

> what ssh server have to do with this?

Because your process is in /system.slice/lsh-server.service, which your user cannot access.

[god (humper)]

 cat /proc/self/cgroup
10:cpuset:/system.slice/lsh-server.service
9:memory:/system.slice/lsh-server.service
8:freezer:/system.slice/lsh-server.service
7:blkio:/system.slice/lsh-server.service
6:hugetlb:/system.slice/lsh-server.service
5:perf_event:/system.slice/lsh-server.service
4:cpu,cpuacct:/system.slice/lsh-server.service
3:net_cls,net_prio:/system.slice/lsh-server.service
2:devices:/system.slice/lsh-server.service
1:name=systemd:/system.slice/lsh-server.service

[god (humper)]

I still don't get the point about lsh - I mean what's the difference with openssh? Are there some specific step by ssh server with regards to user session setup necessary? Or some specific system-wide configuration required somewhere?

[Serge Hallyn (serge-hallyn)]

is lsh somehow not triggering pam_systemd?

[god (humper)]

How does this triggering happens normally? I mean should ssh server call something specific explicitly?

[Martin Pitt (pitti)]

@god, which Ubuntu release is this? I just noticed that our patch to support user LXC regressed in 221 in wily (Ubuntu 15.10), I'll look at this. If you use 15.04 (vivid) that's a separate problem.

But indeed it seems that lsh somehow reconfigures the cgroups, and/or does not invoke PAM.

[Martin Pitt (pitti)]

For the record, I filed bug 1470060 for the wily issue (which affects local and remote sessions all alike).

[god (humper)]

cat /etc/os-release
NAME="Ubuntu"
VERSION="15.04 (Vivid Vervet)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 15.04"
VERSION_ID="15.04"
HOME_URL="http://www.ubuntu.com/"
SUPPORT_URL="http://help.ubuntu.com/"
BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/"

That's another one I think. Let me know if I can help with troubleshooting somehow.

[Martin Pitt (pitti)]

Confirmed. Installing lsh-server in vivid and logging in via ssh reproduces this easily. There is no $XDG_SESSION_ID and login session for lsh, so pam_systemd doesn't run. lsh-server does not ship any PAM config at all.

[god (humper)]

I've checked 'locally' (via spice console) - $XDG_SESSION_ID is present there but container still fails to start:
Quota reached
lxc-start: start.c lxc_spawn: 1000 failed to create configured network

Shall I file another bug for this?

[Martin Pitt (pitti)]

Yes, that "failed to create configured network" is unrelated and deserves a separate report. Please include the entire debug output of LXC there. Thanks!