Bug 1414819 - iscsid reporting blank emerg message
Summary: iscsid reporting blank emerg message
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: iscsi-initiator-utils
Version: 7.1
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: rc
: ---
Assignee: Chris Leech
QA Contact: Martin Hoyer
URL:
Whiteboard:
Depends On:
Blocks: 1422628
TreeView+ depends on / blocked
 
Reported: 2017-01-19 14:47 UTC by John Pittman
Modified: 2020-02-14 18:29 UTC (History)
2 users (show)

Fixed In Version: iscsi-initiator-utils-6.2.0.874-1.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-08-01 16:54:21 UTC
Target Upstream Version:


Attachments (Terms of Use)
unit test creating the issue in the log.c code (4.06 KB, application/x-xz)
2017-01-19 15:58 UTC, David Jeffery
no flags Details
Patch: reset head pointer when moving the tail pointer for an empty buffer (420 bytes, patch)
2017-01-19 16:13 UTC, David Jeffery
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2017:2010 0 normal SHIPPED_LIVE iscsi-initiator-utils bug fix and enhancement update 2017-08-01 17:58:56 UTC

Description John Pittman 2017-01-19 14:47:46 UTC
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

Comment 3 David Jeffery 2017-01-19 15:54:31 UTC
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.

Comment 4 David Jeffery 2017-01-19 15:58:07 UTC
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.

Comment 5 David Jeffery 2017-01-19 16:13:55 UTC
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.

Comment 8 Martin Hoyer 2017-04-28 08:57:47 UTC
No regression found with iscsi-initiator-utils-6.2.0.874-2.el7

Comment 9 errata-xmlrpc 2017-08-01 16:54:21 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, 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


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