Issue
Description of problem:
We were using "journalctl -f" in the OpenShift MCO operator to watch for login events and we noticed that we don't get any (I suspect because we don't ever reach 50+ logins to a RHCOS box)
If you:
run "journalctl -f" with a MESSAGE_ID= AND
there are no matching log messages already in the journal at the time the command is run
Then:
once messages with that MESSAGE_ID do exist, you will not receive them until some number/amount/size of them accumulate
Version-Release number of selected component (if applicable):
systemd 239 (239-45.el8_4.2) on RHCOS
systemd 248 (v248.7-1.fc34) on FCOS
How reproducible:
Every time.
Steps to Reproduce:
1. Create a unit that logs filtered logs to a text file:
sudo cat << EOF > /etc/systemd/system/early_listen.service
[Unit]
Description=Hang journalctl before anyone logs in by filtering both unit and message id
Before=network-online.target
[Service]
User=root
ExecStart=/bin/sh -c "journalctl -b -f -o cat -u systemd-logind.service MESSAGE_ID=8d45620c1a4348dbb17410da57c60c66 | tee /tmp/journal_unit_messageid.txt"
[Install]
WantedBy=multi-user.target
EOF
2.) Enable that unit
systemctl enable early_listen
3.) Clear your journal:
sudo journalctl --flush
sudo journalctl --vacuum-time=1s
4.) Restart your server (may be able to get by without rebooting, I just always did)
sudo systemctl reboot
5.) When the server comes back up, login/ssh into the server
ssh core@192.168.122.16
6.) observe that /tmp/journal_unit_messageid.txt is still empty
cat /tmp/journal_unit_messageid.txt
7.) if you repeatedly login in a loop, after some number of logins (usually > 50) it will snap out of it and events start coming out immediately
Actual results:
Messages do not come out until some unseen/unknown threshold is met
Expected results:
Messages come out as they occur
Additional info:
It feels like buffering, and at first I thought it was standard output buffering and I was doing something wrong, but after testing I don't think so. I also ran it with "stdbuf" for good measure and it didn't help.
If MESSAGE_ID is omitted, journalctl works as expected and messages are returned immediately
Any "journalctl -f" process started after a login message is present in the journal does return (and continue to return) events immediately
It does not appear to be time based – the messages do not seem to come out after days or hours, the only time they start coming out again is when there seem to be "enough of them"