Distro: Arch Linux
LXC version: 3.0.1
Since 4.18-rc1 unprivileged (but started by root user) LXC containers
can't start because of the error:
lxc-start test 20180629043810.254 ERROR lxc_utils - utils.c:open_devnull:1753 - Permission denied - Can't open /dev/null
lxc-start test 20180629043810.254 ERROR lxc_sync - sync.c:__sync_wait:57 - An error occurred in another process (expected sequence number 5)
Privileged containers start normally.
Steps to reproduce:
# lxc-create -n test -t download -- --dist ubuntu --release bionic --arch amd64
# lxc-start -n test
Distro inside the container doesn't matter, ubuntu is picked as an example.
Downgrading to 4.17.3 allows to start unprivileged containers normally.
Bisect between tags 4.18-rc1 and v4.17 led me to commit 55956b59df336f6
("vfs: Allow userns root to call mknod on owned filesystems").
Reverting this commit allows to start the containers on 4.18-rc1 and
newer kernels.
Bisect log and full lxc-start debug log attached.
git bisect start
# good: [29dcea88779c856c7dc92040a0c01233263101d4] Linux 4.17
git bisect good 29dcea88779c856c7dc92040a0c01233263101d4
# bad: [ce397d215ccd07b8ae3f71db689aedb85d56ab40] Linux 4.18-rc1
git bisect bad ce397d215ccd07b8ae3f71db689aedb85d56ab40
# bad: [1c8c5a9d38f607c0b6fd12c91cbe1a4418762a21] Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net-next
git bisect bad 1c8c5a9d38f607c0b6fd12c91cbe1a4418762a21
# bad: [135c5504a600ff9b06e321694fbcac78a9530cd4] Merge tag 'drm-next-2018-06-06-1' of git://anongit.freedesktop.org/drm/drm
git bisect bad 135c5504a600ff9b06e321694fbcac78a9530cd4
# bad: [5231804cf9e584f3e7e763a0d6d2fffe011c1bce] Merge tag 'leds_for_4.18-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/j.anaszewski/linux-leds
git bisect bad 5231804cf9e584f3e7e763a0d6d2fffe011c1bce
# bad: [4057adafb395204af4ff93f3669ecb49eb45b3cf] Merge branch 'core-rcu-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 4057adafb395204af4ff93f3669ecb49eb45b3cf
# good: [eeee3149aaa022145b2659e3b0601dc705d69402] Merge tag 'docs-4.18' of git://git.lwn.net/linux
git bisect good eeee3149aaa022145b2659e3b0601dc705d69402
# good: [23d0b79dfaed2305b500b0215b0421701ada6b1a] btrfs: Add unprivileged version of ino_lookup ioctl
git bisect good 23d0b79dfaed2305b500b0215b0421701ada6b1a
# good: [325520142b47690018d09060a874327d5e7f0709] Merge tag '4.18-smb3-fixes' of git://git.samba.org/sfrench/cifs-2.6
git bisect good 325520142b47690018d09060a874327d5e7f0709
# bad: [93e95fa57441b6976b39029bd658b6bbe7ccfe28] Merge branch 'siginfo-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/ebiederm/user-namespace
git bisect bad 93e95fa57441b6976b39029bd658b6bbe7ccfe28
# good: [c046e2c693c770153acb568e56c0c41cce9c91e2] signal/nios2: Use force_sig_fault where appropriate
git bisect good c046e2c693c770153acb568e56c0c41cce9c91e2
# good: [76b7f670730e87974f71df9f6129811e2769666e] signal/signalfd: Add support for SIGSYS
git bisect good 76b7f670730e87974f71df9f6129811e2769666e
# bad: [f3f1a18330ac1b717cd7a32adff38d965f365aa2] fs: Allow CAP_SYS_ADMIN in s_user_ns to freeze and thaw filesystems
git bisect bad f3f1a18330ac1b717cd7a32adff38d965f365aa2
# bad: [55956b59df336f6738da916dbb520b6e37df9fbd] vfs: Allow userns root to call mknod on owned filesystems.
git bisect bad 55956b59df336f6738da916dbb520b6e37df9fbd
# good: [593d1ce854dff93b3c9066e897192eb676b09c46] vfs: Don't allow changing the link count of an inode with an invalid uid or gid
git bisect good 593d1ce854dff93b3c9066e897192eb676b09c46
# first bad commit: [55956b59df336f6738da916dbb520b6e37df9fbd] vfs: Allow userns root to call mknod on owned filesystems.
lxc-start test 20180629043810.466 INFO lxc_confile - confile.c:set_config_idmaps:1666 - Read uid map: type u nsid 0 hostid 100000 range 65536
lxc-start test 20180629043810.467 INFO lxc_confile - confile.c:set_config_idmaps:1666 - Read uid map: type g nsid 0 hostid 100000 range 65536
lxc-start test 20180629043810.472 INFO lxc_container - lxccontainer.c:do_lxcapi_start:948 - Attempting to set proc title to [lxc monitor] /var/lib/lxc test
lxc-start test 20180629043810.473 INFO lxc_initutils - initutils.c:setproctitle:360 - setting cmdline failed - Invalid argument
lxc-start test 20180629043810.479 INFO lxc_lsm - lsm/lsm.c:lsm_init:46 - LSM security driver nop
lxc-start test 20180629043810.480 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "reject_force_umount # comment this to allow umount -f; not recommended"
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:496 - Set seccomp rule to reject force umounts
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for reject_force_umount action 0(kill)
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:496 - Set seccomp rule to reject force umounts
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for reject_force_umount action 0(kill)
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:496 - Set seccomp rule to reject force umounts
lxc-start test 20180629043810.481 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for reject_force_umount action 0(kill)
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:do_resolve_add_rule:496 - Set seccomp rule to reject force umounts
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for reject_force_umount action 0(kill)
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "[all]"
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "kexec_load errno 1"
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for kexec_load action 327681(errno)
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for kexec_load action 327681(errno)
lxc-start test 20180629043810.482 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for kexec_load action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for kexec_load action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "open_by_handle_at errno 1"
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for open_by_handle_at action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for open_by_handle_at action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for open_by_handle_at action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for open_by_handle_at action 327681(errno)
lxc-start test 20180629043810.483 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "init_module errno 1"
lxc-start test 20180629043810.484 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for init_module action 327681(errno)
lxc-start test 20180629043810.484 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for init_module action 327681(errno)
lxc-start test 20180629043810.484 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for init_module action 327681(errno)
lxc-start test 20180629043810.484 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for init_module action 327681(errno)
lxc-start test 20180629043810.484 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "finit_module errno 1"
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for finit_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for finit_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for finit_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for finit_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:745 - Processing "delete_module errno 1"
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:922 - Added native rule for arch 0 for delete_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:931 - Added compat rule for arch 1073741827 for delete_module action 327681(errno)
lxc-start test 20180629043810.485 INFO lxc_seccomp - seccomp.c:parse_config_v2:941 - Added compat rule for arch 1073741886 for delete_module action 327681(errno)
lxc-start test 20180629043810.486 INFO lxc_seccomp - seccomp.c:parse_config_v2:951 - Added native rule for arch -1073741762 for delete_module action 327681(errno)
lxc-start test 20180629043810.486 INFO lxc_seccomp - seccomp.c:parse_config_v2:955 - Merging compat seccomp contexts into main context
lxc-start test 20180629043810.490 DEBUG terminal - terminal.c:lxc_terminal_peer_default:684 - No such device - The process does not have a controlling terminal
lxc-start test 20180629043810.494 INFO lxc_start - start.c:lxc_init:858 - Container "test" is initialized
lxc-start test 20180629043810.494 DEBUG storage - storage/storage.c:get_storage_by_name:225 - Detected rootfs type "btrfs"
lxc-start test 20180629043810.503 INFO lxc_network - network.c:instantiate_veth:175 - Retrieved mtu 1500 from br0
lxc-start test 20180629043810.506 INFO lxc_network - network.c:instantiate_veth:201 - Attached "vethBPN09W" to bridge "br0"
lxc-start test 20180629043810.507 DEBUG lxc_network - network.c:instantiate_veth:226 - Instantiated veth "vethBPN09W/vethL3XBWV", index is "12"
lxc-start test 20180629043810.511 DEBUG lxc_cgfsng - cgroups/cgfsng.c:cg_legacy_handle_cpuset_hierarchy:606 - "cgroup.clone_children" was already set to "1"
lxc-start test 20180629043810.524 INFO lxc_start - start.c:lxc_spawn:1641 - Cloned CLONE_NEWUSER
lxc-start test 20180629043810.524 INFO lxc_start - start.c:lxc_spawn:1641 - Cloned CLONE_NEWNS
lxc-start test 20180629043810.524 INFO lxc_start - start.c:lxc_spawn:1641 - Cloned CLONE_NEWPID
lxc-start test 20180629043810.524 INFO lxc_start - start.c:lxc_spawn:1641 - Cloned CLONE_NEWUTS
lxc-start test 20180629043810.525 INFO lxc_start - start.c:lxc_spawn:1641 - Cloned CLONE_NEWIPC
lxc-start test 20180629043810.525 DEBUG lxc_start - start.c:lxc_try_preserve_namespaces:204 - Preserved user namespace via fd 14
lxc-start test 20180629043810.525 DEBUG lxc_start - start.c:lxc_try_preserve_namespaces:204 - Preserved mnt namespace via fd 15
lxc-start test 20180629043810.526 DEBUG lxc_start - start.c:lxc_try_preserve_namespaces:204 - Preserved pid namespace via fd 16
lxc-start test 20180629043810.526 DEBUG lxc_start - start.c:lxc_try_preserve_namespaces:204 - Preserved uts namespace via fd 17
lxc-start test 20180629043810.526 DEBUG lxc_start - start.c:lxc_try_preserve_namespaces:204 - Preserved ipc namespace via fd 18
lxc-start test 20180629043810.527 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newuidmap" does have the setuid bit set
lxc-start test 20180629043810.528 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newgidmap" does have the setuid bit set
lxc-start test 20180629043810.528 DEBUG lxc_conf - conf.c:lxc_map_ids:2866 - Functional newuidmap and newgidmap binary found
lxc-start test 20180629043810.733 INFO lxc_start - start.c:do_start:1091 - Unshared CLONE_NEWNET
lxc-start test 20180629043810.743 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newuidmap" does have the setuid bit set
lxc-start test 20180629043810.743 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newgidmap" does have the setuid bit set
lxc-start test 20180629043810.744 DEBUG lxc_conf - conf.c:lxc_map_ids:2866 - Functional newuidmap and newgidmap binary found
lxc-start test 20180629043810.841 DEBUG lxc_start - start.c:lxc_spawn:1695 - Preserved net namespace via fd 10
lxc-start test 20180629043810.165 DEBUG lxc_network - network.c:lxc_network_move_created_netdev_priv:2495 - Moved network device "vethL3XBWV"/"eth0" to network namespace of 2934
lxc-start test 20180629043810.165 NOTICE lxc_utils - utils.c:lxc_switch_uid_gid:2059 - Switched to gid 0.
lxc-start test 20180629043810.165 NOTICE lxc_utils - utils.c:lxc_switch_uid_gid:2065 - Switched to uid 0.
lxc-start test 20180629043810.165 NOTICE lxc_utils - utils.c:lxc_setgroups:2077 - Dropped additional groups.
lxc-start test 20180629043810.166 INFO lxc_start - start.c:do_start:1198 - Unshared CLONE_NEWCGROUP
lxc-start test 20180629043810.166 DEBUG storage - storage/storage.c:get_storage_by_name:225 - Detected rootfs type "btrfs"
lxc-start test 20180629043810.166 DEBUG lxc_conf - conf.c:lxc_setup_rootfs:1369 - Mounted rootfs "/var/lib/lxc/test/rootfs" onto "/usr/lib/lxc/rootfs" with options "(null)"
lxc-start test 20180629043810.166 INFO lxc_conf - conf.c:setup_utsname:787 - Set hostname to "test"
lxc-start test 20180629043810.213 DEBUG lxc_network - network.c:lxc_setup_netdev_in_child_namespaces:3019 - Network device "eth0" has been setup
lxc-start test 20180629043810.213 INFO lxc_network - network.c:lxc_setup_network_in_child_namespaces:3040 - network has been setup
lxc-start test 20180629043810.213 INFO lxc_conf - conf.c:mount_autodev:1194 - Preparing "/dev"
lxc-start test 20180629043810.213 INFO lxc_conf - conf.c:mount_autodev:1216 - Mounted tmpfs on "/usr/lib/lxc/rootfs/dev"
lxc-start test 20180629043810.213 INFO lxc_conf - conf.c:mount_autodev:1233 - Prepared "/dev"
lxc-start test 20180629043810.214 INFO lxc_conf - conf.c:lxc_fill_autodev:1269 - Populating "/dev"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/full"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/null"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/random"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/tty"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/urandom"
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_fill_autodev:1284 - Created device node "/usr/lib/lxc/rootfs/dev/zero"
lxc-start test 20180629043810.214 INFO lxc_conf - conf.c:lxc_fill_autodev:1322 - Populated "/dev"
lxc-start test 20180629043810.214 INFO lxc_conf - conf.c:mount_entry:1952 - No such file or directory - Failed to mount "/sys/fs/fuse/connections" on "/usr/lib/lxc/rootfs/sys/fs/fuse/connections" (optional)
lxc-start test 20180629043810.214 INFO lxc_conf - conf.c:mount_file_entries:2274 - Finished setting up mounts
lxc-start test 20180629043810.214 DEBUG lxc_conf - conf.c:lxc_setup_dev_console:1703 - Mounted pts device "/dev/pts/4" onto "/usr/lib/lxc/rootfs/dev/console"
lxc-start test 20180629043810.214 INFO lxc_utils - utils.c:lxc_mount_proc_if_needed:1722 - I am 1, /proc/self points to "1"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:setup_rootfs_pivot_root:1171 - pivot_root("/usr/lib/lxc/rootfs") successful
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:setup_pivot_root:1500 - Finished pivot_root()
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_devpts:1580 - Mount new devpts instance with options "gid=5,newinstance,ptmxmode=0666,mode=0620,max=1024"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_devpts:1600 - Created dummy "/dev/ptmx" file as bind mount target
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_devpts:1605 - Bind mounted "/dev/pts/ptmx" to "/dev/ptmx"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_allocate_ttys:985 - Created tty "/dev/pts/0" with master fd 11 and slave fd 14
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_allocate_ttys:985 - Created tty "/dev/pts/1" with master fd 15 and slave fd 16
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_allocate_ttys:985 - Created tty "/dev/pts/2" with master fd 17 and slave fd 18
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_allocate_ttys:985 - Created tty "/dev/pts/3" with master fd 19 and slave fd 20
lxc-start test 20180629043810.253 INFO lxc_conf - conf.c:lxc_allocate_ttys:1003 - Finished creating 4 tty devices
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_ttys:944 - Bind mounted "/dev/pts/0" onto "/dev/tty1"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_ttys:944 - Bind mounted "/dev/pts/1" onto "/dev/tty2"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_ttys:944 - Bind mounted "/dev/pts/2" onto "/dev/tty3"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:lxc_setup_ttys:944 - Bind mounted "/dev/pts/3" onto "/dev/tty4"
lxc-start test 20180629043810.253 INFO lxc_conf - conf.c:lxc_setup_ttys:953 - Finished setting up 4 /dev/tty<N> device(s)
lxc-start test 20180629043810.253 INFO lxc_conf - conf.c:setup_personality:1644 - Set personality to "0x0"
lxc-start test 20180629043810.253 DEBUG lxc_conf - conf.c:setup_caps:2450 - Capabilities have been setup
lxc-start test 20180629043810.253 NOTICE lxc_conf - conf.c:lxc_setup:3563 - The container "test" is set up
lxc-start test 20180629043810.254 ERROR lxc_utils - utils.c:open_devnull:1753 - Permission denied - Can't open /dev/null
lxc-start test 20180629043810.254 ERROR lxc_sync - sync.c:__sync_wait:57 - An error occurred in another process (expected sequence number 5)
lxc-start test 20180629043810.254 INFO lxc_network - network.c:lxc_delete_network_priv:2579 - Interface "eth0" with index 12 already deleted or existing in different network namespace
lxc-start test 20180629043810.254 INFO lxc_network - network.c:lxc_delete_network_priv:2589 - Removed interface "eth0" with index 12
lxc-start test 20180629043810.313 INFO lxc_network - network.c:lxc_delete_network_priv:2610 - Removed interface "vethBPN09W" from "br0"
lxc-start test 20180629043810.313 DEBUG lxc_network - network.c:lxc_delete_network:3167 - Deleted network devices
lxc-start test 20180629043810.313 ERROR lxc_start - start.c:__lxc_start:1887 - Failed to spawn container "test"
lxc-start test 20180629043810.313 DEBUG lxc_container - lxccontainer.c:wait_on_daemonized_start:822 - First child 2923 exited
lxc-start test 20180629043810.313 ERROR lxc_container - lxccontainer.c:wait_on_daemonized_start:834 - Received container state "ABORTING" instead of "RUNNING"
lxc-start test 20180629043810.313 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newuidmap" does have the setuid bit set
lxc-start test 20180629043810.313 DEBUG lxc_conf - conf.c:idmaptool_on_path_and_privileged:2778 - The binary "/usr/bin/newgidmap" does have the setuid bit set
lxc-start test 20180629043810.313 DEBUG lxc_conf - conf.c:lxc_map_ids:2866 - Functional newuidmap and newgidmap binary found
_______________________________________________
Containers mailing list
Containers@xxxxxxxxxxxxxxxxxxxxxxxxxx
https://lists.linuxfoundation.org/mailman/listinfo/containers
