Switch from kernel 4.9.0-4-amd64 to 4.14.0-0.bpo.2-amd64

[rag57]

System is debian stretch.

I have got this message after switching kernel from 4.9.0-4-amd64 to 4.14.0-0.bpo.2-amd64:

lxc-start: cgroups/cgfsng.c: create_path_for_hierarchy: 1306 Path “/sys/fs/cgroup/systemd//lxc/lxc_admin” already existed.
lxc-start: cgroups/cgfsng.c: cgfsng_create: 1363 No such file or directory - Failed to create /sys/fs/cgroup/systemd//lxc/lxc_admin: No such file or directory

In an similar post is a discussion about uid and gid:

Issue: CGROUP does not get deleted on failure.

When I switch back, all run fine.

What can i do?

[stgraber]

@brauner any ideas?

@rag57 what LXC version is that?

[rag57]

Paket: lxc
Version: 1:2.0.7-2+deb9u1

[brauner]

The cgroup errors are very likely a red herring. I rather suspect that this is the upstream AppArmor bug that got introduced in the 4.14 kernel. Basically the mount mediation checks are wrong in 4.14. But there’s a commit fixing this upstream https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=5b9f57cf47b87f07210875d6a24776b4496b818d
but it’ll only be released in 4.15. Debian might decide to backport it to 4.14 though not sure. It should qualify as a bugfix.

[brauner]

In any case, I’d need to see the full trace log for the container. With lxd this should be doable when starting the daemon with lxd --debug --group lxd and then giving me the logs under /var/log/lxd/<container-name>/lxc.log. For liblxc it would be lxc-start -n <container-name> -l trace -o <container-name>.log and appending/copying <container-name>.log here.

[rag57]

