slirp4netns: endless loop or huge cpu usage (related to UDP?)

[disaster123]

Hello,

while using jitsi with podman i'm seeing slirp4netns getting stuck constantly at 100% cpu no longer accepting connections.

Command started by podman:

/usr/bin/slirp4netns --disable-host-loopback --mtu 65520 --enable-sandbox --enable-seccomp --api-socket /run/user/1000/libpod/tmp/d60771fb7b575a35f90f9c8525578df771dd3812aa14314b31d0a659b2e91c6b.net -c -e 3 -r 4 --netns-type=path /run/user/1000/netns/cni-e592fe0c-c16c-b9ca-a989-cea8c63152be tap0

slirp4netns binary is this one: https://github.com/rootless-containers/slirp4netns/releases/download/v1.1.4/slirp4netns-x86_64

gdb shows (i don't have any debug symbols for the build):

(gdb) bt
#0  0x00000000004ecf97 in ?? ()
#1  0x000000000044dcf6 in ?? ()
#2  0x00007fff9688e350 in ?? ()
#3  0x0000000000b7fd00 in ?? ()
#4  0x00007fff9688e3a0 in ?? ()
#5  0x0000000000b7e3f0 in ?? ()
#6  0x0000000000b84f28 in ?? ()
#7  0x0000000000ba8790 in ?? ()
#8  0x0000000000b7e3f0 in ?? ()
#9  0x0000000000ba8800 in ?? ()
#10 0x00007fff9688e370 in ?? ()
#11 0x000000000045e55c in ?? ()
#12 0x0000000000ba8800 in ?? ()
#13 0x0000000000ba8790 in ?? ()
#14 0x00007fff9688e5b0 in ?? ()
#15 0x00000000004514e0 in ?? ()
#16 0x0000000100ba8790 in ?? ()
#17 0x0000000000000000 in ?? ()

strace shows:

ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=563842199}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=563886704}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=563931690}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564033383}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564124767}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564170634}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564213966}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564302274}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564374191}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564408837}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564448211}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564533874}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564606082}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564653432}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564697726}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564787697}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564858442}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564896244}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=564932733}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565085363}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565180463}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565230809}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565282268}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565398739}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565497907}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565545228}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565597166}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565726361}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565853063}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565908568}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=565966418}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566108508}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566228335}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566287689}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566369464}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566502007}) = 0
ioctl(9, FIONREAD, [0])                 = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566656831}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566709711}) = 0
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566761750}) = 0
poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
clock_gettime(CLOCK_MONOTONIC, {tv_sec=1084528, tv_nsec=566891958}) = 0

I can only fix this by restartin the whole container.

Stefan

[AkihiroSuda]

Could you provide full reproducer?

[AkihiroSuda]

gdb

If you compile slirp4netns from source, maybe you will get symbols

[AkihiroSuda]

It seems this loop is iterating too much without any packet?

slirp4netns/slirp4netns.c

Line 370 in 6767922

while (1) {

cc @giuseppe

[disaster123]

Could you provide full reproducer?

no it happens out of nothing - but on a regular basis (two times a week)

gdb

If you compile slirp4netns from source, maybe you will get symbols

Last time i did it wasn't working - that the reason i'm using the provided static binaries.

[giuseppe]

something seems wrong with FIONREAD reporting 0 bytes after a SLIRP_POLL_IN event:

poll([{fd=7, events=POLLIN|POLLHUP}, {fd=3, events=POLLHUP}, {fd=5, events=POLLIN|POLLHUP}, {fd=10, events=POLLIN|POLLERR|POLLHUP}, {fd=8, events=POLLIN|POLLERR|POLLHUP}, {fd=9, events=POLLIN|POLLERR|POLLHUP}], 6, 499) = 1 ([{fd=9, revents=POLLIN}])
ioctl(9, FIONREAD, [0])                 = 0

I am not sure how this could happen, and if libslirp could avoid using FIOREAD.

[AkihiroSuda]

Thanks @giuseppe

Seems somehow related to UDP? https://gitlab.freedesktop.org/slirp/libslirp/-/blob/v4.3.1/src/socket.c#L532

@disaster123 Does jitsi heavily uses UDP? Do you think the packet in the problem is coming from jitsi or DNS?

[disaster123]

@AkihiroSuda yes it uses heavily UDP

[AkihiroSuda]

What is the port forwarder? RootlessKit (default in the recent Podman), or slirp4netns (non-default)?

[disaster123]

slirp4netns as RootlessKit does not keep the source ip

[disaster123]

@AkihiroSuda any news or ideas?