Getting systemd service logs faster from my service

Question

I'm having a systemd service defined as follows, that works fine:

[Unit]
Description=my service
After=network.target

[Service]
User=myuser
Group=mygroup
WorkingDirectory=/home/myuser/myapp
Environment="PATH=/home/myuser/myapp/.venv/bin"
ExecStart=/home/myuser/myapp/.venv/bin/python3 /home/myuser/myapp/run.py
Restart=on-failure

[Install]
WantedBy=multi-user.target

This is a Python web application based on Flask framework. Normally in the stdout of the application I can see incoming requests "live", I mean when I run the app like python run.py.

Now after starting the service I'd like to follow logs of the app and I do:

sudo journalctl -f -u my_app.service

and incoming logs are awfully slow - sometimes it takes minutes or more for them to appear in logs. Afterwards they all have proper timestamp though, so it's not like they're disappearing, they do, but after a long time.

What I've tried:

• to redirect systemd service output to files:

  StandardOutput=file:/var/log/my_app/output.log

  StandardError=file:/var/log/my_app/error.log

  with no luck - they save fine but with the same slow speed

• to try to dump journalctl logs to offline faster setting SyncIntervalSec from default 5m to 5s - didn't help either

Is there any way to pass those logs faster from my application to journald? I don't have troubles with other services like system authentication ones - I see records immediately. My journald.conf file has default parameters (except one above), my systemd is version 237 and I'm running Ubuntu 18.04.

Answer 1

The problem is actually with buffering from the Flask application and not with how systemd or journald are ingesting those logs.

This can be counter-intuitive, since as you mentioned, running python3 run.py directly on the command-line works and shows logs properly and also timestamps look correct on the logs.

The former happens because Unix/Linux will typically set up stdout to be unbuffered when connected to a terminal (since it's expecting interaction with an user), but buffered when connected to a file (in case of StandardOutput=file:...) or to a pipe (in case you're logging to the journal, which is the default.)

The latter is because the Python/Flask logger is adding timestamps, so even though it's buffering that output, when it finally issues it into the logs, all the timestamps are there.

Some applications will know this is typically an issue and will set up buffering on stdout appropriately when using it for logs, but this doesn't seem to be the case with this particular Python/Flask setup you are using.

On Python, it's fairly easy to globally change stdout to unbuffered mode, which you can do by:

1. Passing a -u flag to python3 in your command.
2. Setting PYTHONUNBUFFERED=1 in your environment (which you can do in the systemd service unit with an additional Environment=PYTHONUNBUFFERED=1 line.)

You confirmed this worked for your specific case, so that's great!

For non-Python applications suffering from similar issues, there are command-line tools such as unbuffer and stdbuf which can often solve this same problem.

Solutions are usually specific to the kind of application, which is somewhat unfortunate, but often googling or looking for other answers in Stack Exchange (once you know buffering is the issue) will usually lead you to an useful suggestion.