Page MenuHomePhabricator

Tune systemd journal rate limiting for PyBal
Open, Stalled, MediumPublic

Description

As seen in T188085, some pybal messages are being omitted on the systemd journal on certain conditions. For example:

$ sudo journalctl -u pybal --since=yesterday | grep bgp                                                                                                       
Feb 22 09:04:17 lvs1006 pybal[15389]: [bgp] INFO: State is now: IDLE                                                                                          
Feb 22 09:06:28 lvs1006 pybal[24481]: [bgp] INFO: State is now: IDLE                                                                                          
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: (Re)connect to 208.80.154.197                                                                               
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: CONNECT                                                                                       
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: CONNECT                                                                                       
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: OPENSENT                                                                                      
Feb 22 09:13:12 lvs1006 pybal[26025]: [bgp] INFO: State is now: IDLE

VS

vgutierrez@lvs1006:~$ zgrep bgp /var/log/pybal.log.15.gz
Feb 22 09:06:28 lvs1006 pybal[24481]: [bgp] INFO: State is now: IDLE
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: (Re)connect to 208.80.154.197
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: CONNECT
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: CONNECT
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: OPENSENT
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: OPEN: version: 4 ASN: 14907 hold time: 30 id: 3494943429
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: Hold time: 30 Keepalive time: 10
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: OPENCONFIRM
Feb 22 09:06:30 lvs1006 pybal[26025]: [bgp] INFO: State is now: ESTABLISHED

As @MoritzMuehlenhoff pointed out, this behaviour can be related to systemd journal rate limiting. PyBal doesn't configure rate limiting at all and lvs1006 is running with the default values:

[Journal]
#Storage=auto
#Compress=yes
#Seal=yes
#SplitMode=uid
#SyncIntervalSec=5m
#RateLimitInterval=30s
#RateLimitBurst=1000

And from 09:06:28 to 09:06:32 (6 seconds) 854 messages were logged.

We need to set a proper rate limiting policy for pybal to avoid this kind of issue.

Event Timeline

Vgutierrez triaged this task as Medium priority.Mar 9 2018, 11:08 AM
Vgutierrez moved this task from Triage to LoadBalancer on the Traffic board.

pybal emits 854 messages during a restart in lvs1006. Also during a restart is when appears to log at its fastest rate, achieving almost 400 lines per second:

vgutierrez@lvs1006:~$ cut -f3 -d' '  pybal.log.15 |uniq -c |sort -n -r| head -10
    397 09:06:30
    393 09:13:16
    382 13:17:04
    326 09:04:21
    311 09:04:22
    223 09:06:31
    218 09:04:17
    170 13:17:05
    168 09:13:12
    168 09:06:28

so to be safe it looks like we should allow something around 500 messages per second

number of lines logged on a restart it's directly proportional to the number of services configured, lvs1010 appears to be the pybal instance with more services configured (59). Here the numbers are slightly higher:

vgutierrez@lvs1010:~$ cut -f3 -d' '  pybal.log.15 |uniq -c |sort -n -r| head -10
    531 09:01:39
    323 09:01:40
    237 09:01:38
     57 19:53:01
     57 19:36:13
     57 19:34:02
     57 19:31:51
     56 19:59:36
     56 19:50:51
     56 19:49:10

I'd suggest going for something around ~1k messages per second.

Change 418866 had a related patch set uploaded (by Vgutierrez; owner: Vgutierrez):
[operations/debs/pybal@master] Disable journald messages' rate limiting

https://gerrit.wikimedia.org/r/418866

It looks like journald messages' rate limiting is not configurable per unit. So it needs to be done system-wide.

Even worse, in Debian jessie journald configuration resides in /etc/systemd/journald.conf and packages don't have an easy way to influence the configuration while in strech modular configuration is supported through the following paths:

  • /etc/systemd/journald.conf.d/*.conf
  • /run/systemd/journald.conf.d/*.conf
  • /usr/lib/systemd/journald.conf.d/*.conf

I guess this is another reason to update LVS servers to strech (T177961)

The most surprising thing about journald's rate limiting, in the context of the issue that triggered this task, is that by looking at pybal logs we were not aware of the fact that at a certain point some entries were dropped. I've now noticed that indeed journald does log those events:

16:37:55 ema@lvs1006.wikimedia.org:~
$ sudo journalctl -u systemd-journald.service                                                                                                                 
-- Logs begin at Fri 2018-03-09 21:32:02 UTC, end at Thu 2018-03-15 16:38:03 UTC. --                                                                          
Mar 13 15:43:07 lvs1006 systemd-journal[252]: Suppressed 75 messages from /system.slice/pybal.service
Mar 15 13:18:38 lvs1006 systemd-journal[252]: Suppressed 189 messages from /system.slice/pybal.service

It would have been much more useful to get such messages into journalctl -u pybal.service's output instead, and I don't think we did get those. Perhaps file a bug against systemd?

It would have been much more useful to get such messages into journalctl -u pybal.service's output instead, and I don't think we did get those. Perhaps file a bug against systemd?

+1

yup... or at least a warning on systemctl status pybal similar to the one that you get when the journal has been rotated

Change 420299 had a related patch set uploaded (by Vgutierrez; owner: Vgutierrez):
[operations/debs/pybal@master] Make log look tidier on pybal start-up.

https://gerrit.wikimedia.org/r/420299

Change 420299 merged by Vgutierrez:
[operations/debs/pybal@master] Make log look tidier on pybal start-up

https://gerrit.wikimedia.org/r/420299

Vgutierrez changed the task status from Open to Stalled.Apr 16 2018, 8:42 AM

It would have been much more useful to get such messages into journalctl -u pybal.service's output instead, and I don't think we did get those. Perhaps file a bug against systemd?

I've tried reproducing the issue with the latest version of systemd (239) to no avail:

# /etc/systemd/system/logspammer.service
[Unit]
Description=Log Spammer

[Service]
ExecStart=/usr/bin/yes
$ sudo journalctl -u logspammer
[...]
Jul 10 10:39:01 ariel yes[3288]: y
Jul 10 10:39:31 ariel systemd-journald[439]: Suppressed 1044201 messages from logspammer.service
[...]

Nothing to report upstream then!

IMHO it would be great if those messages were in stderr instead of stdout otherwise you miss them when using journalctl + grep, that's why we missed them while debugging the "BGP issue"