rag57
January 10, 2018, 9:04am
1
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.
In an similar post is a discussion about uid and gid:
When I switch back, all run fine.
What can i do?
stgraber
January 11, 2018, 3:24am
2
@brauner any ideas?
@rag57 what LXC version is that?
rag57
January 11, 2018, 9:02am
3
Paket: lxc
brauner
January 11, 2018, 3:07pm
4
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
brauner
January 11, 2018, 3:09pm
5
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
January 11, 2018, 5:17pm
6
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
January 18, 2018, 1:18pm
7
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
January 18, 2018, 2:32pm
8
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"
brauner
January 18, 2018, 3:00pm
9
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
rag57
January 19, 2018, 10:18am
10
kernel 4.14.0-0.bpo.3-amd64 works
