=^.^=

Monitoring Per-Process Memory Usage after OOM-Killer Spree

• karma

It's difficult to pin down the culprit when the Out-Of-Memory killer starts killing processes due to memory starvation, inevitably leaving the system crashed or catastrophically disabled and a long bloody trail of victims in /var/log/messages but not much in the way of a smoking gun. Meanwhile, the pixels of resource graphs shed no light on what memleak exactly went out of control. If it's a recurring problem you almost have to catch it in the act - and good luck to you if it is sporadic or only takes minutes once underway. I have battled this issue on critical systems for almost two decades.

Dec 11 16:40:44 router kernel: sshd invoked oom-killer: gfp_mask=0xd0, order=0, oomkilladj=0 Dec 11 16:40:44 router kernel: [out_of_memory+114/419] out_of_memory+0x72/0x1a3 Dec 11 16:40:44 router kernel: [<c0454b97>] out_of_memory+0x72/0x1a3 Dec 11 16:40:44 router kernel: [__alloc_pages+590/719] __alloc_pages+0x24e/0x2cf Dec 11 16:40:44 router kernel: [<c04561b3>] __alloc_pages+0x24e/0x2cf Dec 11 16:40:44 router kernel: [__get_free_pages+37/49] __get_free_pages+0x25/0x31 Dec 11 16:40:44 router kernel: [<c0456259>] __get_free_pages+0x25/0x31 Dec 11 16:40:44 router kernel: [proc_pid_readlink+93/215] proc_pid_readlink+0x5d/0xd7 Dec 11 16:40:44 router kernel: [<c04a279b>] proc_pid_readlink+0x5d/0xd7 Dec 11 16:40:44 router kernel: [sys_readlinkat+121/146] sys_readlinkat+0x79/0x92 Dec 11 16:40:44 router kernel: [<c047a8ae>] sys_readlinkat+0x79/0x92 Dec 11 16:40:44 router kernel: [do_softirq+28/174] do_softirq+0x1c/0xae Dec 11 16:40:44 router kernel: [<c0406dfb>] do_softirq+0x1c/0xae Dec 11 16:40:45 router fail2ban.actions: WARNING [ssh-iptables] Ban 128.199.194.1 Dec 11 16:40:45 router kernel: [__do_IRQ+0/214] __do_IRQ+0x0/0xd6 Dec 11 16:40:45 router kernel: [<c0447d98>] __do_IRQ+0x0/0xd6 Dec 11 16:40:45 router kernel: [do_IRQ+181/195] do_IRQ+0xb5/0xc3 Dec 11 16:40:45 router kernel: [<c0406f42>] do_IRQ+0xb5/0xc3 Dec 11 16:40:45 router kernel: [sys_readlink+19/23] sys_readlink+0x13/0x17 Dec 11 16:40:45 router kernel: [<c047a8da>] sys_readlink+0x13/0x17 Dec 11 16:40:45 router kernel: [syscall_call+7/11] syscall_call+0x7/0xb Dec 11 16:40:45 router kernel: [<c0405413>] syscall_call+0x7/0xb Dec 11 16:40:45 router kernel: ======================= Dec 11 16:40:45 router kernel: Mem-info: Dec 11 16:40:45 router kernel: DMA per-cpu: Dec 11 16:40:45 router kernel: cpu 0 hot: high 186, batch 31 used:71 Dec 11 16:40:45 router kernel: cpu 0 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 1 hot: high 186, batch 31 used:149 Dec 11 16:40:45 router kernel: cpu 1 cold: high 62, batch 15 used:50 Dec 11 16:40:45 router kernel: cpu 2 hot: high 186, batch 31 used:154 Dec 11 16:40:45 router kernel: cpu 2 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 3 hot: high 186, batch 31 used:164 Dec 11 16:40:45 router kernel: cpu 3 cold: high 62, batch 15 used:55 Dec 11 16:40:45 router kernel: cpu 4 hot: high 186, batch 31 used:34 Dec 11 16:40:45 router kernel: cpu 4 cold: high 62, batch 15 used:58 Dec 11 16:40:45 router kernel: DMA32 per-cpu: empty Dec 11 16:40:45 router kernel: Normal per-cpu: empty Dec 11 16:40:45 router kernel: HighMem per-cpu: Dec 11 16:40:45 router kernel: cpu 0 hot: high 186, batch 31 used:4 Dec 11 16:40:45 router kernel: cpu 0 cold: high 62, batch 15 used:5 Dec 11 16:40:45 router kernel: cpu 1 hot: high 186, batch 31 used:146 Dec 11 16:40:45 router kernel: cpu 1 cold: high 62, batch 15 used:14 Dec 11 16:40:45 router kernel: cpu 2 hot: high 186, batch 31 used:122 Dec 11 16:40:45 router kernel: cpu 2 cold: high 62, batch 15 used:14 Dec 11 16:40:45 router kernel: cpu 3 hot: high 186, batch 31 used:171 Dec 11 16:40:45 router kernel: cpu 3 cold: high 62, batch 15 used:4 Dec 11 16:40:45 router kernel: cpu 4 hot: high 186, batch 31 used:47 Dec 11 16:40:45 router kernel: cpu 4 cold: high 62, batch 15 used:13 Dec 11 16:40:45 router kernel: Free pages: 5447468kB (5444128kB HighMem) Dec 11 16:40:45 router kernel: Active:17178 inactive:6990 dirty:13 writeback:0 unstable:0 free:1361867 slab:167350 mapped-file:4536 mapped-anon:11829 pagetables:665 Dec 11 16:40:45 router kernel: DMA free:3340kB min:3452kB low:4312kB high:5176kB active:128kB inactive:0kB present:745464kB pages_scanned:93 all_unreclaimable? yes Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 5416 Dec 11 16:40:45 router kernel: DMA32 free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 5416 Dec 11 16:40:45 router kernel: Normal free:0kB min:0kB low:0kB high:0kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 43328 Dec 11 16:40:45 router kernel: HighMem free:5444128kB min:512kB low:6932kB high:13352kB active:68584kB inactive:27960kB present:5545992kB pages_scanned:0 all_unreclaimable? no Dec 11 16:40:45 router kernel: lowmem_reserve[]: 0 0 0 0 Dec 11 16:40:45 router kernel: DMA: 15*4kB 20*8kB 31*16kB 16*32kB 9*64kB 2*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 3340kB Dec 11 16:40:45 router kernel: DMA32: empty Dec 11 16:40:45 router kernel: Normal: empty Dec 11 16:40:45 router kernel: HighMem: 32*4kB 370*8kB 659*16kB 499*32kB 536*64kB 235*128kB 85*256kB 33*512kB 15*1024kB 8*2048kB 1289*4096kB = 5444128kB Dec 11 16:40:45 router kernel: 12253 pagecache pages Dec 11 16:40:45 router kernel: Swap cache: add 0, delete 0, find 0/0, race 0+0 Dec 11 16:40:45 router kernel: Free swap = 0kB Dec 11 16:40:45 router kernel: Total swap = 0kB Dec 11 16:40:45 router kernel: Free swap: 0kB Dec 11 16:40:45 router kernel: 1572864 pages of RAM Dec 11 16:40:45 router kernel: 1386498 pages of HIGHMEM Dec 11 16:40:45 router kernel: 15394 reserved pages Dec 11 16:40:45 router kernel: 21560 pages shared Dec 11 16:40:45 router kernel: 0 pages swap cached Dec 11 16:40:45 router kernel: 13 pages dirty Dec 11 16:40:45 router kernel: 0 pages writeback Dec 11 16:40:45 router kernel: 4536 pages mapped Dec 11 16:40:45 router kernel: 167350 pages slab Dec 11 16:40:45 router kernel: 665 pages pagetables Dec 11 16:40:45 router kernel: Out of memory: Killed process 6421, UID 416, (system-mysqld).

