Skip to content
This repository has been archived by the owner on Feb 24, 2020. It is now read-only.

Flake: TestAppUserGroup #3477

Open
s-urbaniak opened this issue Dec 14, 2016 · 17 comments
Open

Flake: TestAppUserGroup #3477

s-urbaniak opened this issue Dec 14, 2016 · 17 comments

Comments

@s-urbaniak
Copy link
Contributor

s-urbaniak commented Dec 14, 2016

This flake has the following output and has been seen two times already:

#3453
#3462

13:17:20 --- FAIL: TestAppUserGroup (62.72s)
13:17:20 	rkt_tests.go:355: didn't receive expected output "User: uid=1000 euid=1000 gid=300 egid=300": image: using image from file /home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/stage1-coreos.aci
13:17:20 		image: using image from file /home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/test-tmp/rkt-inspect-user-group.aci
13:17:20 		image: using image from file /home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/test-tmp/rkt-inspect-dummy.aci
13:17:20 		stage0: Preparing stage1
13:17:20 		stage0: Writing image manifest
13:17:20 		stage0: Loading image sha512-5140aa50fac1e7fdbca9025fac0369a9ff08cc3b4808edaed14d8068f6caaf05
13:17:20 		stage0: Writing image manifest
13:17:20 		stage0: Loading image sha512-5675f64aa733bd5e491aab90c92a9ebec5c57d59ccd62b0dc72378a4677812a5
13:17:20 		stage0: Writing image manifest
13:17:20 		stage0: Writing pod manifest
13:17:20 		stage0: Setting up stage1
13:17:20 		stage0: Wrote filesystem to /tmp/datadir-399831401/pods/run/b3dd12f1-e3ad-480c-a4e1-b2316b227b0f
13:17:20 		stage0: Pivoting to filesystem /tmp/datadir-399831401/pods/run/b3dd12f1-e3ad-480c-a4e1-b2316b227b0f
13:17:20 		stage0: Execing [/tmp/datadir-399831401/pods/run/b3dd12f1-e3ad-480c-a4e1-b2316b227b0f/stage1/rootfs/init --debug --net=default --local-config=/tmp/localdir-258835380 b3dd12f1-e3ad-480c-a4e1-b2316b227b0f]
13:17:20 		networking: loading networks from /tmp/localdir-258835380/net.d
13:17:20 		networking: loading network default with type ptp
13:17:20 		stage1: canMachinedRegister true
13:17:20 		stage1: args ["stage1/rootfs/usr/lib/ld-linux-x86-64.so.2" "stage1/rootfs/usr/bin/systemd-nspawn" "--boot" "--notify-ready=yes" "-Zsystem_u:system_r:svirt_lxc_net_t:s0:c522,c1003" "-Lsystem_u:object_r:svirt_sandbox_file_t:s0:c522,c1003" "--register=true" "--link-journal=try-guest" "--uuid=b3dd12f1-e3ad-480c-a4e1-b2316b227b0f" "--machine=rkt-b3dd12f1-e3ad-480c-a4e1-b2316b227b0f" "--directory=stage1/rootfs" "--capability=CAP_AUDIT_WRITE,CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FSETID,CAP_FOWNER,CAP_KILL,CAP_MKNOD,CAP_NET_RAW,CAP_NET_BIND_SERVICE,CAP_SETUID,CAP_SETGID,CAP_SETPCAP,CAP_SETFCAP,CAP_SYS_CHROOT" "--capability=CAP_AUDIT_WRITE,CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FSETID,CAP_FOWNER,CAP_KILL,CAP_MKNOD,CAP_NET_RAW,CAP_NET_BIND_SERVICE,CAP_SETUID,CAP_SETGID,CAP_SETPCAP,CAP_SETFCAP,CAP_SYS_CHROOT" "--" "--default-standard-output=tty"]
13:17:20 		stage1: env ["MAIL=/var/mail/fedora" "LANG=en_US.UTF-8" "PATH=/sbin:/bin:/usr/sbin:/usr/bin" "LOGNAME=root" "USER=root" "USERNAME=root" "HOME=/root" "SHELL=/bin/bash" "TERM=unknown" "SUDO_COMMAND=/usr/bin/go test -tags coreos -timeout 60m -v github.com/coreos/rkt/tests" "SUDO_USER=fedora" "SUDO_UID=1000" "SUDO_GID=1000" "RKT_STAGE1_DEFAULT_FLAVOR=coreos" "RKT=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt" "ACTOOL=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tools/actool" "RKT_INSPECT_IMAGE=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt-inspect.aci" "RKT_EMPTY_IMAGE=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt-empty.aci" "RKT_ACE_MAIN_IMAGE=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt-ace-validator-main.aci" "RKT_ACE_SIDEKICK_IMAGE=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt-ace-validator-sidekick.aci" "RKT_CNI_PROXY=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/cniproxy" "FUNCTIONAL_TMP=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/test-tmp" "INSPECT_BINARY=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/inspect" "STUB_STAGE1=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/tmp/functional/rkt-stub-stage1.aci" "GO15VENDOREXPERIMENT=1" "GOARCH=amd64" "CGO_ENABLED=1" "CC=gcc" "CXX=g++" "GOPATH=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/gopath" "PWD=/home/fedora/workspace/rkt-github-ci/os_type/fedora-rawhide/stage1_flavor/coreos/builds/build-rkt-coreos/build-rkt-1.21.0+git/gopath/src/github.com/coreos/rkt/tests" "RKT_LOCK_FD=4" "RKT_SELINUX_CONTEXT=system_u:system_r:svirt_lxc_net_t:s0:c522,c1003" "RKT_SELINUX_MOUNT_CONTEXT=system_u:object_r:svirt_sandbox_file_t:s0:c522,c1003" "LD_LIBRARY_PATH=stage1/rootfs/usr/lib:stage1/rootfs/usr/lib/systemd" "SYSTEMD_NSPAWN_CONTAINER_SERVICE=rkt" "SYSTEMD_NSPAWN_USE_CGNS=no"]
13:17:20 		stage1: mounting source "" target "/" fstype "none" flags MS_REC|MS_SLAVE data ""
13:17:20 		stage1: mounting source "" target "/" fstype "none" flags MS_REC|MS_SHARED data ""
13:17:20 		stage1: unifiedCgroup false
13:17:20 		stage1: subcgroup "machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope"
13:17:20 		stage1: enabledCgroups map['\v':["memory"] '\x03':["perf_event"] '\b':["pids"] '\x02':["blkio"] '\n':["cpu" "cpuacct"] '\a':["devices"] '\x04':["freezer"] '\x05':["net_cls" "net_prio"] '\x06':["hugetlb"] '\t':["cpuset"]]
13:17:20 		stage1: serviceNames ["rkt-inspect.service" "dummy.service"]
13:17:20 		stage1: mounting source "sysfs" target "stage1/rootfs/sys" fstype "sysfs" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data ""
13:17:20 		stage1: mounting source "tmpfs" target "stage1/rootfs/sys/fs/cgroup" fstype "tmpfs" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_STRICTATIME data "mode=755,context=\"system_u:object_r:svirt_sandbox_file_t:s0:c522,c1003\""
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "cpu,cpuacct"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/devices" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "devices"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/freezer" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "freezer"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/net_cls,net_prio" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "net_cls,net_prio"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/hugetlb" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "hugetlb"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/cpuset" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "cpuset"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/memory" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "memory"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/perf_event" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "perf_event"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/pids" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "pids"
13:17:20 		stage1: mounting source "cgroup" target "stage1/rootfs/sys/fs/cgroup/blkio" fstype "cgroup" flags MS_NODEV|MS_NOEXEC|MS_NOSUID data "blkio"
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup" target "stage1/rootfs/sys/fs/cgroup" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_STRICTATIME|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpuset" target "stage1/rootfs/sys/fs/cgroup/cpuset" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cpu.cfs_quota_us" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cpu.cfs_quota_us" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cpu.shares" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cpu.shares" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cpu.cfs_quota_us" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cpu.cfs_quota_us" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cpu.shares" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cpu.shares" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct" target "stage1/rootfs/sys/fs/cgroup/cpu,cpuacct" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/devices.allow" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/devices.allow" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/devices.deny" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/devices.deny" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/devices.allow" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/devices.allow" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/devices.deny" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/devices.deny" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/devices/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/devices" target "stage1/rootfs/sys/fs/cgroup/devices" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/freezer" target "stage1/rootfs/sys/fs/cgroup/freezer" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/net_cls,net_prio" target "stage1/rootfs/sys/fs/cgroup/net_cls,net_prio" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/hugetlb" target "stage1/rootfs/sys/fs/cgroup/hugetlb" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/blkio" target "stage1/rootfs/sys/fs/cgroup/blkio" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/memory.limit_in_bytes" target "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/memory.limit_in_bytes" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/rkt-inspect.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/memory.limit_in_bytes" target "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/memory.limit_in_bytes" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" target "stage1/rootfs/sys/fs/cgroup/memory/machine.slice/machine-rkt\\x2db3dd12f1\\x2de3ad\\x2d480c\\x2da4e1\\x2db2316b227b0f.scope/system.slice/dummy.service/cgroup.procs" fstype "" flags MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/memory" target "stage1/rootfs/sys/fs/cgroup/memory" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/perf_event" target "stage1/rootfs/sys/fs/cgroup/perf_event" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys/fs/cgroup/pids" target "stage1/rootfs/sys/fs/cgroup/pids" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		stage1: mounting source "stage1/rootfs/sys" target "stage1/rootfs/sys" fstype "" flags MS_NODEV|MS_NOEXEC|MS_NOSUID|MS_RDONLY|MS_REMOUNT|MS_BIND data ""
13:17:20 		Spawning container rkt-b3dd12f1-e3ad-480c-a4e1-b2316b227b0f on /tmp/datadir-399831401/pods/run/b3dd12f1-e3ad-480c-a4e1-b2316b227b0f/stage1/rootfs.
13:17:20 		Press ^] three times within 1s to kill container.
13:17:20 		systemd 231 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN)
13:17:20 		Detected virtualization rkt.
13:17:20 		Detected architecture x86-64.
13:17:20 		
13:17:20 		Welcome to �[1mLinux�[0m!
13:17:20 		
13:17:20 		Set hostname to <rkt-b3dd12f1-e3ad-480c-a4e1-b2316b227b0f>.
13:17:20 		[�[0;32m  OK  �[0m] Created slice system.slice.
13:17:20 		[�[0;32m  OK  �[0m] Created slice system-prepare\x2dapp.slice.
13:17:20 		         Starting Create /etc/passwd and /etc/group...
13:17:20 		[�[0;32m  OK  �[0m] Started Pod shutdown.
13:17:20 		[�[0;32m  OK  �[0m] Started rkt-inspect Reaper.
13:17:20 		[�[0;32m  OK  �[0m] Started dummy Reaper.
13:17:20 		[�[0;32m  OK  �[0m] Listening on Journal Socket.
13:17:20 		[�[0;32m  OK  �[0m] Listening on Journal Socket (/dev/log).
13:17:20 		         Starting Journal Service...
13:17:20 		[�[0;32m  OK  �[0m] Started Create /etc/passwd and /etc/group.
13:17:20 		[�[0;32m  OK  �[0m] Started Journal Service.
13:17:20 		         Starting Prepare minimum environment for chrooted applications...
13:17:20 		         Starting Prepare minimum environment for chrooted applications...
13:17:20 		[�[0;32m  OK  �[0m] Started Prepare minimum environment for chrooted applications.
13:17:20 		[�[0;32m  OK  �[0m] Started Prepare minimum environment for chrooted applications.
13:17:20 		[�[0;32m  OK  �[0m] Started Application=rkt-inspect Image=coreos.com/rkt-inspect.
13:17:20 		[�[0;32m  OK  �[0m] Started Application=dummy Image=dummy.
13:17:20 		[�[0;32m  OK  �[0m] Reached target rkt apps target.
13:17:20 		         Starting rkt supervisor-ready signaling...
13:17:20 		[�[0;32m  OK  �[0m] Started rkt supervisor-ready signaling.
13:17:20 		Sending SIGTERM to remaining processes...
13:17:20 		Sending SIGKILL to remaining processes...
13:17:20 		Container rkt-b3dd12f1-e3ad-480c-a4e1-b2316b227b0f failed with error code 226.
13:17:20 	rkt_tests.go:141: rkt terminated with unexpected status 226, expected 0
13:17:20 		Output:
13:17:20 		[]
@s-urbaniak s-urbaniak changed the title Flage: Flake: TestAppUserGroup Dec 14, 2016
@lucab
Copy link
Member

lucab commented Jan 5, 2017

The failure:

rkt terminated with unexpected status 226, expected 0

is due to systemd failing with EXIT_NAMESPACE when bringing up stage2. I've seen this happening in a bunch of other testcases recently, in a non-deterministic way.

@squeed
Copy link
Contributor

squeed commented Jan 5, 2017

This may be fixed by bumping systemd to 232.

@lucab
Copy link
Member

lucab commented Jan 5, 2017

I did some cross-checking between test history, git log and dates and I have some doubts related to #3432. In particular, I fear that as a side-effect of 3c93df9#diff-99ef63dd92c607458ff979e0c391eb56L287 we are now mutating some of the fields related to users/groups/private-users that are now shared by pointer. That may explain the flake, as multiple applications with different settings could be racing against each other. @squeed @s-urbaniak can you please have a cross-check of the logic around there?

@s-urbaniak
Copy link
Contributor Author

as far as I see UidRange is not modified in the above code path.

@squeed
Copy link
Contributor

squeed commented Jan 6, 2017

As I was spamming this, I was able to get this error to happen in rkt v1.20 - before 3432 was merged. So it's not that :-(.

@lucab
Copy link
Member

lucab commented Jan 6, 2017

Also, the same error showed up at some point in TestExitCodeWithSeveralApps, which isn't concerned by private-users.

@s-urbaniak
Copy link
Contributor Author

This flake is hard to reproduce and happens ~once a day on my machine. What we know so far:

  • The pod has been started successfully, that is systemd-nspawn, systemd are up.
  • The failure happens when the corresponding container service units start (in this test case dummy.service and rkt-inspect.service) and it fails for only one arbitrary service.
  • To start the service unit systemd forks and tries to exec_child which fails and produces the above error and the following journal entry:
{
  "__CURSOR": "s=450a9881e06145f399e72b625346621b;i=11b5;b=3a88272951684706b74fb65b0f0a69a1;m=cc4eacf22;t=5458fd9e5b7c1;x=db211d51f0c1f525",
  "__REALTIME_TIMESTAMP": "1483859021903809",
  "__MONOTONIC_TIMESTAMP": "54843330338",
  "_BOOT_ID": "3a88272951684706b74fb65b0f0a69a1",
  "SYSLOG_FACILITY": "3",
  "_UID": "0",
  "_MACHINE_ID": "0faed2d5be0e4b138348c7e073cf7824",
  "_HOSTNAME": "rkt-0faed2d5-be0e-4b13-8348-c7e073cf7824",
  "SYSLOG_IDENTIFIER": "systemd",
  "_TRANSPORT": "journal",
  "_CAP_EFFECTIVE": "fdecafff",
  "_SYSTEMD_SLICE": "-.slice",
  "UNIT": "rkt-inspect.service",
  "PRIORITY": "3",
  "MESSAGE_ID": "641257651c1b4ec9a8624d7a40a9e1e7",
  "_PID": "13",
  "_GID": "300",
  "_COMM": "(inspect)",
  "_SYSTEMD_CGROUP": "/",
  "ERRNO": "22",
  "CODE_FILE": "/home/sur/src/rkt/src/github.com/coreos/rkt/build-rkt/tmp/usr_from_src/systemd/src/src/core/execute.c",
  "CODE_LINE": "2267",
  "CODE_FUNCTION": "exec_spawn",
  "MESSAGE": "rkt-inspect.service: Failed at step NAMESPACE spawning /inspect: Invalid argument",
  "EXECUTABLE": "/inspect",
  "_SOURCE_REALTIME_TIMESTAMP": "1483859021903262"
}

A patched systemd with more detailed journal log entries triaged the EINVAL error source at the following remount operation: https://github.com/systemd/systemd/blob/v231/src/basic/mount-util.c#L431

Here systemd parses /proc/self/mountinfo and does a recursive bind-mount of each entry and remounts it, optionally read-only.

That remount fails sporadically.

The remount loop of mount entries fails at random places, but consistently at some /opt/stage2/.../proc/sys/... entry, for me it failed in /opt/stage2/rkt-inspect/rootfs/proc/sys/kernel/modprobe.

@s-urbaniak
Copy link
Contributor Author

So after discussion the above finding with @lucab we may have a candidate in prepare-app.c where we also bind-mount stage1's /proc to stage2's /proc recursively.

Now since systemd does a bind-mount dance afterwards too with /proc these mount events could be propagated between the two applications causing the above issues.

Recent changes in rkt-inspect amplify this hypothesis.

Marking /proc in prepare-app.c as MS_PRIVATE would prevent the above mentioned mount event propagation and alleviate the above behavior.

@squeed
Copy link
Contributor

squeed commented Jan 9, 2017

The question then is: are there any applications that rely on /proc being shared within the pod?

@lucab
Copy link
Member

lucab commented Jan 12, 2017

Further theory about mount propagation turned out to be also wrong: I tried marking all mounts performed by prepare-app as MS_PRIVATE, but the flake still showed up after a dozen of test iterations.

@evverx
Copy link
Contributor

evverx commented Jan 26, 2017

A patched systemd with more detailed journal log entries triaged the EINVAL error source at the following remount operation: https://github.com/systemd/systemd/blob/v231/src/basic/mount-util.c#L431

@s-urbaniak , did you get something like this

mount("/opt/stage2/rkt-inspect/rootfs/proc/sys/kernel/modprobe", "/opt/stage2/rkt-inspect/rootfs/proc/sys/kernel/modprobe", NULL, MS_BIND|MS_REC, NULL) = 0

mount("/opt/stage2/rkt-inspect/rootfs/proc/sys/kernel/modprobe", "/opt/stage2/rkt-inspect/rootfs/proc/sys/kernel/modprobe", 0x556ef5f5d270, MS_MGC_VAL|MS_RDONLY|MS_REMOUNT|MS_BIND, NULL) = -1 EINVAL (Invalid argument)

?
i.e mount --bind dir dir; mount -o remount,ro,bind ./dir didn't work. Right?

Which kernel version are you using?

@evverx
Copy link
Contributor

evverx commented Jan 26, 2017

This may be fixed by bumping systemd to 232

Nope. systemd/systemd#4752 (comment)

@s-urbaniak
Copy link
Contributor Author

@evverx yes, that is exactly the failure I saw when investigating the issue. The kernel under test was 4.8.13.

@evverx
Copy link
Contributor

evverx commented Jan 26, 2017

Well, I think this is a kernel issue.

mount --bind t t && mount -o remount,ro,bind t shouldn't fail. (do_remount shouldn't return -EINVAL after successful mount --bind t t)

@s-urbaniak ,please try this patch:

diff --git a/src/basic/mount-util.c b/src/basic/mount-util.c
index f0bc9ca..bd6c99d 100644
--- a/src/basic/mount-util.c
+++ b/src/basic/mount-util.c
@@ -453,7 +453,14 @@ int bind_remount_recursive(const char *prefix, bool ro, char **blacklist) {
                         orig_flags &= ~MS_RDONLY;

                         if (mount(NULL, prefix, NULL, orig_flags|MS_BIND|MS_REMOUNT|(ro ? MS_RDONLY : 0), NULL) < 0)
+                                log_error_errno(errno, "Failed to remount %s (first attempt): %m", prefix);
+
+                        sleep(5);
+
+                        if (mount(NULL, prefix, NULL, orig_flags|MS_BIND|MS_REMOUNT|(ro ? MS_RDONLY : 0), NULL) < 0) {
+                                log_error_errno(errno, "Failed to remount %s (second attempt): %m", prefix);
                                 return -errno;
+                        }

                         log_debug("Made top-level directory %s a mount point.", prefix);

Does it "fix" the test?

@evverx
Copy link
Contributor

evverx commented Jan 26, 2017

Also, it would be great to see all mount-args

@s-urbaniak
Copy link
Contributor Author

@evverx I'll try to get an overnight test run on my machine with the above patch and will let you know about the result.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants