High cpu usage in LXD containers

[ghost]

This has been reproduced in CRUX distribution running in an LXD container. Every time syslogd is started it reaches 100% cpu utilization. It seems to be something specific to running in unprivileged containers.

[troglobit]

Do you have any tips for me how to easily reproduce this? URL, some link to a cookbook or something?

[ghost]

It occurs in a CRUX 3.6 LXD container on a Ubuntu Server 20.04 host. I just use the default LXD settings for the most part, minus a few things for the container filesystem and networking. We had the same behavior with a different syslogd implementation and I worked around it with some option (-s I think) that switched the kernel messaging to a system call API, whatever that meant exactly.

[ghost]

If you really need access to it I can arrange SSH access to debug from the container.

[troglobit]

Basically I just want a way for me to reproduce, and possibly even set up a test case for this in the sysklogd project. I don't have access to a CRUX installation and I don't have LXD, so I was curious if you could describe how you run things in an LXD container, what limitations you've seen. Currently sysklogd unconditionally tries to open /dev/kmsg, with fallback to /proc/kmsg, only if opening both fail does it disable kernel logging. So there's no way to disable this, if that is the root cause of this issue.

[ghost]

It's being run as a sysvinit service in the CRUX container. I've just been unable to determine what code is causing syslogd to go to 100% cpu utilization in this environment. I'll try to get a container setup where I can reproduce it.

[troglobit]

OK. I'll try to set up something similar using plain lxc. Do you happen to know the command line arguments used, and the /etc/syslog.conf file? Would be really helpful! :)

[ghost]

The arguments seem to mostly be irrelevant. It goes to 100% regardless.

[ghost]

This is the contents of the file. The included directory is empty.

#
# /etc/syslog.conf
#

*.emerg                                         *
kern.*                                          /var/log/kernel
authpriv,auth.info                              /var/log/auth
mail.info                                       /var/log/mail
cron.info                                       /var/log/cron
*.info;authpriv,auth,mail,cron,kern.none        /var/log/messages
*.=debug;kern.none                              /var/log/debug

