RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2062505 - Log loss occurred due to rsyslogd log rotation when writing to a pipe [rhel-7.9.z]
Summary: Log loss occurred due to rsyslogd log rotation when writing to a pipe [rhel-7...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: rsyslog
Version: 7.9
Hardware: Unspecified
OS: Unspecified
urgent
high
Target Milestone: rc
: 7.9
Assignee: Attila Lakatos
QA Contact: Dalibor Pospíšil
URL:
Whiteboard:
Depends On:
Blocks: 2089120 2089121 2089122
TreeView+ depends on / blocked
 
Reported: 2022-03-10 01:19 UTC by Christian Horn
Modified: 2022-08-11 01:37 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: Log loss occurred due to log rotation while writing to a named pipe. Consequence: A race condition could occur where one or more messages logged via the ompipe module could be lost when a HUP signal was delivered to rsyslog. Fix: The race condition has been eliminated from the code by proper use of mutex locks and unlocks. Result: Log loss can not occur due to log rotation when writing to a named pipe.
Clone Of:
: 2089120 2089121 2089122 (view as bug list)
Environment:
Last Closed: 2022-04-05 17:18:00 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github rsyslog rsyslog pull 4279 0 None Merged ompipe bugfix: race during HUP 2022-03-10 08:27:22 UTC
Red Hat Issue Tracker RHELPLAN-115089 0 None None None 2022-03-10 01:33:37 UTC
Red Hat Issue Tracker SECENGSP-4403 0 None None None 2022-03-10 01:33:40 UTC
Red Hat Knowledge Base (Solution) 6746151 0 None None None 2022-03-10 01:28:04 UTC
Red Hat Product Errata RHBA-2022:1203 0 None None None 2022-04-05 17:18:03 UTC

Description Christian Horn 2022-03-10 01:19:14 UTC
Description of problem:
  Log loss occurred due to rsyslogd log rotation when writing to a pipe file on RHEL7.
  If log rotation occurs in rsyslogd while writing to a pipe file, the following is outputted:
  
    rsyslogd: write error on pipe /opt/fujitsu/ServerViewSuite/HWLog/path/syslog_fifo: Bad file descriptor
  
  When rsyslogd receives SIGHUP, rsyslogd closes the pipe and then reopens it.
  If rsyslogd writes to the pipe between the pipe closes and the pipe opens, 
  this issue occurs because there is no File Descriptor.
  
  The rsyslog-v8 did not perform mutual exclusion between the pipe 
  and SIGHUP processing threads, so when a conflict occurs, 
  this message is outputted and the log is lost.

Version-Release number of selected component (if applicable):
all rsyslog versions seem affected

How reproducible:
Sometimes

Step to Reproduce:

  Send SIGHUP to rsyslogd when rsyslogd is writing a pipe file.

Actual Results:

  Log is lost with an error message.

Expected Results:

  Log is not lost. There is no error message.


Additional info:
- One of our partners reported this issue, at least one AMC customer is affected.  
  RHEL7.4 and later seem affected, so this is a regression from
  the earlier rhel7 releases.
- Following commit is suspected to have introduced the issue,
  the lock between worker threads has been removed to improve performance:
  
    https://github.com/rsyslog/rsyslog/commit/5878ee24c7232d0f4f8655e7af6a1d456c07492f#diff-8812a601dc91036540f968b25f8042f76727172a6b5cc208c8db7dd0fbae5078
      - milestone: action mutex removed
        - This means actions may now be called concurrently and must make
          provisions themselves to handle multi-threading.
  
  However, since the mutual exclusion was taken not only between worker threads,
  but also in the main thread, the mutual exclusion between the main and worker
  threads was removed.
  As a result, this issue occurs from the rsyslog-v8 on.
- This seems to be the upstream fix:
  https://github.com/rsyslog/rsyslog/commit/5878ee24c7232d0f4f8655e7af6a1d456c07492f#diff-8812a601dc91036540f968b25f8042f76727172a6b5cc208c8db7dd0fbae5078

Comment 4 Christian Horn 2022-03-10 01:25:29 UTC
As first step, engineering, can you comment on if you see/reproduce this?
Can you think of a workaround?  We did so far not come up with one, if
one existed it could be used instead of having to request rhel7.9.z errata.
How complex do you think a fix would be?
Should we clone this bz to rhel8?

Comment 5 Christian Horn 2022-03-10 01:33:26 UTC
Seems like 
https://github.com/rsyslog/rsyslog/commit/5878ee24c7232d0f4f8655e7af6a1d456c07492f#diff-8812a601dc91036540f968b25f8042f76727172a6b5cc208c8db7dd0fbae5078
is fixed in rsyslog v8.2202.0 and later - that is quite recent, rsyslog
in rhel8 and rhel9 builds is older.

Comment 7 Christian Horn 2022-03-14 01:18:53 UTC
Our partner provided details regarding reproducer, they use gdb as follows:

  1. Create FIFO (Named Pipe) in/var/tmp
  # mkfifo /var/tmp/fifo


  2. Add `daemon.=debug |/var/tmp/fifo` to /etc/rsyslog.conf.
  # grep fifo /etc/rsyslog.conf
  daemon.=debug |/var/tmp/fifo


  3. Restart service
  # systemctl restart rsyslog


  4. Start gdb and set a breakpoint on writePipe
  # gdb -p $(pidof rsyslogd)
  ...
  (gdb) b writePipe
  Breakpoint 1 at 0x55df6bf4dd5a: file ompipe.c, line 181.
  (gdb) c
  Continuing.


  5. Log a message to the system log
  # logger -p 'daemon.debug' hoge


  6. Proceed to write()
  [Switching to Thread 0x7fd08ce5d700 (LWP 17026)]

  Breakpoint 1, doAction (pMsgData=0x7fd08ce5c9a0, pWrkrData=<optimized out>) at ompipe.c:335
  335             iRet = writePipe(ppString, pData);
  (gdb) s
  writePipe (pData=0x55df6e11d850, ppString=0x7fd08ce5c9a0) at ompipe.c:181
  181             if(pData->fd == -1) {
  (gdb) n
  189             iLenWritten = write(pData->fd, ppString[0], strlen((char*)ppString[0]));
  (gdb) list
  184                     if((iRetLocal != RS_RET_OK) || (pData->fd == -1))
  185                             ABORT_FINALIZE(RS_RET_SUSPENDED); /* whatever the failure was, we need to retry */
  186             }
  187
  188             /* create the message based on format specified */
  189             iLenWritten = write(pData->fd, ppString[0], strlen((char*)ppString[0]));
  190             if(iLenWritten < 0) {
  191                     const int e = errno;
  192                     /* If a named pipe is full, we suspend this action for a while */
  193                     if(e == EAGAIN)


  7. Send HUP to rsyslogd
  # pkill -HUP -x rsyslogd


  8. Exit gdb
  (gdb) detach
  Detaching from program: /usr/sbin/rsyslogd, process 17023
  [Inferior 1 (process 17023) detached]
  (gdb) q


  9. Message "Bad file descriptor" is output in /var/log/messages
  - Confirmed for RHEL7
    Mar  2 10:26:26 localhost rsyslogd: [origin software="rsyslogd" swVersion="8.24.0-55.el7" x-pid="17023" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
    Mar  2 10:26:26 localhost rsyslogd: write error on pipe /var/tmp/fifo: Bad file descriptor [v8.24.0-55.el7]

  - Confirmed for RHEL8
    Mar  2 16:09:35 mori rsyslogd[244983]: [origin software="rsyslogd" swVersion="8.1911.0-3.el8" x-pid="244983" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
    Mar  2 16:09:35 mori rsyslogd[244983]: write error on pipe /tmp/syslog_fifo: Bad file descriptor [v8.1911.0-3.el8]

Comment 33 errata-xmlrpc 2022-04-05 17:18:00 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (rsyslog bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:1203


Note You need to log in before you can comment on or make changes to this bug.