Bug 1774746 - iscsi login fails during install with "buf[20] !sufficient to decode string[66]" since Fedora-Rawhide-20191119.n.2
Summary: iscsi login fails during install with "buf[20] !sufficient to decode string[6...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: iscsi-initiator-utils
Version: 32
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Chris Leech
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: openqa AcceptedBlocker AcceptedFreeze...
Depends On:
Blocks: BetaFreezeException, F32BetaFreezeException F32FinalBlocker, FinalBlocker
TreeView+ depends on / blocked
 
Reported: 2019-11-20 20:45 UTC by Adam Williamson
Modified: 2020-03-13 19:36 UTC (History)
6 users (show)

Fixed In Version: iscsi-initiator-utils-6.2.1.0-2.git4440e57.fc32
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-03-13 19:36:50 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Github open-iscsi open-iscsi issues 192 None closed iscsi login fails during Fedora install with "buf[20] !sufficient to decode string[66]" since 2.1.0 2020-03-19 13:17:07 UTC

Description Adam Williamson 2019-11-20 20:45:02 UTC
Since Fedora-Rawhide-20191119.n.2 landed, the openQA iscsi install test is failing. On the client end we see these messages:

20:56:16,457 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Running Thread: AnaTaskThread-ISCSILoginTask-1 (140310385428224)
20:56:16,464 INFO kernel:scsi host3: iSCSI Initiator over TCP/IP
20:56:16,473 INFO iscsid:iscsid: conn 0 login rejected: initiator error (02/00)
20:56:16,473 INFO kernel: connection1:0: detected conn error (1020)
20:56:16,476 INFO iscsid:iscsid: Connection1:0 to [target: iqn.2016-06.local.domain:support.target1, portal: 10.0.2.110,3260] through [iface: default] is shutdown.
20:56:16,479 WARNING org.fedoraproject.Anaconda.Modules.Storage:WARNING:blivet:iSCSI: could not log into iqn.2016-06.local.domain:support.target1: Failed to call Login method on /org/freedesktop/UDisks2/Manager with ('iqn.2016-06.local.domain:support.target1', 1, '10.0.2.110', 3260, 'default', {'username': <'test'>, 'password': <'weakpassword'>, 'node.startup': <'automatic'>}) arguments: GDBus.Error:org.freedesktop.UDisks2.Error.Failed: Login failed: initiator reported error (19 - encountered non-retryable iSCSI login failure)
20:56:16,479 WARNING org.fedoraproject.Anaconda.Modules.Storage:INFO:anaconda.threading:Thread Failed: AnaTaskThread-ISCSILoginTask-1 (140310385428224)
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:ERROR:anaconda.modules.common.task.task:Thread AnaTaskThread-ISCSILoginTask-1 has failed: Traceback (most recent call last):
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.8/site-packages/pyanaconda/threading.py", line 280, in run
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:    threading.Thread.run(self)
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.8/threading.py", line 870, in run
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._target(*self._args, **self._kwargs)
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/common/task/task.py", line 95, in _task_run_callback
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._set_result(self.run())
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/iscsi/discover.py", line 139, in run
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:    self._log_into_node(node_info, self._credentials)
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:  File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/iscsi/discover.py", line 178, in _log_into_node
20:56:16,482 WARNING org.fedoraproject.Anaconda.Modules.Storage:    raise StorageDiscoveryError(msg)

on the server end, we see this error at the same time:

Nov 19 12:56:16 support.domain.local tgtd[12010]: tgtd: chap_decode_string(279) buf[20] !sufficient to decode string[66]

This test last passed on the Fedora-Rawhide-20191115.n.0 compose. I've run it several times across openQA stg and prod, it repeatedly succeeded with Fedora-Rawhide-20191115.n.0 and fails with Fedora-Rawhide-20191119.n.2.

I do not believe the server end has changed at all here, it would be running iscsi-initiator-utils-6.2.0.876-10.gitf3c8e90.fc31 the same way in both cases. I also don't see that anaconda or blivet have changed their iscsi code in a way that would affect this between 20191115.n.0 and 20191119.n.2. So I'm assigning this to iscsi-initiator-utils, because we got a new build introducing a new major version which landed in the 20191119.n.2 compose:

https://koji.fedoraproject.org/koji/buildinfo?buildID=1413979

that seems like the obvious suspect here.

Proposing as a Final blocker per https://fedoraproject.org/wiki/Fedora_32_Final_Release_Criteria#network-attached-storage - "The installer must be able to detect (if possible) and install to supported network-attached storage devices."

Comment 1 Adam Williamson 2020-01-10 17:12:01 UTC
Ping? This is still broken, nearly two months later.

Comment 2 Adam Williamson 2020-02-06 21:49:41 UTC
Discussed at 2020-02-03 blocker review meeting: https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2020-02-03/f32-blocker-review.2020-02-03-17.13.html . Accepted as a Final blocker as a violation of "The installer must be able to detect (if possible) and install to supported network-attached storage devices." - https://fedoraproject.org/wiki/Fedora_32_Final_Release_Criteria#Network_attached_storage .

Comment 3 Ben Cotton 2020-02-11 16:40:15 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 32 development cycle.
Changing version to 32.

Comment 4 Adam Williamson 2020-03-03 02:58:12 UTC
Upstream suggested that https://github.com/open-iscsi/open-iscsi/commit/d3daa7a2bc3f5bca874d3efd072b34a657c4d492 should fix this. I'm running a Rawhide build with that patch backported at present. I'll see if that fixes the bug in Rawhide; if so, I'll do the same backport for F32.

Comment 5 Adam Williamson 2020-03-04 16:28:48 UTC
OK, so I did the backport, then Chris subsequently sent the whole of 2.1.1 to Rawhide. openQA testing indicates that the test now passes both with the backport build (which was in 20200303.n.0) and the 2.1.1 build (which was in 20200304.n.0).

As we're in Beta freeze, I'm going to send an update for F32 with just the backport - policy during freezes is that updates should include as little change as possible while still fixing the issue. Chris, we could do 2.1.1 for F32 after the Beta release, if you think it's a good idea. If you think any other fixes in 2.1.1 are important enough that they should make Beta, please let me know and we can figure it out. Thanks!

Comment 6 Fedora Update System 2020-03-04 16:42:10 UTC
FEDORA-2020-1ed3392208 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-1ed3392208

Comment 7 Fedora Update System 2020-03-04 20:15:34 UTC
iscsi-initiator-utils-6.2.1.0-2.git4440e57.fc32 has been pushed to the Fedora 32 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-1ed3392208

Comment 8 Adam Williamson 2020-03-06 20:42:04 UTC
Proposing as Beta FE - we're frozen for Beta, it would be good to fix iSCSI installs for it.

Comment 9 Adam Williamson 2020-03-10 00:59:18 UTC
Discussed during the 2020-03-09 freeze exception review meeting: [0]

Accepted as a freeze exception as a significant installer bug that cannot be fixed with an update.

[0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-03-09/f32-blocker-review.2020-03-09-16.01.txt

Comment 10 Fedora Update System 2020-03-13 19:36:50 UTC
iscsi-initiator-utils-6.2.1.0-2.git4440e57.fc32 has been pushed to the Fedora 32 stable repository. If problems still persist, please make note of it in this bug report.


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