When i start a Debian Jessie container (unprivileged) the /sbin/init (/lib/systemd/systemd) occupies 100% CPU and blocks the early boot for exactly 25 seconds. Only /sbin/init is spawned at that point. Later, journalctl or systemd-analyze only show proper started units (<0.010s). No evidence in any log (journalctl is not yet started). Booting needs 25.069s. On privileged 0.069s.
This is an strace log excerpt of lxc-start (its 46MB, 99% repeating the last lines clock_gettime, ppoll, recvmsg):
4153 open("/etc/hostname", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 4
4153 fstat64(4, {st_dev=makedev(8, 2), st_ino=45690, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=7, st_atime=1527429530 /* 2018-05-27T15:58:50.103537483+0200 */, st_atime_nsec=103537483, st_mtime=1527429530 /* 2018-05-27T15:58:50.103537483+0200 */, st_mtime_nsec=103537483, st_ctime=1527869703 /* 2018-06-01T18:15:03.130696223+0200 */, st_ctime_nsec=130696223}) = 0
4153 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fa1000
4153 read(4, "debian\n", 4096) = 7
4153 close(4) = 0
4153 munmap(0xb7fa1000, 4096) = 0
4153 sethostname("debian", 6) = 0
4153 writev(3, [{iov_base="Set hostname to <debian>.", iov_len=25}, {iov_base="\n", iov_len=1}], 2) = 26
4153 umask(000) = 000
4153 stat64("/etc", {st_dev=makedev(8, 2), st_ino=45306, st_mode=S_IFDIR|0755, st_nlink=47, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=4096, st_atime=1527429418 /* 2018-05-27T15:56:58.647396981+0200 */, st_atime_nsec=647396981, st_mtime=1527540643 /* 2018-05-28T22:50:43.441666447+0200 */, st_mtime_nsec=441666447, st_ctime=1527869703 /* 2018-06-01T18:15:03.160695190+0200 */, st_ctime_nsec=160695190}) = 0
4153 open("/etc/machine-id", O_RDWR|O_CREAT|O_NOCTTY|O_LARGEFILE|O_CLOEXEC, 0444) = 4
4153 umask(000) = 000
4153 fstat64(4, {st_dev=makedev(8, 2), st_ino=45791, st_mode=S_IFREG|0444, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=33, st_atime=1527540642 /* 2018-05-28T22:50:42.871552407+0200 */, st_atime_nsec=871552407, st_mtime=1527540642 /* 2018-05-28T22:50:42.871552407+0200 */, st_mtime_nsec=871552407, st_ctime=1527869703 /* 2018-06-01T18:15:03.160695190+0200 */, st_ctime_nsec=160695190}) = 0
4153 read(4, "8ea83f33af0d4f08a59d342d4b9675e3"..., 33) = 33
4153 close(4) = 0
4153 access("/proc/net", R_OK) = 0
4153 access("/proc/net/unix", R_OK) = 0
4153 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
4153 ioctl(4, SIOCGIFINDEX, {ifr_name="lo", }) = 0
4153 close(4) = 0
4153 socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC|SOCK_NONBLOCK, NETLINK_ROUTE) = 4
4153 setsockopt(4, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
4153 setsockopt(4, SOL_NETLINK, 3, [1], 4) = 0
4153 bind(4, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 16) = 0
4153 getsockname(4, {sa_family=AF_NETLINK, nl_pid=1, nl_groups=00000000}, [16->12]) = 0
4153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=3956, tv_nsec=105523734}) = 0
4153 sendto(4, {{len=32, type=0x14 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=0, pid=0}, "\x02\x08\x80\xfe\x01\x00\x00\x00\x08\x00\x02\x00\x7f\x00\x00\x01"}, 32, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 16 <unfinished ...>
4153 <... sendto resumed> ) = 32
4153 access("/sys/module/ipv6", F_OK <unfinished ...>
4153 <... access resumed> ) = 0
4153 open("/sys/module/ipv6/parameters/disable", O_RDONLY|O_LARGEFILE|O_CLOEXEC <unfinished ...>
4153 <... open resumed> ) = 5
4153 fstat64(5, <unfinished ...>
4153 <... fstat64 resumed> {st_dev=makedev(0, 20), st_ino=4000, st_mode=S_IFREG|0444, st_nlink=1, st_uid=65534, st_gid=65534, st_blksize=4096, st_blocks=0, st_size=4096, st_atime=1527875842 /* 2018-06-01T19:57:22.099624668+0200 */, st_atime_nsec=99624668, st_mtime=1527875842 /* 2018-06-01T19:57:22.099624668+0200 */, st_mtime_nsec=99624668, st_ctime=1527875842 /* 2018-06-01T19:57:22.099624668+0200 */, st_ctime_nsec=99624668}) = 0
4153 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
4153 <... mmap2 resumed> ) = 0xb7fa1000
4153 read(5, <unfinished ...>
4153 <... read resumed> "0\n", 4096) = 2
4153 close(5 <unfinished ...>
4153 <... close resumed> ) = 0
4153 munmap(0xb7fa1000, 4096) = 0
4153 clock_gettime(CLOCK_MONOTONIC, <unfinished ...>
4153 <... clock_gettime resumed> {tv_sec=3956, tv_nsec=124545017}) = 0
4153 sendto(4, {{len=44, type=0x14 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=1, pid=0}, "\x0a\x80\x80\xfe\x01\x00\x00\x00\x14\x00\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01"}, 44, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 16 <unfinished ...>
4153 <... sendto resumed> ) = 44
4153 clock_gettime(CLOCK_MONOTONIC, <unfinished ...>
4153 <... clock_gettime resumed> {tv_sec=3956, tv_nsec=141719457}) = 0
4153 sendto(4, {{len=32, type=0x13 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=2, pid=0}, "\x00\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00"}, 32, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 16 <unfinished ...>
4153 <... sendto resumed> ) = 32
4153 clock_gettime(CLOCK_MONOTONIC, <unfinished ...>
4153 <... clock_gettime resumed> {tv_sec=3956, tv_nsec=158887751}) = 0
4153 ppoll([{fd=4, events=POLLIN}], 1, {tv_sec=0, tv_nsec=0}, NULL, 8 <unfinished ...>
4153 <... ppoll resumed> ) = 1 ([{fd=4, revents=POLLIN}], left {tv_sec=0, tv_nsec=0})
4153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=3956, tv_nsec=160302704}) = 0
4153 recvmsg(4, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=NULL, iov_len=0}], msg_iovlen=1, msg_control=[{cmsg_len=16, cmsg_level=SOL_NETLINK, cmsg_type=0x3}, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=0, uid=65534, gid=65534}}], msg_controllen=40, msg_flags=MSG_TRUNC}, MSG_PEEK|MSG_TRUNC) = 36
4153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=3956, tv_nsec=160565581}) = 0
4153 ppoll([{fd=4, events=POLLIN}], 1, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=4, revents=POLLIN}], left {tv_sec=0, tv_nsec=0})
4153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=3956, tv_nsec=160732079}) = 0
4153 recvmsg(4, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=NULL, iov_len=0}], msg_iovlen=1, msg_control=[{cmsg_len=16, cmsg_level=SOL_NETLINK, cmsg_type=0x3}, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=0, uid=65534, gid=65534}}], msg_controllen=40, msg_flags=MSG_TRUNC}, MSG_PEEK|MSG_TRUNC) = 36
4153 clock_gettime(CLOCK_MONOTONIC, {tv_sec=3956, tv_nsec=160939364}) = 0
4153 ppoll([{fd=4, events=POLLIN}], 1, {tv_sec=0, tv_nsec=0}, NULL, 8) = 1 ([{fd=4, revents=POLLIN}], left {tv_sec=0, tv_nsec=0})
[...]
[...]
4153 writev(3, [{"Failed to configure loopback dev"..., 60}, {"\n", 1}], 2) = 61
4153 close(4)
It passes /etc/hostname, /etc/machine-id, /proc/net/unix and socket/AF_NETLINK.
The pattern matches loopback_setup(): https://github.com/systemd/systemd/blob/v215/src/core/main.c#L1563
Systemd cgroup is mounted:
systemd on /sys/fs/cgroup/systemd type cgroup (rw,relatime,name=systemd)
How can i allow this socket (or whatever blocks here)?
Edit:
Maybe related. The container cannot be stopped by ‘lxc-stop -n debian’ (priv and unpriv).
This does work though: ‘lxc-attach -n debian – halt’