Bug 1457359

Can you check the status of the iscsid and iscsiuio service and socket units?

# systemctl status iscsid.service iscsid.socket iscsiuio.service iscsiuio.socket

Are there any signs of SELinux issues?

# grep "denied" /var/log/audit/audit.log

(In reply to Chris Leech from comment #3)
# systemctl status iscsid.service iscsid.socket iscsiuio.service iscsiuio.socket
● iscsid.service - Open-iSCSI
   Loaded: loaded (/usr/lib/systemd/system/iscsid.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2017-06-01 05:05:33 EDT; 4min 59s ago
     Docs: man:iscsid(8)
           man:iscsiadm(8)
  Process: 3084 ExecStop=/sbin/iscsiadm -k 0 2 (code=exited, status=0/SUCCESS)
  Process: 3087 ExecStart=/usr/sbin/iscsid (code=exited, status=0/SUCCESS)
 Main PID: 3089 (iscsid)
   CGroup: /system.slice/iscsid.service
           ├─3088 /usr/sbin/iscsid
           └─3089 /usr/sbin/iscsid

Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com systemd[1]: Starting Op...
Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com iscsid[3087]: iSCSI log...
Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com systemd[1]: Started Ope...
Jun 01 05:05:34 storageqe-11.rhts.eng.bos.redhat.com iscsid[3088]: iSCSI dae...

● iscsid.socket - Open-iSCSI iscsid Socket
   Loaded: loaded (/usr/lib/systemd/system/iscsid.socket; enabled; vendor preset: disabled)
   Active: inactive (dead)
     Docs: man:iscsid(8)
           man:iscsiadm(8)
   Listen: @ISCSIADM_ABSTRACT_NAMESPACE (Stream)

● iscsiuio.service - iSCSI UserSpace I/O driver
   Loaded: loaded (/usr/lib/systemd/system/iscsiuio.service; disabled; vendor preset: disabled)
   Active: inactive (dead)
     Docs: man:iscsiuio(8)

● iscsiuio.socket - Open-iSCSI iscsiuio Socket
   Loaded: loaded (/usr/lib/systemd/system/iscsiuio.socket; enabled; vendor preset: disabled)
   Active: inactive (dead)
     Docs: man:iscsiuio(8)
   Listen: @ISCSID_UIP_ABSTRACT_NAMESPACE (Stream)
Hint: Some lines were ellipsized, use -l to show in full.

No SElinux issues, nothing on dmesg.

Looks like the cause might be somewhere in our test environment setup - just tried to do things manually and it worked well. I will try to find where did it gone wrong.

(In reply to Martin Hoyer from comment #4)
> (In reply to Chris Leech from comment #3)
> # systemctl status iscsid.service iscsid.socket iscsiuio.service
> iscsiuio.socket
> ● iscsid.service - Open-iSCSI
>    Loaded: loaded (/usr/lib/systemd/system/iscsid.service; disabled; vendor
> preset: disabled)
>    Active: active (running) since Thu 2017-06-01 05:05:33 EDT; 4min 59s ago
>      Docs: man:iscsid(8)
>            man:iscsiadm(8)
>   Process: 3084 ExecStop=/sbin/iscsiadm -k 0 2 (code=exited,
> status=0/SUCCESS)
>   Process: 3087 ExecStart=/usr/sbin/iscsid (code=exited, status=0/SUCCESS)
>  Main PID: 3089 (iscsid)
>    CGroup: /system.slice/iscsid.service
>            ├─3088 /usr/sbin/iscsid
>            └─3089 /usr/sbin/iscsid
> 
> Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com systemd[1]: Starting
> Op...
> Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com iscsid[3087]: iSCSI
> log...
> Jun 01 05:05:33 storageqe-11.rhts.eng.bos.redhat.com systemd[1]: Started
> Ope...
> Jun 01 05:05:34 storageqe-11.rhts.eng.bos.redhat.com iscsid[3088]: iSCSI
> dae...
> 
> ● iscsid.socket - Open-iSCSI iscsid Socket
>    Loaded: loaded (/usr/lib/systemd/system/iscsid.socket; enabled; vendor
> preset: disabled)
>    Active: inactive (dead)
>      Docs: man:iscsid(8)
>            man:iscsiadm(8)
>    Listen: @ISCSIADM_ABSTRACT_NAMESPACE (Stream)
> 
> ● iscsiuio.service - iSCSI UserSpace I/O driver
>    Loaded: loaded (/usr/lib/systemd/system/iscsiuio.service; disabled;
> vendor preset: disabled)
>    Active: inactive (dead)
>      Docs: man:iscsiuio(8)
> 
> ● iscsiuio.socket - Open-iSCSI iscsiuio Socket
>    Loaded: loaded (/usr/lib/systemd/system/iscsiuio.socket; enabled; vendor
> preset: disabled)
>    Active: inactive (dead)
>      Docs: man:iscsiuio(8)
>    Listen: @ISCSID_UIP_ABSTRACT_NAMESPACE (Stream)
> Hint: Some lines were ellipsized, use -l to show in full.
> 
> No SElinux issues, nothing on dmesg.
> 
> Looks like the cause might be somewhere in our test environment setup - just
> tried to do things manually and it worked well. I will try to find where did
> it gone wrong.

OK, I can possibly see how this happened.  The socket units are enabled but inactive, so I'm guessing that the rpm was installed but the system was not restarted.  Then iscsiadm can use the iscsid.startup setting in iscsid.conf if it fails to connect to iscsid, which we use in el7 to ensure the socket activation units are active.  But if there was no restart, and the iscsid.service was started directly, then the socket activation units don't get started and nothing will start iscsiuio.

We might be able to improve this, but I don't think there's a regression.

Chris, thanks for the update. I played did some testing today:

- running any of our tests via beaker fails with this problem | works well with RHEL-7.3
- running it manually in exactly the same environment pass without this issue

I've failed to see the difference between beaker run and manual run.

Restarting iscsiuio service resolves this issue. 
Chris, do You want to keep this bz open? I still wonder why we don't see this on RHEL-7.3 though.

(In reply to Martin Hoyer from comment #7)
> Restarting iscsiuio service resolves this issue. 
> Chris, do You want to keep this bz open? I still wonder why we don't see
> this on RHEL-7.3 though.

I think the test scripts are doing somthing like 'systemctl restart iscsid' or 'service iscsid restart'?

There seems to be a timing difference as the next iscsiadm command races against the iscsid restart, and if it's running in time to accept the socket connect but the iscsiuio socket activation unit isn't running this can happen.

The RPM enables the socket activation units by default, but I didn't want to start anything.  But then iscsiadm will try and tell systemd to start the socket activation units if it can't connect to iscsid.  

So in practice there's not much difference and having systemd start the socket activation doesn't start new processes, so I think just starting socket activations on RPM install would fix this.  Seems to in my testing with a spec file change.

(In reply to Chris Leech from comment #8)
> I think the test scripts are doing somthing like 'systemctl restart iscsid'
> or 'service iscsid restart'?
Indeed, they are running 'systemctl restart iscsid', followed by some non-iscsi related checks. Than, after ~90s another test is updating iface information and restarting the service again. After this the discovery fails.

Seems like, once this happens, only way to fix it is restart iscsiuio service or stop iscsid and try to do discovery again.

Tested with iscsi-initiator-utils-6.2.0.874-6 and -7
The issue is no longer present. No regression found.

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-2018:0993