Will bird block on syslog() call?
Hi, We have observed some instability on BFD protocol, where upstream router and/or the server (Linux RedHat 7.3) declares the BFD session dead and as consequence upstream router stops forwarding traffic to the server (we utilize ECMP). Our current hypothesis is that Bird log messages (only BGP KEEPALIVE messages when there isn't any route change) via syslog glibc function, which connects to UNIX socket (/dev/log) and the sender (Bird daemon) may block when the receiver (rsyslogd) doesn't response fast enough or the buffer is full. On RedHat 7 servers there is a chain of daemons, which receive log messages via UNIX socket. systemd-journald.service listens on /dev/log UNIX SOCKET and forwards messages to /run/systemd/journal/syslog UNIX SOCKET where rsyslogd listens on. As far as I can see in the code and in the output of ps -eLl, Bird daemon is a single threaded process (please correct me if I am wrong), so it could be that a call to syslog blocks for X seconds when X is higher than the failure detection time. Can you confirm this hypothesis? Here is an sanitized config: log syslog { debug, trace, info, remote, warning, error, auth, fatal, bug }; /* Source configuration snippets Please make sure they are valid snippets for Bird */ include "/etc/bird.d/*.conf"; include "/etc/bird.d/4/*.conf"; router id 1.2.3.1; protocol device { scan time 10; } protocol static { disabled yes; } protocol direct direct1 { interface "lo"; debug all; export none; import where net ~ ANYCAST_NETWORKS; } protocol bfd BFD1 { debug { states, routes, filters, interfaces, events }; interface "north", "south" { min rx interval 400 ms; min tx interval 400 ms; idle tx interval 1000 ms; multiplier 3; }; } protocol bgp BGP1 { disabled no; description "Peer-BGP1"; neighbor 1.2.3.254 as 4; source address 1.2.3.1; bfd on; debug all; import none; export where match_route_north(); direct; hold time 10; startup hold time 240; connect retry time 120; keepalive time 3; start delay time 5; error wait time 60, 300; error forget time 300; disable after error off; next hop self; path metric 1; default bgp_med 0; default bgp_local_pref 0; local as 1; } protocol bgp BGP2 { disabled no; description "Peer-BGP2"; neighbor 1.2.4.254 as 7; source address 1.2.3.1; bfd on; debug all; import none; export where match_route_south(); direct; hold time 10; startup hold time 240; connect retry time 120; keepalive time 3; start delay time 5; error wait time 60, 300; error forget time 300; disable after error off; next hop self; path metric 1; default bgp_med 0; default bgp_local_pref 0; local as 1; } Cheers, Pavlos
On Fri, Feb 24, 2017 at 01:13:55PM +0100, Pavlos Parissis wrote:
Hi,
We have observed some instability on BFD protocol, where upstream router and/or the server (Linux RedHat 7.3) declares the BFD session dead and as consequence upstream router stops forwarding traffic to the server (we utilize ECMP).
Our current hypothesis is that Bird log messages (only BGP KEEPALIVE messages when there isn't any route change) via syslog glibc function, which connects to UNIX socket (/dev/log) and the sender (Bird daemon) may block when the receiver (rsyslogd) doesn't response fast enough or the buffer is full.
On RedHat 7 servers there is a chain of daemons, which receive log messages via UNIX socket.
systemd-journald.service listens on /dev/log UNIX SOCKET and forwards messages to /run/systemd/journal/syslog UNIX SOCKET where rsyslogd listens on.
As far as I can see in the code and in the output of ps -eLl, Bird daemon is a single threaded process (please correct me if I am wrong), so it could be that a call to syslog blocks for X seconds when X is higher than the failure detection time.
Hi BIRD is single-threaded with the exception of BFD, which runs in a separate thread. Generally, interaction of BFD thread with the rest of BIRD is designed in a way that BFD thread should not wait on the main thread. So generally, the main thread blocked on syslog() should not cause problems to the BFD thread. There are some exceptions, like when the BFD thread wants to log itself (there is shared mutex around logging subsystem), but that is usually not a problem, as BFD do not log anything during regular operation (unless packet logging is enabled). I would suggest to decrease min rx/tx interval to 100 ms (to see if that helps). And you could try 'watchdog warning' / 'debug latency' options (with appropriate values, like 500 ms) to track latency in the main thread to see if BFD problems are related to eventual latency problems in the main thread. -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
On 24/02/2017 04:12 μμ, Ondrej Zajicek wrote:
On Fri, Feb 24, 2017 at 01:13:55PM +0100, Pavlos Parissis wrote:
Hi,
We have observed some instability on BFD protocol, where upstream router and/or the server (Linux RedHat 7.3) declares the BFD session dead and as consequence upstream router stops forwarding traffic to the server (we utilize ECMP).
Our current hypothesis is that Bird log messages (only BGP KEEPALIVE messages when there isn't any route change) via syslog glibc function, which connects to UNIX socket (/dev/log) and the sender (Bird daemon) may block when the receiver (rsyslogd) doesn't response fast enough or the buffer is full.
On RedHat 7 servers there is a chain of daemons, which receive log messages via UNIX socket.
systemd-journald.service listens on /dev/log UNIX SOCKET and forwards messages to /run/systemd/journal/syslog UNIX SOCKET where rsyslogd listens on.
As far as I can see in the code and in the output of ps -eLl, Bird daemon is a single threaded process (please correct me if I am wrong), so it could be that a call to syslog blocks for X seconds when X is higher than the failure detection time.
Hi
BIRD is single-threaded with the exception of BFD, which runs in a separate thread. Generally, interaction of BFD thread with the rest of BIRD is designed in a way that BFD thread should not wait on the main thread. So generally, the main thread blocked on syslog() should not cause problems to the BFD thread. There are some exceptions, like when the BFD thread wants to log itself (there is shared mutex around logging subsystem), but that is usually not a problem, as BFD do not log anything during regular operation (unless packet logging is enabled).
I would suggest to decrease min rx/tx interval to 100 ms (to see if that helps).
If the hypothesis holds true, that is Bird blocks for 1.2secs, then sending BFD messages at higher rate wont help. Do you think so ? I could try the opposite, configure the upstream router to declare the BFD down only after hasn't seen a BFD message for a period of 5seconds.
And you could try 'watchdog warning' / 'debug latency' options (with appropriate values, like 500 ms) to track latency in the main thread to see if BFD problems are related to eventual latency problems in the main thread.
Unfortunately, I still run 1.4.5 version, which doesn't those options, thus I can't experiment with them. I guess this is yet another reason for upgrading to 1.6.3. Thanks a lot for your reply, it is very much appreciated. Cheers, Pavlos
On Fri, Feb 24, 2017 at 08:48:48PM +0100, Pavlos Parissis wrote:
On 24/02/2017 04:12 μμ, Ondrej Zajicek wrote:
I would suggest to decrease min rx/tx interval to 100 ms (to see if that helps).
If the hypothesis holds true, that is Bird blocks for 1.2secs, then sending BFD messages at higher rate wont help. Do you think so ?
I was imprecise here. I meant decrease of min rx/tx interval with appropriate increase of multiplier. It would not help if the hypothesis is true, but it may help if there are some other causes.
I could try the opposite, configure the upstream router to declare the BFD down only after hasn't seen a BFD message for a period of 5seconds.
Note that multiplier configured on each side is propagated to the other side where it is used to compute timeout for received BFD messages. So if you want the upstream router not to declare the BFD down too early, you would need to configure multiplier on the BIRD router, not on the upstream router. But in practice you would probably want to set both values, as possible blocking for several seconds could produce session failure in both directions (as the blocked router could process 'timeout' event even before it processes queued received BFD messages), -- Elen sila lumenn' omentielvo Ondrej 'Santiago' Zajicek (email: santiago@crfreenet.org) OpenPGP encrypted e-mails preferred (KeyID 0x11DEADC3, wwwkeys.pgp.net) "To err is human -- to blame it on a computer is even more so."
participants (2)
-
Ondrej Zajicek -
Pavlos Parissis