Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-30567

journalctl -f with MESSAGE_ID= before messages with that ID exist in the journal results in "buffered" output of future messages

Linking RHIVOS CVEs to...Migration: Automation ...SWIFT: POC ConversionSync from "Extern...XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Minor Minor
    • None
    • rhel-9.0.0
    • systemd
    • None
    • Low
    • rhel-systemd
    • ssg_core_services
    • 2
    • False
    • False
    • Hide

      None

      Show
      None
    • Yes
    • None
    • If docs needed, set a value
    • None
    • 57,005

      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"

              dtardon@redhat.com David Tardon
              jkyros@redhat.com John Kyros
              David Tardon David Tardon
              Frantisek Sumsal Frantisek Sumsal
              Mugdha Soni Mugdha Soni
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated: