[systemd-devel] systemd-nspawn container not starting on RHEL9.0

Thomas Archambault toma at TPArchambault.com
Tue Aug 9 16:40:08 UTC 2022


Thank you Lennart for the follow-up.

There does appear to be mostly filesystem operations prior to my 
manually killing nspawn as you suggested. I only let it run about 3 
minutes prior to sending a signal given that the strace output = ~25M.

One obvious issue is the non-zero return from an ioctl call with the 
BTRFS_IOC_SUBVOL_CREATE arg at line 410, in the snippet below from my 
RHEL9.0 strace capture; this is occurring right after the initial blast 
of debug log messages. I'm trying to get a stack trace for that error 
currently.


410-2064 ioctl(5</>, BTRFS_IOC_SUBVOL_CREATE, {fd=0</dev/pts/0>, 
name=".#machine.c8578d59f810b73d"}) = -1 ENOTTY (Inappropriate ioctl for 
device)

...

Setting RLIMIT_SIGPENDING to 14657.
Setting RLIMIT_MSGQUEUE to 819200.
Setting RLIMIT_NICE to 0.
Setting RLIMIT_RTPRIO to 0.
Setting RLIMIT_RTTIME to infinity.
Found cgroup2 on/sys/fs/cgroup/, full unified hierarchy

...

With the last line above generated from line 395's writev below. 
Unfortunately, I believe I left off the '-s 500' arg to strace. I can 
run things again if that's a help.

toma at toma-MacBookPro:20220808$ grep -nA25 cgroup2 
nspawn.rhel90.boot.strace.out
395:2064  writev(2</dev/pts/0>, [{iov_base="Found cgroup2 on 
/sys/fs/cgroup/"..., iov_len=56}, {iov_base="\n", iov_len=1}], 2) = 57
396-2064  rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], 
sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f0298fb3db0}, NULL, 8) = 0
397-2064  umask(022)                        = 022
398-2064  openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_PATH|O_DIRECTORY) = 
3</>
399-2064  close(3</>)                       = 0
400-2064  getrandom("\x8c\x75\xd8\x95\x8f\x01\x7b\xd3", 8, 
GRND_NONBLOCK|GRND_INSECURE) = 8
401-2064  newfstatat(AT_FDCWD, "/.#machine.c8578d59f810b73d", 
0x7ffef92612a0, 0) = -1 ENOENT (No such file or directory)
402-2064  openat(AT_FDCWD, "/.#.#machine.c8578d59f810b73d.lck", 
O_RDWR|O_CREAT|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC, 0600) = 
3</.#.#machine.c8578d59f810b73d.lck>
403-2064  fcntl(3</.#.#machine.c8578d59f810b73d.lck>, F_OFD_SETLK, 
{l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
404-2064  newfstatat(3</.#.#machine.c8578d59f810b73d.lck>, "", 
{st_mode=S_IFREG|0600, st_size=0, ...}, AT_EMPTY_PATH) = 0
405-2064  rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
406-2064  openat(AT_FDCWD, "/", O_RDONLY|O_NOCTTY|O_CLOEXEC|O_DIRECTORY) 
= 4</>
407-2064  newfstatat(4</>, "", {st_mode=S_IFDIR|0555, st_size=4096, 
...}, AT_EMPTY_PATH) = 0
408-2064  openat(AT_FDCWD, "/", O_RDONLY|O_CLOEXEC|O_DIRECTORY) = 5</>
409-2064  fcntl(5</>, F_GETFL)              = 0x18000 (flags 
O_RDONLY|O_LARGEFILE|O_DIRECTORY)
410-2064  ioctl(5</>, BTRFS_IOC_SUBVOL_CREATE, {fd=0</dev/pts/0>, 
name=".#machine.c8578d59f810b73d"}) = -1 ENOTTY (Inappropriate ioctl for 
device)
411-2064  close(5</>)                       = 0
412-2064  mkdir("/.#machine.c8578d59f810b73d", 0755) = 0
413-2064  newfstatat(4</>, "", {st_mode=S_IFDIR|0555, st_size=4096, 
...}, AT_EMPTY_PATH) = 0
414-2064  fcntl(4</>, F_DUPFD_CLOEXEC, 3)   = 5</>
415-2064  getrandom("\x77\x72\x24\xdb\xb2\xcf\x6e\x46", 8, 
GRND_NONBLOCK|GRND_INSECURE) = 8
416-2064  newfstatat(5</>, "", {st_mode=S_IFDIR|0555, st_size=4096, 
...}, AT_EMPTY_PATH) = 0
417-2064  fcntl(5</>, F_GETFL)              = 0x18000 (flags 
O_RDONLY|O_LARGEFILE|O_DIRECTORY)
418-2064  fcntl(5</>, F_SETFD, FD_CLOEXEC)  = 0
419-2064  openat(AT_FDCWD, "/.#machine.c8578d59f810b73d", 
O_RDONLY|O_CLOEXEC|O_DIRECTORY) = 6</.#machine.c8578d59f810b73d>
420-2064  getdents64(6</.#machine.c8578d59f810b73d>, 0x7ffef9260cc0 /* 2 
entries */, 840) = 48
toma at toma-MacBookPro:20220808$

That failure leads to many repeated filesystem operations for each 
resource, similar to the following except with differing file paths. As 
you suggested that's the reason for the delay in spawning the container.

2297  newfstatat(7</tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
{st_mode=S_IFDIR|0700, st_size=17, ...}, AT_SYMLINK_NOFOLLOW) = 0
2297  statx(7</tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW|AT_NO_AUTOMOUNT, STATX_TYPE, 
{stx_mask=STATX_BASIC_STA
TS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0700, stx_size=17, 
...}) = 0
2297  openat(7</tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) = 
9</tmp/systemd-private-ceff107148c24952bc
2765d331699258-switcheroo-control.service-ZzjWeB>
2297 
newfstatat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
"", {st_mode=S_IFDIR|0700, st_size=17, ...}, AT_EMPTY_PATH) = 0
2297 
fcntl(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
F_GETFL) = 0x38000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_DIRECTORY)
2297 
fcntl(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
F_SETFD, FD_CLOEXEC) = 0
2297  openat(8</.#machine.556acffc5c4193f9/tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
O_RDONLY|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or directo
ry)
2297  mkdirat(8</.#machine.556acffc5c4193f9/tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
0700) = 0
2297  openat(8</.#machine.556acffc5c4193f9/tmp>, 
"systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB", 
O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) = 10</.#machine.
556acffc5c4193f9/tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>
2297 
getdents64(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
0x55f6b5181f00 /* 3 entries */, 32768) = 72
2297  rt_sigtimedwait([INT], NULL, {tv_sec=0, tv_nsec=0}, 8) = -1 EAGAIN 
(Resource temporarily unavailable)
2297 
newfstatat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
"tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=6, ...}, 
AT_SYMLINK_NOFOLLOW) = 0
2297 
statx(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
"tmp", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW|AT_NO_AUTOMOUNT, 
STATX_TYPE, {stx_mask=STATX_BASIC
_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|S_ISVTX|0777, 
stx_size=6, ...}) = 0
2297 
openat(9</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
"tmp", O_RDONLY|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC|O_DIRECTORY) = 
11</tmp/systemd-private-ceff107148c24
952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>
2297 
newfstatat(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>, 
"", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=6, ...}, AT_EMPTY_PATH) = 0
2297 
fcntl(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>, 
F_GETFL) = 0x38000 (flags O_RDONLY|O_LARGEFILE|O_NOFOLLOW|O_DIRECTORY)
2297 
fcntl(11</tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB/tmp>, 
F_SETFD, FD_CLOEXEC) = 0
2297 
openat(10</.#machine.556acffc5c4193f9/tmp/systemd-private-ceff107148c24952bc2765d331699258-switcheroo-control.service-ZzjWeB>, 
"tmp", O_RDONLY|O_CLOEXEC|O_DIRECTORY) = -1 ENOENT (No such file or di
rectory)


Any thoughts, or comments are appreciated.

Regards,

-Tom

PS and fwiw: systemd version 250, Linux 5.14.0-70.17.1.el9_0.x86_64, 
over xfs.

On 8/4/22 16:49, Lennart Poettering wrote:
> On Do, 04.08.22 13:30, Thomas Archambault (toma at TPArchambault.com) wrote:
>
>> Following up on xfs and reflinks, it appears they are enabled on my
>> out-of-box RHEL9.0. Fwiw, this is a VBox VM however so if the FC34 system
>> which works correctly, but is using btrfs.
>>
>> As always, appreciate any help/references.
> Try straceing nspawn, to see what it does.
>
> strace -f -y -s 500 -o /tmp/nspawnstrace.log systemd-nspawn …
>
> Then look at the generated log and see what is busy doing... If unsure
> paste things somewhre.
>
> Lennart
>
> --
> Lennart Poettering, Berlin
>


More information about the systemd-devel mailing list