SysLogHandler missing logs

Question

I am setupping a SysLogHandler.

I am using the following script:

#!/usr/bin/env python

import logging
from logging.handlers import SysLogHandler

handler_syslog = SysLogHandler(
    address="/dev/log",
    facility=SysLogHandler.LOG_DAEMON,
)

fmt0 = logging.Formatter(fmt="%(module)s: %(asctime)s - %(levelname)s - %(message).1000s")
handler_syslog.setFormatter(fmt0)

my_logger = logging.getLogger()
my_logger.setLevel(logging.DEBUG)
my_logger.addHandler(handler_syslog)

i = 0
while True:
    import time
    X = 0.0001
    time.sleep(X)
    logging.info(i)
    i += 1

I check the logs being written here:

tail -f /var/log/daemon.log

And it gives:

Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,527 - INFO - 993
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,528 - INFO - 994
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,528 - INFO - 995
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,528 - INFO - 996
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,529 - INFO - 997
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,529 - INFO - 998
Apr  1 20:10:41 fr-machine-01 syslogtest[28894]: 2022-04-01 20:10:41,529 - INFO - 999

Several things I noticed:

1. After the first lines, nothing is displayed. 999 is the last number I get. It is not a coincidence that it stops after 1000 lines, but I have no explanation as to why.

2. I tried setting time.sleep(X) with different X values and for greater X than 0.0001 (like X=1, X=0.01..), I get all the logs.

3. Between tests, I sometimes get a:

   Apr  1 20:10:01 fr-machine-01 systemd-journald[461]: Suppressed 27344 messages from session-1492208.scope
   

All in all, I suppose I am reaching a rate-limit. But I did not find any information about it online. Moreover, this is an example test, but the real app running that made me notice the bug is a much slower logger (with about 1000 logs / minute).

Anyone knows how I can proceed to get all the logs into that file using a SysLogHandler?

Answer 1

I found the solution outside Python.

The problem was indeed due to a rate limit. systemd-journald has 2 parameters that regulate the number of logs being handled. Inside /etc/systemd/journald.conf:

RateLimitIntervalSec=30s
RateLimitBurst=1000

This allows only 1000 logs to be processed every 30 seconds period. If too many of them are received, the further messages will be dropped until the window of 30 seconds is over.

To reduce the number of logs being ditched, upgrade the RateLimitBurst or set both to 0. Note that setting them both to 0 is not recommended since the rate limit exists to avoid having a rogue program logging too much and monopolizing resources on a machine (or even break it).

Once updated, run:

sudo systemctl restart systemd-journald

I found this and this resources useful.