We can take steps like recording per-process memory use over time and make comparisons to attempt identification. Create /usr/sbin/psmon.sh:

#!/bin/bash # https://foxpa.ws/monitoring-memory-use-after-oom-killer-spree LOG_PATH=/var/log/ps/ FILE_NAME=ps.`date +%Y%m%d%H%M` RETAIN_DAYS=7 find $LOG_PATH -mtime +$RETAIN_DAYS -type f -delete ps -o pid,user,%mem,vsz,rss,command ax | head -n 1 > $LOG_PATH$FILE_NAME ps -o pid,user,%mem,vsz,rss,command ax --no-headers | sort -bnrk 5 >> $LOG_PATH$FILE_NAME

Note that the first call to ps is just to extract the column header names; by using an identical call for data and headers ps does all the work for us of making sure the spacing aligns properly. The call to sort will order the results by their RSS or Resident State Size. This is a better metric for our purposes than VSZ (virtual memory) which counts unused allocations that may be squeezed off as memory pressure builds up.

PID USER %MEM VSZ RSS COMMAND 6801 416 0.3 139892 19620 /usr/share/system-mysql/usr/libexec/system-mysqld --defaults-file=/usr/share/system-mysql/etc/my.cnf --basedir=/usr/share/system-mysql --datadir=/var/lib/system-mysql --user=system-mysql --pid-file=/var/run/system-mysqld/system-mysqld.pid --skip-external-locking --port=3308 --socket=/var/lib/system-mysql/mysql.sock 16679 ldap 0.2 465212 17984 /usr/sbin/slapd -h ldap://127.0.0.1/ -u ldap 6621 101 0.1 34300 9860 webconfig 26409 101 0.1 34300 9792 webconfig 6843 root 0.1 28436 8944 webconfig 6704 root 0.1 27872 7064 /usr/sbin/snmpd -Lsd -Lf /dev/null -p /var/run/snmpd.pid -a 7043 root 0.0 9764 5396 syswatch 6887 root 0.0 92804 4208 /usr/bin/python /usr/bin/fail2ban-server -b -s /var/run/fail2ban/fail2ban.sock -x 12516 root 0.0 14132 3952 sshd: root@pts/1 ...

This configuration, where the output from each run is placed into a separate file which includes a timestamp in the filename lends itself well to capturing detailed, multi-line output, in contrast with typical log files. It also lends itself well to our purpose here, where we want to inspect changes to a specific process over time, by using a simple batch grep:

grep webconfig * ps.202312150201:23383 101 0.1 34296 9876 webconfig ps.202312150301:23383 101 0.1 34296 9876 webconfig ps.202312150401:23383 101 0.1 34296 9876 webconfig ...

However this multi-file setup is not the kind of situation logrotate was made for and as we log every hour - or even less, if your particular memleak tends to rev up in minutes or seconds - there will soon be multitudes of files which will make haystack work of zeroing in, not to mention consume storage resources. Therefore, we perform our own garbage collection with find: simply set the maximum number of days you would like to retain data for as the RETAIN_DAYS variable.

Now we set the stage and configure crond to record hourly (or less, via crontab):
mkdir /var/log/ps chmod +x /usr/sbin/psmon.sh ln -s /usr/sbin/psmon.sh /etc/cron.hourly/

It now becomes possible to inspect changes to memory utilization on a per-process basis and hopefully identify the suspect after the next incident, then prevent it from striking again.

ClearOS Complains of Down or Missing LDAP Service

• karma

If you find yourself unable to load certain parts of the ClearOS webconfig because they complain of LDAP problems, or if you experience inconsistent results authenticating with one or more services, check slapd:

service ldap restart Stopping slapd: [FAILED] /var/lib/ldap/log.0000000005 is not owned by "ldap"[WARNING] Checking configuration files for slapd: [FAILED] bdb_db_open: database "cn=accesslog": unclean shutdown detected; attempting recovery. bdb_db_open: database "cn=accesslog": recovery skipped in read-only mode. Run manual recovery if errors are encountered. bdb(dc=router,dc=domain,dc=com): /var/lib/ldap/log.0000000005: log file unreadable: Permission denied bdb(dc=router,dc=domain,dc=com): PANIC: Permission denied bdb(dc=router,dc=domain,dc=com): Invalid log file: log.0000000005: DB_RUNRECOVERY: Fatal error, run database recovery bdb(dc=router,dc=domain,dc=com): PANIC: DB_RUNRECOVERY: Fatal error, run database recovery bdb(dc=router,dc=domain,dc=com): unable to join the environment bdb_db_open: database "dc=router,dc=domain,dc=com" cannot be opened, err -30975. Restore from backup! backend_startup_one: bi_db_open failed! (-30975) slap_startup failed (test would succeed using the -u switch) stale lock files may be present in /var/lib/ldap/accesslog[WARNING] ls -lsah /var/lib/ldap/log.0000000005 11M -rw-r----- 1 root root 10M Dec 12 09:18 /var/lib/ldap/log.0000000005 ls -lsah /var/lib/ldap log.0000000004 log.0000000005 ls -lsah /var/lib/ldap/log.0000000004 11M -rw------- 1 ldap ldap 10M Oct 4 2021 /var/lib/ldap/log.0000000004 chown ldap:ldap /var/lib/ldap/log.0000000005 service ldap restart Stopping slapd: [FAILED] Checking configuration files for slapd: [WARNING] bdb_db_open: database "cn=accesslog": unclean shutdown detected; attempting recovery. bdb_db_open: database "cn=accesslog": recovery skipped in read-only mode. Run manual recovery if errors are encountered. config file testing succeeded Starting slapd: [ OK ] service ldap restart Stopping slapd: [ OK ] Starting slapd: [ OK ]

Unable to Login as root on Serial Terminal, Physical Console or Pseudoterminal with Correct Password

• karma

If you find yourself able to log in under user accounts but not directly as root on one or more consoles, yet you are able to log in as a user then su - without issue, can log in over SSH or other remotely accessible services that authenticate by root account, you may have a pam_securetty misconfiguration. Check /var/log/secure:

Dec 12 08:33:20 host login: pam_securetty(login:auth): access denied: tty 'ttyS0' is not secure !

Add the missing serial interface to /etc/securetty. If using Xen, cover your bases and make sure hvc0 and xvc0 are included as well.

Enable xenconsoled Serial Logging

• karma

Be sure to take into consideration the potential security implications of storing every detail from every management session conducted by serial. By nature of the interface, most will be root/sudoer logins.

On a fresh Red Hat/CentOS dom0 you will find /var/log/xen/console/ barren, or perhaps not even extant (mkdir -P). On older installations that come with a xend service, you can enable serial console recording globally (all domUs at once) by setting XENCONSOLED_LOG_GUESTS=yes in /etc/sysconfig/xend and restarting the xend service.

XENCONSOLED_LOG_HYPERVISOR=yes XENCONSOLED_TIMESTAMP_HYPERVISOR_LOG=yes XENCONSOLED_LOG_GUESTS=yes XENCONSOLED_TIMESTAMP_GUEST_LOG=yes XENCONSOLED_LOG_DIR=/var/log/xen/console/

On newer system.d installations run out of xencommons I had to run down the environment variables:

locate xenconsoled.service /etc/systemd/system/multi-user.target.wants/xenconsoled.service /usr/lib/systemd/system/xenconsoled.service cat /usr/lib/systemd/system/xenconsoled.service [Unit] Description=Xenconsoled - handles logging from guest consoles and hypervisor Requires=proc-xen.mount xenstored.service After=proc-xen.mount xenstored.service ConditionPathExists=/proc/xen/capabilities [Service] Type=simple Environment=XENCONSOLED_ARGS= Environment=XENCONSOLED_TRACE=none Environment=XENCONSOLED_LOG_DIR=/var/log/xen/console EnvironmentFile=/etc/sysconfig/xencommons ExecStartPre=/bin/grep -q control_d /proc/xen/capabilities ExecStartPre=/bin/mkdir -p ${XENCONSOLED_LOG_DIR} ExecStart=/usr/sbin/xenconsoled -i --log=${XENCONSOLED_TRACE} --log-dir=${XENCONSOLED_LOG_DIR} $XENCONSOLED_ARGS [Install] WantedBy=multi-user.target xenconsoled --help Usage: xenconsoled [-h] [-V] [-v] [-i] [--log=none|guest|hv|all] [--log-dir=DIR] [--pid-file=PATH] [-t, --timestamp=none|guest|hv|all] [-o, --overflow-data=discard|keep]
Documentation regarding xenconsoled's options is scarce to say the least. At the time of publication I'm apparently the first person on the internet to have tried figuring out what important-sounding --overflow-data does. Fortunately xenconsoled plays nicely with being killed live on the command line and having its flags twiddled with - it will even auto-daemonize. Avoid spawning more than one instance at a time, though doing so produces no catastrophically ill effects.

Once you have settled on a configuration, it is made persistent by dropping environment variables into the very top of /etc/sysconfig/xencommons:

## Path: System/Virtualization ## Type: string ## Default: "none" # # Log xenconsoled messages (cf xl dmesg) #XENCONSOLED_TRACE=[none|guest|hv|all] XENCONSOLED_TRACE=all XENCONSOLED_ARGS="--timestamp=all" #XENCONSOLED_LOG_DIR=/var/log/xen/console

On Debian and derivatives like Ubuntu the same is accomplished by setting:
XENCONSOLED_ARGS="--timestamp=all --log=all --log-dir=/var/log/xen/console/"
in /etc/default/xend.

Another option is the direct route:
nohup xl console domain 2>&1 tee /var/log/xen/console/guest-domain.log &

Note that the actual client interface, xenconsole can be called directly, but typically is not in your PATH by default and must be called from its location. It accepts a domain ID number as opposed to a domain name, but allows one to specify if the interface to which you are connecting is provided by HVM/QEMU (serial) or PV (pv) using the --type flag:

/usr/lib64/xen/bin/xenconsole --help Usage: /usr/lib64/xen/bin/xenconsole [OPTION] DOMID Attaches to a virtual domain console -h, --help display this help and exit -n, --num N use console number N --type TYPE console type. must be 'pv' or 'serial' --start-notify-fd N file descriptor used to notify parent xl list | grep domain domain 5 8192 5 -b---- 119.1 /usr/lib64/xen/bin/xenconsole 5

You can tee your interactive session to a logfile, but unlike the configuration shown above the flow into the file will cease when you exit xenconsole:

/usr/lib64/xen/bin/xenconsole 5 tee:stdio,file:/var/log/xen/console/guest-domain.log

Some interesting and highly technical background on the provisioning and configuration of the underlaying serial devices and emulations is provided in https://xenbits.xenproject.org/docs/unstable/misc/console.txt however you are unlikely to find it useful to your logging endeavour unless you are engaged in extreme debugging.

Running OPNsense Serial image Installer on Xen

• karma

I'm not used to using hard drive images as VM installation media as opposed to ISO images. The boot="dc" directive in a Xen configuration flatfile specifies boot order by device type and not address - putting 'd' before 'c' does not mean the second image file specified will be booted, it means any CD-ROM image will be booted before any hard drive image.

From the official Xen wiki, Setting boot order for domUs:

# boot on floppy (a), hard disk (c), Network (n) or CD-ROM (d) # default: hard disk, cd-rom, floppy boot="cda"

Pecking order is then resolved by the sequence of definition. The same is even true of XenCenter which provides a dropdown selector of bootable media categories and no way to specify a single image. Even the CLI toolstack does not provide this facility and that makes me leery of installations where the second disk image that we are installing to will be misidentified by device node upon completing the installation when we've detatched the installer's image and the installed image's device node is bumped up in sequence.

Fortunately (so far!), at least OPNsense seems to boot without issue from what was adb1 during installation but forevermore occupies adb0. However, from experience I know this will not hold true for many installations. The fix is to mount the guest image while it is shut down and try to search-and-replace every reference to the root device's node. I start by grepping the whole /etc tree and then focus on the guest's bootloader - which may require an offline, chrooted redeployment post-reconfiguration.

I used the following config and simply twiddled the disk line:

name = "opnsense-serial" type = "hvm" vcpus = 2 memory = 2048 vif = [ 'bridge=nullbr0', 'type=ioemu, bridge=nullbr0' ] disk = ['file:/xen/opnsense/OPNsense-23.7-serial-amd64.img,hda,w', 'file:/xen/opnsense/opnsense.hdd,hdb,w'] #disk = ['file:/xen/opnsense/opnsense.hdd,hda,w'] serial = 'pty'

Then reverted to my original production config.

I would note that vgaconsole is entirely disabled on the serial installer, so configuring graphics and vnc/other GUI access is rendered moot.

Always remember to launch your serially-managed VMs with xenconsole by affixing the -c flag to your create command line - at least if you are managing or troubleshooting the VM - as this is the only way to view every line of output from bootstrap onward, unless you enable console logging to the dom0 - taking into consideration the potential security implications of storing every detail from every management session thereby conducted.

To enable logging of this interface, check out Enable xenconsoled Serial Logging.