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 1396651 - Failed to read PID from file /var/run/iscsid.pid: Invalid argument
Summary: Failed to read PID from file /var/run/iscsid.pid: Invalid argument
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: iscsi-initiator-utils
Version: 7.3
Hardware: All
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: Chris Leech
QA Contact: Filip Suba
URL:
Whiteboard:
Depends On:
Blocks: 1420851 1711360
TreeView+ depends on / blocked
 
Reported: 2016-11-18 20:31 UTC by John Pittman
Modified: 2023-09-07 18:48 UTC (History)
11 users (show)

Fixed In Version: iscsi-initiator-utils-6.2.0.874-15
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-03-31 20:03:52 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 2742841 0 None None None 2016-11-18 21:05:23 UTC
Red Hat Product Errata RHBA-2020:1124 0 None None None 2020-03-31 20:04:29 UTC

Description John Pittman 2016-11-18 20:31:18 UTC 
Description of problem:

At boot or at restart of iscsid service, systemd fails to load the pid from within the SERVICE_START case of service_sigchld_event.  Removing PIDFile from .service file does get around the error (fails on PID file %s not readable (yet?)), but per systemd.service documentation PIDFile should be used for forking service.

Log snip can be found at https://paste.fedoraproject.org/484515/
- you will see the RH_DEBUG lines just showing which function we come from

Version-Release number of selected component (if applicable):

kernel-3.10.0-514.el7.x86_64
iscsi-initiator-utils-6.2.0.873-35.el7.x86_64
systemd-219-30.el7.6.x86_64

How reproducible:

Install iscsi, enable, and reboot

Actual results:

Failed to read PID from file /var/run/iscsid.pid: Invalid argument

Expected results:
 
Other than not hitting the error every time, unclear at this point.  I can not say with confidence whether this is the fault of iscsid or systemd, so I will start it in systemd.  Please feel free to change the component.  Also, if there is further information needed, please let me know and I would be glad to gather it.
Comment 1 John Pittman 2016-11-18 20:43:17 UTC 
It was just noted that disabling selinux is a workaround for this.

selinux-policy-3.13.1-102.el7_3.4.noarch

log snip with selinux disabled:  https://paste.fedoraproject.org/484529/
Comment 2 Lukáš Nykrýn 2016-11-21 09:43:28 UTC 
Can you provide us the message from /var/log/audit/audit.log why selinux denied accessing that pid file?
Comment 3 John Pittman 2016-11-21 15:02:40 UTC 
There doesn't seem to be a denial, and in my tests today, disabling selinux did not work around the issue, we get the same message of failure.  Possibly changed the timing enough in my earlier attempts to get rid of the message.
Comment 6 Jan Synacek 2016-11-23 08:02:42 UTC 
It looks like the pid file is there, but no pid has been written in it when systemd tries to read it. Does this happen only once on boot? Or every time that you start/restart iscsid?
Comment 7 John Pittman 2016-11-23 20:40:41 UTC 
It happens every time.  I've been able to reproduce at boot, with 'systemctl restart iscsid' and 'systemctl stop iscsid ; systemctl start iscsid'.
Comment 8 Jan Synacek 2016-11-24 12:08:07 UTC 
I managed to reproduce this in my VM. Excerpt from the debug log (with my comments marked):

Nov 24 12:47:54 rhel7-virt systemd[1]: About to execute: /usr/sbin/iscsid
Nov 24 12:47:54 rhel7-virt systemd[1]: Forked /usr/sbin/iscsid as 1272
Nov 24 12:47:54 rhel7-virt systemd[1]: iscsid.service changed dead -> start
Nov 24 12:47:54 rhel7-virt systemd[1]: Starting Open-iSCSI...
Nov 24 12:47:54 rhel7-virt systemd[1272]: Executing: /usr/sbin/iscsid
Nov 24 12:47:54 rhel7-virt iscsid[1272]: iSCSI logger with pid=1276 started!
Nov 24 12:47:54 rhel7-virt iscsid[1276]: iSCSI daemon with pid=1277 started!
Nov 24 12:47:54 rhel7-virt systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=82 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd-logind[748]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=82 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=83 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd-logind[748]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=83 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd[1]: Received SIGCHLD from PID 1272 (iscsid).
Nov 24 12:47:54 rhel7-virt systemd[1]: Child 1272 (iscsid) died (code=exited, status=0/SUCCESS)
Nov 24 12:47:54 rhel7-virt systemd[1]: Child 1272 belongs to iscsid.service
Nov 24 12:47:54 rhel7-virt systemd[1]: iscsid.service: control process exited, code=exited status=0
Nov 24 12:47:54 rhel7-virt systemd[1]: iscsid.service got final SIGCHLD for state start

                                       ^^^^ systemd realizes that it got the final SIGCHLD, but the PID file hasn't been written yet (by iscsid).

Nov 24 12:47:54 rhel7-virt systemd[1]: Failed to read PID from file /var/run/iscsid.pid: Invalid argument
Nov 24 12:47:54 rhel7-virt systemd[1]: Setting watch for iscsid.service's PID file /var/run/iscsid.pid

                                       ^^^^ systemd starts watching for the soon-to-be PID file...

Nov 24 12:47:54 rhel7-virt systemd[1]: Trying to read iscsid.service's PID file /var/run/iscsid.pid in case it changed
Nov 24 12:47:54 rhel7-virt systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=95 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd-logind[748]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=95 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=96 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd-logind[748]: Got message type=signal sender=:1.0 destination=n/a object=/org/freedesktop/systemd1/unit/iscsid_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=96 reply_cookie=0 error=n/a
Nov 24 12:47:54 rhel7-virt systemd[1]: inotify event for iscsid.service

                                       ^^^^ ...and it appears...

Nov 24 12:47:54 rhel7-virt systemd[1]: Main PID loaded: 1277
Nov 24 12:47:54 rhel7-virt systemd[1]: Stopping watch for iscsid.service's PID file /var/run/iscsid.pid

                                       ^^^^ ...and it is read, everything works as expected

Nov 24 12:47:54 rhel7-virt systemd[1]: iscsid.service changed start -> running
Nov 24 12:47:54 rhel7-virt systemd[1]: Job iscsid.service/start finished, result=done
Nov 24 12:47:54 rhel7-virt systemd[1]: Started Open-iSCSI.
Nov 24 12:47:54 rhel7-virt systemd[1]: iscsid.socket changed listening -> running

From now on, the service runs without any problems. I don't think that there are any problems with systemd with regards to this bug. If anything should be fixed, it's the iscsid - it should write the file earlier.
Comment 9 Adam Hunt 2017-01-31 21:22:24 UTC 
Has any progress been made on this? If this is indeed a bug in iscsid, has anyone reported it upstream?
Comment 10 Alex Wang 2018-04-05 18:13:42 UTC 
It's been over a year since the last update, any progress on this?
Comment 14 Filip Suba 2019-12-06 11:46:46 UTC 
Verified with iscsi-initiator-utils-6.2.0.874-17.
Comment 16 errata-xmlrpc 2020-03-31 20:03:52 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-2020:1124
Note You need to log in before you can comment on or make changes to this bug.