Bug 1624670

Summary:	iSCSI Login negotiation failed due to CHAP_N values do not match!
Product:	Red Hat Enterprise Linux 7	Reporter:	Xiubo Li <xiubli>
Component:	iscsi-initiator-utils	Assignee:	Chris Leech <cleech>
Status:	CLOSED ERRATA	QA Contact:	Filip Suba <fsuba>
Severity:	urgent	Docs Contact:
Priority:	high
Version:	7.5	CC:	bkunal, cleech, mmuench, prasanna.kalever, sheggodu, ykaul
Target Milestone:	rc
Target Release:	7.8
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	iscsi-initiator-utils-6.2.0.874-13.el7	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2020-03-31 20:03:52 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1554642, 1577173, 1597320, 1625824, 1646945, 1654409, 1657156, 1727425

Description Xiubo Li 2018-09-03 02:56:26 UTC

Description of problem:

For our CNS product, we can hit the "iSCSI Login negotiation failed" very frequently, and from the target side dmesg logs we can see the following logs:

Sep 02 22:41:50 rhel1 kernel: Selected MD5 Algorithm
Sep 02 22:41:50 rhel1 kernel: [server] Got CHAP_A=5
Sep 02 22:41:50 rhel1 kernel: [server] Sending CHAP_A=5
Sep 02 22:41:50 rhel1 kernel: [server] Sending CHAP_I=72
Sep 02 22:41:50 rhel1 kernel: [server] Sending CHAP_C=0x8c1295d9ee15bbd4c10a87cdb9b55131
Sep 02 22:41:50 rhel1 kernel: Received OK response from LIO Authentication, continuing.
Sep 02 22:41:50 rhel1 kernel: Sending Login Response, Flags: 0x00, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x8ac1142c, Length:
Sep 02 22:41:50 rhel1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff9be258024000
Sep 02 22:41:50 rhel1 kernel: entering iscsi_target_do_login_rx, conn: ffff9be258024000, kworker/0:2:21036
Sep 02 22:41:50 rhel1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff9be258024000
Sep 02 22:41:50 rhel1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff9be258024000 >>>>
Sep 02 22:41:50 rhel1 kernel: Starting login_timer for kworker/0:2/21036
Sep 02 22:41:50 rhel1 kernel: Got Login Command, Flags 0x81, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x2d14c18a, CID: 0, Length: 50
Sep 02 22:41:50 rhel1 kernel: iscsi_target_do_login_rx after rx_login_io, ffff9be258024000, kworker/0:2:21036
Sep 02 22:41:50 rhel1 kernel: CHAP_N[], auth->userid[34dcd8da-7e5f-4028-93b4-3917c2173711]!
Sep 02 22:41:50 rhel1 kernel: CHAP_R[], auth->password[770ae86f-09e9-4faa-9745-fa0f135ec6cf]!
Sep 02 22:41:50 rhel1 kernel: CHAP_N values do not match!
Sep 02 22:41:50 rhel1 kernel: Security negotiation failed.
Sep 02 22:41:50 rhel1 kernel: Added timeout timer to iSCSI login request for 15 seconds.
Sep 02 22:41:50 rhel1 kernel: Moving to TARG_CONN_STATE_XPT_UP.
Sep 02 22:41:50 rhel1 kernel: Entering iscsi_target_restore_sock_callbacks: conn: ffff9be258024000
Sep 02 22:41:50 rhel1 kernel: iSCSI Login negotiation failed.

NOTE: some of the logs are added by myself and some are from the dynamic debuginfo.

The CHAP_N value is NULL.

From the initiator side, after setting the "node.session.auth.username" and "node.session.auth.password", just before login we just list the parameters we set, it shows that "node.session.auth.username" is empty:

...
node.session.queue_depth = 32
node.session.nr_sessions = 1
node.session.auth.authmethod = None
node.session.auth.username = <empty>
node.session.auth.password = ********
node.session.auth.username_in = <empty>
node.session.auth.password_in = <empty>
...

I have tried the newest open-iscsi code from the upstream, still the same.

This will be very easy to reproduce when trying to login multi targets in parallel, more detail and the reproduce scrtipt could be found in https://bugzilla.redhat.com/show_bug.cgi?id=1597320#c26.

Thanks,


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


How reproducible: 30%

Comment 3 Xiubo Li 2018-09-03 10:07:46 UTC

#iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n node.session.auth.authmethod -v CHAP
#iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n node.session.auth.username -v $USER
#iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n node.session.auth.password -v $PASSWORD

For this, from my debug and through reading the code it seems when updating the parm followed it will overwrite the front one. I have tried to combine the above 3 commands to single one, like:

# iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n node.session.auth.authmethod -v CHAP -o update -n node.session.auth.username -v $USER -o update -n node.session.auth.password -v $PASSWORD

Test for many times, didn't reproduce it yet.

@Chris It seems buggy when loading -> updating -> storing the node type rec info in parallel. For the workaround will it be work just combining them ?

Thanks,

Comment 5 Chris Leech 2018-09-18 18:17:10 UTC

(In reply to Xiubo Li from comment #3)
> #iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n
> node.session.auth.authmethod -v CHAP
> #iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n
> node.session.auth.username -v $USER
> #iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n
> node.session.auth.password -v $PASSWORD
> 
> For this, from my debug and through reading the code it seems when updating
> the parm followed it will overwrite the front one. I have tried to combine
> the above 3 commands to single one, like:
> 
> # iscsiadm -m node -p $N:3260 -T $IQN -I default -o update -n
> node.session.auth.authmethod -v CHAP -o update -n node.session.auth.username
> -v $USER -o update -n node.session.auth.password -v $PASSWORD
> 
> Test for many times, didn't reproduce it yet.
> 
> @Chris It seems buggy when loading -> updating -> storing the node type rec
> info in parallel. For the workaround will it be work just combining them ?
> 
> Thanks,

Ug. iscsiadm is getting a file lock while writing out records, but updates are a read-modify-write operation and only the write is locked.  So the parallel requests are reading in the pre-update record and then overwriting each other with the writes.

I'll look at improving the parallel handling of the records, but I think it should be fine if you only have one process per record updating with multiple values.

Comment 7 Amar Tumballi 2018-10-22 09:15:08 UTC

Chris, just checking if you got any chance to go further with this bug?

Comment 10 Yaniv Kaul 2019-04-22 12:10:57 UTC

Do we have any updates on this BZ?

Comment 14 Chris Leech 2019-07-05 16:50:53 UTC

Solution has been agreed to and code merged upstream.

Comment 15 Chris Leech 2019-07-05 18:10:18 UTC

*** Bug 1624678 has been marked as a duplicate of this bug. ***

Comment 17 Filip Suba 2019-12-06 11:40:45 UTC

Verified with iscsi-initiator-utils-6.2.0.874-17.el7.

Comment 19 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