lxc-start -n <container-name> -l trace -o <container-name>.log

  lxc-start 20170111164450.450 INFO     lxc_start_ui - tools/lxc_start.c:main:275 - using rcfile /var/lib/lxc/lxc_admin/config                                                                                                                         
  lxc-start 20170111164450.450 WARN     lxc_confile - confile.c:config_pivotdir:1910 - lxc.pivotdir is ignored.  It will soon become an error.                                                                                                         
  lxc-start 20170111164450.450 INFO     lxc_confile - confile.c:config_idmap:1531 - read uid map: type u nsid 0 hostid 1000000 range 65536                                                                                                             
  lxc-start 20170111164450.450 INFO     lxc_confile - confile.c:config_idmap:1531 - read uid map: type g nsid 0 hostid 1000000 range 65536                                                                                                             
  lxc-start 20170111164450.451 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:309 - Going to wait for pid 1077.                                                                                                                                   
  lxc-start 20170111164450.452 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:328 - Trying to sync with child process.                                                                                                                            
  lxc-start 20170111164450.452 INFO     lxc_start - start.c:lxc_check_inherited:235 - Closed inherited fd: 4.                                                                                                                                          
  lxc-start 20170111164450.452 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:366 - Using pipe file descriptor 5 for monitord.                                                                                                                    
  lxc-start 20170111164450.499 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:343 - Sucessfully synced with child process.                                                                                                                        
  lxc-start 20170111164450.501 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:312 - Finished waiting on pid 1077.
  lxc-start 20170111164450.501 INFO     lxc_container - lxccontainer.c:do_lxcapi_start:804 - Attempting to set proc title to [lxc monitor] /var/lib/lxc lxc_admin
  lxc-start 20170111164450.502 INFO     lxc_lsm - lsm/lsm.c:lsm_init:48 - LSM security driver AppArmor
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .reject_force_umount  # comment this to allow umount -f;  not recommended.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for reject_force_umount action 0.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:do_resolve_add_rule:251 - Setting Seccomp rule to reject force umounts.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for reject_force_umount action 0.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:do_resolve_add_rule:251 - Setting Seccomp rule to reject force umounts.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .[all].
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .kexec_load errno 1.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for kexec_load action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for kexec_load action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .open_by_handle_at errno 1.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for open_by_handle_at action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for open_by_handle_at action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .init_module errno 1.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for init_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for init_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .finit_module errno 1.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for finit_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for finit_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:402 - processing: .delete_module errno 1.
  lxc-start 20170111164450.503 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:309 - Going to wait for pid 1081.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:567 - Adding native rule for delete_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:570 - Adding compat rule for delete_module action 327681.
  lxc-start 20170111164450.503 INFO     lxc_seccomp - seccomp.c:parse_config_v2:580 - Merging in the compat Seccomp ctx into the main one.
  lxc-start 20170111164450.503 DEBUG    lxc_start - start.c:setup_signal_fd:273 - Set SIGCHLD handler with file descriptor: 5.
  lxc-start 20170111164450.504 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:328 - Trying to sync with child process.
  lxc-start 20170111164450.504 INFO     lxc_start - start.c:lxc_check_inherited:235 - Closed inherited fd: 4.
  lxc-start 20170111164450.504 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:366 - Using pipe file descriptor 5 for monitord.
  lxc-start 20170111164450.505 DEBUG    console - console.c:lxc_console_peer_default:468 - no console peer
  lxc-start 20170111164450.505 INFO     lxc_start - start.c:lxc_init:475 - Container "lxc_admin" is initialized.
  lxc-start 20170111164450.506 DEBUG    lxc_start - start.c:__lxc_start:1317 - Not dropping CAP_SYS_BOOT or watching utmp.
  lxc-start 20170111164450.513 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:343 - Sucessfully synced with child process.
  lxc-start 20170111164450.513 DEBUG    lxc_monitor - monitor.c:lxc_monitord_spawn:312 - Finished waiting on pid 1081.
  lxc-start 20170111164450.514 INFO     lxc_monitor - monitor.c:lxc_monitor_sock_name:185 - Using monitor socket name "lxc/ad055575fe28ddd5//var/lib/lxc".
  lxc-start 20170111164450.523 INFO     lxc_conf - conf.c:instantiate_veth:2647 - Retrieved mtu 1500 from intern
  lxc-start 20170111164450.523 INFO     lxc_conf - conf.c:instantiate_veth:2672 - Attached 'vethJ0V4K8': to the bridge 'intern': 
  lxc-start 20170111164450.523 DEBUG    lxc_conf - conf.c:instantiate_veth:2689 - instantiated veth 'vethJ0V4K8/vethR9R9MP', index is '6'
  lxc-start 20170111164450.523 INFO     lxc_cgroup - cgroups/cgroup.c:cgroup_init:68 - cgroup driver cgroupfs-ng initing for lxc_admin
  lxc-start 20170111164450.525 DEBUG    lxc_cgfsng - cgroups/cgfsng.c:filter_and_set_cpus:474 - No isolated cpus detected.
  lxc-start 20170111164450.525 DEBUG    lxc_cgfsng - cgroups/cgfsng.c:handle_cpuset_hierarchy:644 - "cgroup.clone_children" was already set to "1".
  lxc-start 20170111164450.526 INFO     lxc_start - start.c:lxc_spawn:1154 - Cloned CLONE_NEWUSER.
  lxc-start 20170111164450.526 INFO     lxc_start - start.c:lxc_spawn:1154 - Cloned CLONE_NEWNS.
  lxc-start 20170111164450.526 INFO     lxc_start - start.c:lxc_spawn:1154 - Cloned CLONE_NEWPID.
  lxc-start 20170111164450.526 INFO     lxc_start - start.c:lxc_spawn:1154 - Cloned CLONE_NEWUTS.
  lxc-start 20170111164450.526 INFO     lxc_start - start.c:lxc_spawn:1154 - Cloned CLONE_NEWIPC.
  lxc-start 20170111164450.699 INFO     lxc_start - start.c:do_start:745 - Unshared CLONE_NEWNET.
  lxc-start 20170111164450.699 DEBUG    lxc_cgfsng - cgroups/cgfsng.c:cgfsng_setup_limits:1954 - cgroup 'memory.limit_in_bytes' set to '256M'
  lxc-start 20170111164450.700 DEBUG    lxc_cgfsng - cgroups/cgfsng.c:cgfsng_setup_limits:1954 - cgroup 'memory.memsw.limit_in_bytes' set to '500M'
  lxc-start 20170111164450.700 INFO     lxc_cgfsng - cgroups/cgfsng.c:cgfsng_setup_limits:1958 - cgroup has been setup
  lxc-start 20170111164450.727 DEBUG    lxc_conf - conf.c:lxc_assign_network:3185 - move 'vethR9R9MP'/'(null)' to '1090': .
  lxc-start 20170111164450.727 NOTICE   lxc_utils - utils.c:lxc_switch_uid_gid:2064 - Switched to gid 0.
  lxc-start 20170111164450.727 NOTICE   lxc_utils - utils.c:lxc_switch_uid_gid:2070 - Switched to uid 0.
  lxc-start 20170111164450.727 NOTICE   lxc_utils - utils.c:lxc_setgroups:2082 - Dropped additional groups.
  lxc-start 20170111164450.728 ERROR    lxc_conf - conf.c:setup_rootfs:1279 - failed to mount rootfs
  lxc-start 20170111164450.728 ERROR    lxc_conf - conf.c:do_rootfs_setup:3750 - failed to setup rootfs for 'lxc_admin'
  lxc-start 20170111164450.728 ERROR    lxc_conf - conf.c:lxc_setup:3832 - Error setting up rootfs mount after spawn
  lxc-start 20170111164450.728 ERROR    lxc_start - start.c:do_start:811 - Failed to setup container "lxc_admin".
  lxc-start 20170111164450.728 ERROR    lxc_sync - sync.c:__sync_wait:57 - An error occurred in another process (expected sequence number 3)
  lxc-start 20170111164450.728 INFO     lxc_conf - conf.c:lxc_delete_network:3005 - Interface "(null)" with index 6 already deleted or existing in different network namespace.
  lxc-start 20170111164450.767 INFO     lxc_conf - conf.c:lxc_delete_network:3040 - Removed interface "vethJ0V4K8" from host.
  lxc-start 20170111164450.767 ERROR    lxc_start - start.c:__lxc_start:1346 - Failed to spawn container "lxc_admin".
  lxc-start 20170111164450.803 INFO     lxc_conf - conf.c:run_script_argv:424 - Executing script "/usr/share/lxcfs/lxc.reboot.hook" for container "lxc_admin", config section "lxc".
  lxc-start 20170111164451.321 WARN     lxc_commands - commands.c:lxc_cmd_rsp_recv:172 - Command get_cgroup failed to receive response: Connection reset by peer.
  lxc-start 20170111164456.326 ERROR    lxc_start_ui - tools/lxc_start.c:main:366 - The container failed to start.
  lxc-start 20170111164456.327 ERROR    lxc_start_ui - tools/lxc_start.c:main:368 - To get more details, run the container in foreground mode.
  lxc-start 20170111164456.327 ERROR    lxc_start_ui - tools/lxc_start.c:main:370 - Additional information can be obtained by setting the --logfile and --logpriority options.

