Bug 2062505
| Summary: | Log loss occurred due to rsyslogd log rotation when writing to a pipe [rhel-7.9.z] | |||
|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Christian Horn <chorn> | |
| Component: | rsyslog | Assignee: | Attila Lakatos <alakatos> | |
| Status: | CLOSED ERRATA | QA Contact: | Dalibor Pospíšil <dapospis> | |
| Severity: | high | Docs Contact: | ||
| Priority: | urgent | |||
| Version: | 7.9 | CC: | alakatos, dapospis, kpfleming, lvrabec, mmatsuya, rsroka, sarroutb | |
| Target Milestone: | rc | Keywords: | Triaged, ZStream | |
| Target Release: | 7.9 | Flags: | pm-rhel:
mirror+
|
|
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | ||||
| 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.
|
Story Points: | --- | |
| Clone Of: | ||||
| : | 2089120 2089121 2089122 (view as bug list) | Environment: | ||
| Last Closed: | 2022-04-05 17:18:00 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | --- | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | --- | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 2089120, 2089121, 2089122 | |||
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? 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. 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]
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 |
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