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?

In T189290#4053740, @ema wrote:

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

In T189290#4053740, @ema wrote:

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"

@Vgutierrez: Is https://gerrit.wikimedia.org/r/c/operations/debs/pybal/+/418866 still wanted? What exactly (task, person?) is this task stalled on? Thanks!

The swap of Traffic for Traffic-Icebox in this ticket's set of tags was based on a bulk action for all such tickets that haven't been updated in 6 months or more. This does not imply any human judgement about the validity or importance of the task, and is simply the first step in a larger task cleanup effort. Further manual triage and/or requests for updates will happen this month for all such tickets. For more detail, have a look at the extended explanation on the main page of Traffic-Icebox . Thank you!