zebra_apic threads not started after FRR service restart

[ToshikiRen]

Discussed in #16638

^{Originally posted by ToshikiRen August 23, 2024}
zebra_apic threads not started after FRR service restart (happens after multiple restarts, not all the time, the issue occurrence is mostly random)

The issue is that no routes are sent from routing daemons (e.g., BGP) to the kernel.

Questions:

1. From my understanding the zebra_apic are responsible for communication between the FRR daemons and the linux kernel. Is my assumption correct?
2. What could be the cause for the zebra_apic to not be started?

I managed to reproduce the issue on a box with the following configuration, without configuring BGP peers:

# default to using syslog. /etc/rsyslog.d/45-frr.conf places the log in
# /var/log/frr/frr.log
#
# Note:
# FRR's configuration shell, vtysh, dynamically edits the live, in-memory
# configuration while FRR is running. When instructed, vtysh will persist the
# live configuration to this file, overwriting its contents. If you want to
# avoid this, you can edit this file manually before starting FRR, or instruct
# vtysh to write configuration to a different file.
log syslog informational
!
debug zebra events
debug zebra packet recv
debug zebra kernel
debug zebra rib
debug zebra nht
debug zebra dplane
debug zebra nexthop
debug zebra neigh
debug bgp nht
debug bgp zebra

The error from the logs when the issue occurs during restart:

bgpd[335825]: [VMFZK-56S5Y] bgp_zebra_label_manager_connect: failed connecting synchronous zclient!

FRR version: 9.1
Show version output:

FRRouting 9.1 (come-as4581) on Linux(6.6.32-dent).
Copyright 1996-2005 Kunihiro Ishiguro, et al.
configured with:
    '--build=x86_64-linux' '--host=aarch64-dent-linux' '--target=aarch64-dent-linux' '--prefix=/usr' '--exec_prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--libexecdir=/usr/libexec' '--datadir=/usr/share' '--sysconfdir=/etc' '--sharedstatedir=/com' '--localstatedir=/var' '--libdir=/usr/lib' '--includedir=/usr/include' '--oldincludedir=/usr/include' '--infodir=/usr/share/info' '--mandir=/usr/share/man' '--disable-silent-rules' '--disable-dependency-tracking' '--with-libtool-sysroot=' '--sbindir=/usr/libexec/frr' '--sysconfdir=/etc/frr' '--localstatedir=/var/run/frr' '--enable-vtysh' '--enable-multipath=64' '--enable-user=frr' '--enable-group=frr' '--enable-vty-group=frrvty' '--enable-configfile-mask=0640' '--enable-logfile-mask=0640' '--disable-doc' '--with-clippy=/usr/lib/clippy' '--disable-capabilities' '--disable-cumulus' '--disable-datacenter' '--disable-fpm' '--disable-grpc' '--disable-ospfapi' '--disable-ospfclient' '--with-libpam' '--disable-protobuf' '--disable-snmp' '--disable-zeromq' 'build_alias=x86_64-linux' 'host_alias=aarch64-dent-linux' 'target_alias=aarch64-dent-linux' 'AR=aarch64-dent-linux-gcc-ar' 'LD=aarch64-dent-linux-ld --sysroot= ' 'OBJCOPY=aarch64-dent-linux-objcopy' 'OBJDUMP=aarch64-dent-linux-objdump' 'RANLIB=aarch64-dent-linux-gcc-ranlib' 'STRIP=aarch64-dent-linux-strip' 'PKG_CONFIG_PATH=/usr/lib/pkgconfig:/usr/share/pkgconfig' 'PKG_CONFIG_LIBDIR=/usr/lib/pkgconfig' 'CC=aarch64-dent-linux-gcc -mbranch-protection=standard -fstack-protector-strong -O2 -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security -Werror=format-security --sysroot=' 'CPPFLAGS=' 'CPP=aarch64-dent-linux-gcc -E --sysroot= -mbranch-protection=standard -fstack-protector-strong -O2 -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security -Werror=format-security' 'CXX=aarch64-dent-linux-g++ -mbranch-protection=standard -fstack-protector-strong -O2 -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security -Werror=format-security --sysroot=' 'PYTHON=/usr/bin/python3-native/python3'

When the issue occurs the zebra zserv.api socket is owned by root instead of frr:

# ls -l /var/run/frr/zserv.api
srwx------ 1 root frr 0 Aug 28 06:20 /var/run/frr/zserv.api

Looking into the code it seems the only case for root to own this socket would be to use a TCP connection but it is not the case for our configuration.

I have seen this issue on the latest frr release (10.1) as well.

[ToshikiRen]

I have been using the following script to reproduce the issue. I have modified the original service file to permit faster restarts so we could see the issue faster, the issue appears with the default configuration as well, if anyone wants to reproduce it using the default configuration you can change the sleep to match the service configuration.

#!/bin/bash

while true; do
    zebra_count=$(ps -L -p $(pgrep zebra) | grep zebra_apic | wc -l)

    if [ "$zebra_count" -lt 1 ]; then
        echo "Number of zebra apic thread is less than 1. Exiting..."
        date
	pid=$(ps aux | grep "[j]ournalctl -fu frr" | awk '{print $2}')
	kill -9 $pid
	break
    else
	ps -L -p $(pgrep zebra)
    	    echo "Restarting FRR..."
        date
	pid=$(ps aux | grep "[j]ournalctl -fu frr" | awk '{print $2}')
	kill -9 $pid
	journalctl -fu frr > frr_log.issue &
	sudo systemctl restart frr
        sleep 11
    fi
done

[ton31337]

As I understand we should see failed connecting synchronous zclient in frr_log.issue, right? But I can't see it running your script.

[ToshikiRen]

If the threads are missing and the owner of the socket is root, then the issue occured. The missing failed connecting synchronous zclient might be related to the debug settings from frr that you have setup. In case that one is missing you can also look for the:

bgpd[9945]: [TBNSW-XXXBM] sendmsg_zebra_rnh: We have not connected yet, cannot send nexthops
bgpd[9945]: [HXW3G-K1M2A] sendmsg_zebra_rnh: sending cmd ZEBRA_NEXTHOP_REGISTER for 20.20.0.1/32 (vrf VRF default)
bgpd[9945]: [YTHK0-FSPPJ][EC 33554500] sendmsg_nexthop: zclient_send_message() failed

[ton31337]

Could you test this PR #16749?

[ToshikiRen]

I still see the issue where the zserv.api is owned by root instead of the frr user on PR #16749

[ToshikiRen]

I looked with a friend at the code and we think that the issue might be in zserv_start. If something goes wrong here the socket could be bound to user root, but it should not be the case since the socket is an unix socket, right?

~# netstat -an | grep zserv
unix  2      [ ACC ]     STREAM     LISTENING     230024   /var/run/frr/zserv.api

The above netstat -an output is from a device for which the issue occured. When it is working the output is the following:

~# netstat -an | grep zserv
unix  2      [ ACC ]     STREAM     LISTENING     337256   /var/run/frr/zserv.api
unix  3      [ ]         STREAM     CONNECTED     337320   /var/run/frr/zserv.api

[ton31337]

Could you show the whole /var/run/frr directory?

[ToshikiRen]

This is the entire content of the /run/frr from when the issue occurs:

total 16K
drwxr-xr-x  2 frr  frr    280 Sep  5 14:06 .
drwxr-xr-x 24 root root   920 Sep  5 08:38 ..
-rw-r--r--  1 frr  frr      7 Sep  5 14:06 mgmtd.pid
srwxrwx---  1 frr  frrvty   0 Sep  5 14:06 mgmtd.vty
srwx------  1 frr  frr      0 Sep  5 14:06 mgmtd_be.sock
srwx------  1 frr  frr      0 Sep  5 14:06 mgmtd_fe.sock
-rw-r--r--  1 frr  frr      7 Sep  5 14:06 staticd.pid
srwxrwx---  1 frr  frrvty   0 Sep  5 14:06 staticd.vty
-rw-r--r--  1 root root     7 Sep  5 14:06 watchfrr.pid
-rw-r-----  1 root root     0 Sep  5 14:06 watchfrr.started
srwxrwx---  1 root frrvty   0 Sep  5 14:06 watchfrr.vty
-rw-r--r--  1 frr  frr      7 Sep  5 14:06 zebra.pid
srwxrwx---  1 frr  frrvty   0 Sep  5 14:06 zebra.vty
srwx------  1 root frr      0 Sep  5 14:06 zserv.api

[ToshikiRen]

Can you reopen it since the issue persists?
P.S: Please let me know if there is anything else that I may provide in order to help

[KanjiMonster]

I'm also seeing the wrong permissions issue for zserv.api. This is currently theory-crafted, because I don't haven't reviewed the code yet to prove this is the case:

1. while trying to add debug code to log the UID/GID when stuff happens, I stumbled upon code says that that privs may be per thread, or per process. For per thread, you need to have the capabilities feature enabled (--enable-capabilities).
2. Our FRR has capabilities disabled, so privileges are raised per process, not per thread.
3. My theory: there is a race condition where the unix socket may get created while a different thread has raised privileges.

Currently testing that theory by running the restart script with FRR built with capabilities enabled.

@ToshikiRen do you have capabilities enabled in your package? If not, this might be the issue.

[KanjiMonster]

Actually I just saw the thread, and you do have them disabled.

[KanjiMonster]

The more I look at the code, the more I am convinced that for privs_per_process = true it does not ensure that the code run with privs = NULL is actually run without any privs.

AFAICT there is nothing preventing another process from raising the privs, or it being run while privs are raised in these cases, just that raising and lowering privs isn't done in parallel.

And it also fits the observed state, the socket was created as root instead of frr.

Script still running without failing in a loop.

[KanjiMonster]

Looking at 7bfe765, building without it is already highly discouraged in 10, so maybe libcap just should be mandatory, since it isn't just a performance penalty, but actually broken (at least in 9.1+).

Might be easier than trying to fix this.

[KanjiMonster]

@eqvinox since you authored that commit, what's your preference here? Trying to fix the per-process privileges code to ensure that zserv creates the unix socket in an unprivileged context (and make it even slower), or make libcap mandatory (and probably rip out the per-process code).

I checked the code, and AFAICT zebra's zserv is the only user with NULL privileges here. The code seems to have been that way since quite a while (I only checked 8.2). I did not check if there are differences preventing it on older versions (e.g. startup order/non-existent threading).