iscsid fails to log out from target on shutdown

Hello Michael and thanks for this bug report. I don't have a system I can reproduce the issue on at the moment, but your analysis looks correct to me. Integrating your open-iscsi-sanbootable.finalrd into the open-iscsi.finalrd hook shipped with the open-iscsi Ubuntu package should do the trick.

The open-iscsi.finalrd hook is an Ubuntu-specific thing, so there is no doubt the fix belongs to Ubuntu.

Here I think we need to:
 - Prepare a open-iscsi package with an updated open-iscsi.finalrd
 - Verify that is works and causes no regressions (ideally with your help)

Cc: xnox, maintainer of the finalrd and original author of the open-iscsi.finalrd hook, just in case se has thoughts on this issue or on the inclusion of libnss in the finalrd.

Thanks. I can easily retest whenever an updated open-iscsi .deb is available to download - just let me know.

The package has some tests that are meant to do iscsi root but can't be executed fully automated.
With those one can try iscsi-root rather easy (not really easy, but better than from scratch).

$ pull-lp-source open-iscsi
$ cd open-iscsi-2.1.3/
$ PATH=$PWD/debian/tests:$PATH
$ get-image hirsute.d hirsute
$ sudo ./debian/tests/patch-image --kernel=hirsute.d/kernel --initrd=hirsute.d/initrd hirsute.d/disk.img
$ tgt-boot-test -v hirsute.d/disk.img hirsute.d/kernel hirsute.d/initrd
# At this point this boots off the iscsi root and one can log in with ubuntu/passw0rd

This is using overlayroot like:
sda 8:0 0 2.2G 1 disk
├─sda1 8:1 0 2.1G 1 part /media/root-ro
├─sda14 8:14 0 4M 1 part
└─sda15 8:15 0 106M 1 part

Mounted like:
/dev/sda1 on /media/root-ro type ext4 (ro,relatime)
tmpfs-root on /media/root-rw type tmpfs (rw,relatime,inode64)
overlayroot on / type overlay (rw,relatime,lowerdir=/media/root-ro,upperdir=/media/root-rw/overlay,workdir=/media/root-rw/overlay-workdir/_)

$ sudo iscsiadm -m session -P 1
Target: tgt-boot-test-SKWNjP (non-flash)
 Current Portal: 10.0.12.2:3260,1
 Persistent Portal: 10.0.12.2:3260,1
  **********
  Interface:
  **********
  Iface Name: default
  Iface Transport: tcp
  Iface Initiatorname: maas-enlist
  Iface IPaddress: 10.0.12.15
  Iface HWaddress: default
  Iface Netdev: default
  SID: 1
  iSCSI Connection State: LOGGED IN
  iSCSI Session State: LOGGED_IN
  Internal iscsid Session State: NO CHANGE

This is a transient setup, but it should run the same hooks shouldn't it?
In any case it does not have the same hang, the guest shuts down even it failing.
To be fair the finalrd has issues, but not a full hang.

...
[ OK ] Reached target Power-Off.
Unexpected iSCSI Connection State, forcing iSCSI logout.
Logging out of session [sid: 1, target: tgt-boot-test-reTuhW, portal: 10.0.12.2,3260]
[ 250.977777] sd-execu[1727]: /usr/lib/systemd/system-shutdown/open-iscsi.finalrd failed with exit status 141.
[ 251.000668] reboot: Power down
xkvm returned 0 in 252s
cleaning up tgt mount tgt-boot-test-reTuhW

@Michael - do you think we need a R/W iSCSI root to experience the full hang that you reported?
@Michael - I tested Hirsute (21.04), which version did you run on (maybe it differs between them)?

On 13/04/2021 15:05, Christian Ehrhardt  wrote:
> This is a transient setup, but it should run the same hooks shouldn't it?
> In any case it does not have the same hang, the guest shuts down even it failing.
> To be fair the finalrd has issues, but not a full hang.
>
> ...
> [ OK ] Reached target Power-Off.
> Unexpected iSCSI Connection State, forcing iSCSI logout.
> Logging out of session [sid: 1, target: tgt-boot-test-reTuhW, portal: 10.0.12.2,3260]
> [ 250.977777] sd-execu[1727]: /usr/lib/systemd/system-shutdown/open-iscsi.finalrd failed with exit status 141.

It looks as though you happen to be hitting an error condition, and the
error handler (in iscsid?) happens to attempt to clear the error by
logging out from the target, which entirely coincidentally happens to be
the desired action from the finalrd script. But this is happening by
coincidence rather than by design.