[brauner]

It seems you can’t mount the rootfs which makes AppArmor more likely. Anything suspicious in the dmesg output when starting one of those containers?

[rag57]

Jan 7 20:39:32 rz4 kernel: [ 842.833805] audit: type=1400 audit(1515353972.827:85): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile="/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3410 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:39:32 rz4 kernel: [ 842.833842] audit: type=1400 audit(1515353972.827:86): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3410 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:50:35 rz4 kernel: [ 1505.244155] audit: type=1400 audit(1515354635.208:87): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3740 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:50:35 rz4 kernel: [ 1505.244193] audit: type=1400 audit(1515354635.208:88): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3740 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:51:07 rz4 kernel: [ 1537.193491] audit: type=1400 audit(1515354667.159:89): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3853 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:51:07 rz4 kernel: [ 1537.193530] audit: type=1400 audit(1515354667.159:90): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3853 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:51:16 rz4 kernel: [ 1546.085871] audit: type=1400 audit(1515354676.050:91): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3960 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 7 20:51:16 rz4 kernel: [ 1546.085913] audit: type=1400 audit(1515354676.050:92): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=3960 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 11 17:44:50 rz4 kernel: [ 191.687844] audit: type=1400 audit(1515689090.724:17): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=1090 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind"
Jan 11 17:44:50 rz4 kernel: [ 191.687871] audit: type=1400 audit(1515689090.724:18): apparmor=“DENIED” operation=“mount” info=“failed mntpnt match” error=-13 profile=”/usr/bin/lxc-start" name="/usr/lib/x86_64-linux-gnu/lxc/rootfs/" pid=1090 comm=“lxc-start” srcname="/vm/lxc_admin/rootfs/" flags=“rw, rbind”

[brauner]

Right, this is as I expected. This is the AppArmor bug in 4.14. which is fixed by https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=5b9f57cf47b87f07210875d6a24776b4496b818d
which will be in 4.15. So this is not liblxc’s fault.

[rag57]

kernel 4.14.0-0.bpo.3-amd64 works