include /etc/syslog.d/*.conf

# End of file

[ghost]

Also since LXD defaults to unprivileged containers you may also want to test those in addition to privileged containers. The difference is whether the containers run with UID/GID mapping or not.

[ghost]

Another thing I've noted is that syslogd seems to become unresponsive to signals while in this state. I have to use SIGKILL to end it.

[ghost]

Also config file seems to make little difference. It still does it even if I comment out all the lines, basically leaving it with an empty config file.

[troglobit]

Thank you so much for the follow-up! This will definitely help <3

[ghost]

I'm working on a temporary container but it's going to take a bit to compile the software. CRUX is mostly source based and all.

[troglobit]

No worries. I'm building an image from Buildroot ... and will also probably soon retire for the evening. But I'll be back again tomorrow morning, CET.

[ghost]

Ok. I found something strange. If I delete /dev/kmsg, syslogd works as expected. But if /dev/kmsg is a regular file, syslogd goes to 100% cpu utilization. /proc/kmsg is provided by the container but /dev/kmsg isn't necessarily. Perhaps the simplest workaround is to check if /dev/kmsg is an actual block or character device before attempting to use it?

[ghost]

Either that or find a more suitable approach to selecting the kernel interface to use.

[troglobit]

Yeah I suspected something like that. Having a check for character device is definitely useful.

I'm also starting to realize that logging kernel events in a container isn't that useful, the kernel is shared with the host (and perhaps many other containers), so best to avoid logging that. What's worse, if we did read kernel logs from /proc/kmsg we would steal log messages from the host ... that's the difference to /dev/kmsg, it allows multiple readers.

So we probably also need a way to disable kernel logs altogether. (Since I know of no reliable method to detect if one is in a container or not, which I guess is sort of the point.)

I'll see if I can spend some more time today reproducing this.

[ghost]

Yea, it makes sense to double check that a device node matches the expected interface. Regarding LXC/LXD containers, I note they usually lack /dev/kmsg but have /proc/kmsg. It's how dmesg is still able to work to a degree in containers. If there's no reason to retain support for /proc/kmsg, you could just remove that and shore up the /dev/kmsg checks. That should automatically filter out the impacted containers due to lacking a suitable kernel logging interface.

[troglobit]

Finally reproduced the issue over here. So it's definitely an issue with sysklogd itself. I've tried disabling /dev/kmsg and then it's a lot calmer, although still runs at 12% CPU. We definitely need a command line flag to disable opensys() from being called, at all. I got stuck figuring one out though ... I think I'll rename the new (yet unreleased) -K option to -t and use -K to disable kernel logging.

Btw, I guess /proc is just shared from the host since many apps need /proc ...

[ghost]

systemd apparently has some way to sniff out the type of virtualization in use. Perhaps you could see what it's doing to detect containers?

https://www.man7.org/linux/man-pages/man1/systemd-detect-virt.1.html

[troglobit]

Interesting, thanks I'll look into it! (Probably add -K anyway for this)

[troglobit]

There, fixed -- with an extra little tweak to detect the most common (?) container scenarios and disable kernel logging.

Thank you for the report and the sparring on this, very appreciated! <3

[TimB87]

Hi @troglobit @braewoods Thanks for looking into this. Current HEAD fails to build with the following:

=======> Building '/home/pkgmk/packages_c36/sysklogd#2.3.0-2.pkg.tar.gz'.
bsdtar -p -o -C /home/ramdisk/sysklogd/src -xf /home/pkgmk/distfiles/sysklogd-2.3.0.tar.gz
[…]
+ patch -Np1 -i /home/ramdisk/sysklogd/src/kmsg.patch                                                                                                                                                            
patching file man/syslog.conf.5                                                                                                                                                                                  
patching file man/syslogd.8                                                                                                                                                                                      
patching file src/syslogd.c
[…]
------------------ Summary ------------------
 sysklogd version 2.3.0
  Prefix.........: /usr
  Sysconfdir.....: /etc
  Runstatedir....: /run
  C Compiler.....: gcc -O2 -march=x86-64   

 Optional features:
  logger.........: no
  suspend time...: 180 sec
  systemd........: no

------------- Compiler version --------------
gcc (CRUX-x86_64-multilib) 10.3.0
Copyright (C) 2020 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
---------------------------------------------
[…]
+ make
make  all-recursive
make[1]: Entering directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0'
Making all in example
make[2]: Entering directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/example'
make[2]: Nothing to be done for 'all'.
make[2]: Leaving directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/example'
Making all in man
make[2]: Entering directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/man'
make[2]: Nothing to be done for 'all'.
make[2]: Leaving directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/man'
Making all in src
make[2]: Entering directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/src'
  CC       syslogd-syslogd.o
  CC       syslogd-socket.o
  CC       syslogd-timer.o
  CC       libsyslog_la-syslog.lo
  CC       ../lib/pidfile.lo
  CC       ../lib/strlcpy.lo
  CC       ../lib/strlcat.lo
  CCLD     libsyslog.la
syslogd.c: In function 'main':
syslogd.c:517:2: error: label at end of compound statement
  517 |  no_klogd:
      |  ^~~~~~~~
make[2]: *** [Makefile:672: syslogd-syslogd.o] Error 1
make[2]: *** Waiting for unfinished jobs....
make[2]: Leaving directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0/src'
make[1]: *** [Makefile:511: all-recursive] Error 1
make[1]: Leaving directory '/home/ramdisk/sysklogd/src/sysklogd-2.3.0'
make: *** [Makefile:399: all] Error 2
=======> ERROR: Building '/home/pkgmk/packages_c36/sysklogd#2.3.0-2.pkg.tar.gz' failed.

Of course, this is inside a LXC/LXD container :)

[troglobit]

Thanks for the heads-up, @TimB87! Dunno why I didn't catch that myself, it's right there, plain as day now that I rebuild ... oh well.

[TimB87]

This builds fine for me! Thank you @troglobit