On a "real" iSCSI-booted system, I do see the 30 second delay.

I was testing 20.04.

Thanks,

Michael

Thanks for the answers Michael!

With Focal in my test environment I still see
Unexpected iSCSI Connection State, forcing iSCSI logout.
Logging out of session [sid: 1, target: tgt-boot-test-CgkE2Y, portal: 10.0.12.2,3260]
[ 1291.109263] sd-execu[1616]: /usr/lib/systemd/system-shutdown/open-iscsi.finalrd failed with exit status 141.
[ 1291.114839] reboot: System halted
=> But TBH, that also is at a ~25s delay :-

So I might need a different setup to test this myself.

I looked at the changes more in detail:

#1
NSS while not directly linked (and thereby missed by:
  copy_exec /sbin/iscsid
Can be needed by nsswitch.conf used by getpwuid of glibc and
the default being "files" which then needs this lib eventually.

#2
And a fake trivial passwd, I can't see how that hurts and it if fixes the issue that you are seeing - why not adding that.

I've thrown preliminary builds for Hirsute and Focal adopting your changes into a PPA [1] and would appreciate if you could test if they indeed work out as you expect.

[1]: https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4527/+packages

Confirmed (on focal) that the open-iscsi PPA fixes the issue as expected.

The final console messages on a "real" iSCSI-booted VM are now:

[ OK ] Reached target Final Step.
[ OK ] Finished Power-Off.
[ OK ] Reached target Power-Off.
Logging out of session [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:risso, portal: 10.0.0.6,3260]
Logout of [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:risso, portal: 10.0.0.6,3260] successful.
[ 24.782589] reboot: Power down

i.e. no "failed with exit status 141" errors.

Thanks for fixing so quickly!

Reviewed as well, uploaded for Hirsute.
Once it completes there we can go for the SRUs.

This bug was fixed in the package open-iscsi - 2.1.3-1ubuntu6

---------------
open-iscsi (2.1.3-1ubuntu6) hirsute; urgency=medium

  * d/open-iscsi.finalrd: fix UID resolution issues in logout (LP: #1922976)
    Thanks to Michael Brown

 -- Christian Ehrhardt <email address hidden> Thu, 18 Mar 2021 09:44:07 +0100

Hirsute done, sponsored as SRUs for Focal and Hirsute for review by the SRU Team

Hello Michael, or anyone else affected,

Accepted open-iscsi into groovy-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/open-iscsi/2.1.1-1ubuntu2.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-groovy to verification-done-groovy. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-groovy. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Hello Michael, or anyone else affected,

Accepted open-iscsi into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/open-iscsi/2.0.874-7.1ubuntu6.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

I've checked my cases and they were not regressing. That is good, but as we've found before they are not authoritative for the issue we want to fix here.

@Michael - would you be able to do the real verification for Focal and Groovy with your setup please?

Confirmed that 2.0.874-7.1ubuntu6.2 works on Focal: shutdown occurs cleanly as

[ OK ] Reached target Power-Off.
Logging out of session [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:risso, portal: 10.0.0.6,3260]
Logout of [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:risso, portal: 10.0.0.6,3260] successful.
[ 29.161023] reboot: Power down

Confirmed that 2.1.1-1ubuntu2.1 works on Groovy: shutdown occurs cleanly as

[ OK ] Reached target Power-Off.
Logging out of session [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:thing, portal: 10.0.0.6,3260]
Logout of [sid: 1, target: iqn.2010-04.org.ipxe.dolphin:thing, portal: 10.0.0.6,3260] successful.
[ 29.405754] reboot: Power down

Thank you Michael !

This bug was fixed in the package open-iscsi - 2.1.1-1ubuntu2.1

---------------
open-iscsi (2.1.1-1ubuntu2.1) groovy; urgency=medium

  * d/open-iscsi.finalrd: fix UID resolution issues in logout (LP: #1922976)
    Thanks to Michael Brown

 -- Christian Ehrhardt <email address hidden> Thu, 18 Mar 2021 09:44:07 +0100

The verification of the Stable Release Update for open-iscsi has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

This bug was fixed in the package open-iscsi - 2.0.874-7.1ubuntu6.2

---------------
open-iscsi (2.0.874-7.1ubuntu6.2) focal; urgency=medium

  * d/open-iscsi.finalrd: fix UID resolution issues in logout (LP: #1922976)
    Thanks to Michael Brown

 -- Christian Ehrhardt <email address hidden> Thu, 18 Mar 2021 09:44:07 +0100