Bug 1414819
| Summary: | iscsid reporting blank emerg message | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | John Pittman <jpittman> | ||||||
| Component: | iscsi-initiator-utils | Assignee: | Chris Leech <cleech> | ||||||
| Status: | CLOSED ERRATA | QA Contact: | Martin Hoyer <mhoyer> | ||||||
| Severity: | low | Docs Contact: | |||||||
| Priority: | unspecified | ||||||||
| Version: | 7.1 | CC: | agrover, djeffery | ||||||
| Target Milestone: | rc | Keywords: | Patch | ||||||
| Target Release: | --- | ||||||||
| Hardware: | x86_64 | ||||||||
| OS: | Linux | ||||||||
| Whiteboard: | |||||||||
| Fixed In Version: | iscsi-initiator-utils-6.2.0.874-1.el7 | Doc Type: | If docs needed, set a value | ||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2017-08-01 16:54:21 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: | 1422628 | ||||||||
| Attachments: |
|
||||||||
The blank emergency message appears to be do to a bug in log_enqueue() from usr/log.c . The iscsid logging code in usr/log.c uses a share memory area like a modified circular buffer. Unlike a simple circular buffer, the tail pointer points to the beginning of the last message, not the end. And messages are not split when wrapping to the beginning of the circular buffer area. If a message is too big to fit at the end, the whole thing is placed at the beginning and a blank area which should be skipped is left at the end of the buffer area. But if the buffer is empty with the head pointer (and tail pointer) near the end of the buffer, inserting a message too big to fit in the end of the memory area will cause a extra blank entry to be created. Since the blank entry will normally be all-zeros in memory, this will get treated like a emergency priority (priority 0) message with an empty message string. The problem is how log_enqueue does not move the head pointer in this case with a previously empty buffer. The tail pointer is moved to the beginning of the buffer area and the log entry put in the beginning of the buffer area. But since the head pointer wasn't moved to match, log_dequeue interprets the state as there being 2 messages: 1 message where the head pointer is pointing to, then the other message where the tail is pointing to. The unintended entry at the head pointer then creates the blank emergency message when it is pushed to syslog. Created attachment 1242519 [details]
unit test creating the issue in the log.c code
I've attached a tarball with code which can recreate the unintended entry. It contains an unmodified copy of log.c from the iscsi code, wraps it, and then makes calls which will put the logging code in the bad state. It will report an error when it dequeues the bad entry which has a prio of 0.
Created attachment 1242525 [details]
Patch: reset head pointer when moving the tail pointer for an empty buffer
The attached patch should fix the issue. If setting the tail pointer to the start of the buffer from there not being enough space, the head pointer and lastmsg varable should also be set to the start of the buffer if the buffer was empty. This avoid the head pointer being left pointing to an empty, invalid entry and avoids a stale lastmsg being scribbled to which could potentially be beyond the end of the buffer area.
No regression found with iscsi-initiator-utils-6.2.0.874-2.el7 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, 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-2017:2010 |
Description of problem: In the customer's environment, iscsid is reporting a single blank emerg line at connection failure. /var/log/messages: Dec 15 18:47:29 hostname kern.info: kernel: connection50:0: detected conn error (1011) Dec 15 18:47:29 hostname daemon.emerg: iscsid: ^^^^^^^^^^^^^^^^^ emerg level and blank message Dec 15 18:47:29 hostname daemon.warning: iscsid: Kernel reported iSCSI connection 86:0 error (1011 - ISCSI_ERR_CONN_FAILED: iSCSI connection failed) state (3) journalctl --all --this-boot --no-pager -o verbose: Thu 2016-12-15 18:47:29.942853 JST <omitted> _TRANSPORT=syslog _CAP_EFFECTIVE=1fffffffff _SYSTEMD_SLICE=system.slice _BOOT_ID=<omitted> _MACHINE_ID=<omitted> _HOSTNAME=<omitted> SYSLOG_FACILITY=3 _UID=0 _GID=0 SYSLOG_IDENTIFIER=iscsid _PID=3445 _COMM=iscsid _EXE=/usr/sbin/iscsid _CMDLINE=/usr/sbin/iscsid _SYSTEMD_CGROUP=/system.slice/iscsid.service _SYSTEMD_UNIT=iscsid.service PRIORITY=0 MESSAGE= _SOURCE_REALTIME_TIMESTAMP=1481795249942853 As a note, the custom rsyslog.conf being used can be found at https://paste.fedoraproject.org/530840/. We assumed that this was not the cause of the issue as the message was found in journalctl as well. Additionally I am unable to reproduce with the custom .conf. Version-Release number of selected component (if applicable): iscsi-initiator-utils-6.2.0.873-32.el7.x86_64 kernel-3.10.0-229.20.1.el7.x86_64 libiscsi-1.9.0-6.el7.x86_64 How reproducible: Only reproducible in customer environment. Have not been able to reproduce this locally. Actual results: Single blank emerg message Expected results: No blank message