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

logger sending process start time not current time with log messages

    • Icon: Bug Bug
    • Resolution: Done-Errata
    • Icon: Normal Normal
    • rhel-9.4
    • CentOS Stream 9, rhel-9.3.0
    • util-linux
    • None
    • util-linux-2.37.4-16.el9
    • None
    • Low
    • rhel-sst-cs-plumbers
    • ssg_core_services
    • 26
    • 1
    • QE ack, Dev ack
    • False
    • Hide

      None

      Show
      None
    • No
    • Red Hat Enterprise Linux
    • None
    • All
    • None

      What were you trying to do that didn't work?

       

      CentOS Stream 9 does not carry this patch which was introduced upstream, and thus is subject to the reported issue, where sometimes `logger` will report the process start time instead of the current time in log messages.

      https://github.com/util-linux/util-linux/issues/1866

      Please provide the package NVR for which bug is seen:

      util-linux-2.37.4-15.el9

      How reproducible:

      Sometimes - depends on system load

      Steps to reproduce

      1. dnf -y install strace util-linux
      2. (sleep 5;date;date) | strace -e read,sendmsg logger

      Expected results

      read(0, "Wed Jan 10 05:38:26 PM UTC 2024\n", 4096) = 32
      sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="<13>Jan 10 17:38:26 root: ", iov_len=26}, {iov_base="Wed Jan 10 05:38:26 PM UTC 2024", iov_len=31}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 57
      read(0, "Wed Jan 10 05:38:26 PM UTC 2024\n", 4096) = 32
      sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="<13>Jan 10 17:38:26 root: ", iov_len=26}, {iov_base="Wed Jan 10 05:38:26 PM UTC 2024", iov_len=31}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 57

      Actual results

       

      read(0, "Wed Jan 10 05:38:26 PM UTC 2024\n", 4096) = 32
      sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="<13>Jan 10 17:38:21 root: ", iov_len=26}, {iov_base="Wed Jan 10 05:38:26 PM UTC 2024", iov_len=31}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 57
      read(0, "Wed Jan 10 05:38:26 PM UTC 2024\n", 4096) = 32
      sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="<13>Jan 10 17:38:26 root: ", iov_len=26}, {iov_base="Wed Jan 10 05:38:26 PM UTC 2024", iov_len=31}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 57

       

      Note in the examples above, the difference is hard to notice, but logger reports 17:38:21 (process start time) instead of 17:38:26, when the message was emitted.

       

              rhn-engineering-kzak Karel Zak
              neilhanlon Neil Hanlon
              Karel Zak Karel Zak
              Radka Brychtova Radka Brychtova
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated:
                Resolved: