Bug 1624670 - iSCSI Login negotiation failed due to CHAP_N values do not match!
Summary: iSCSI Login negotiation failed due to CHAP_N values do not match!
Keywords:
Status: VERIFIED
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: iscsi-initiator-utils
Version: 7.5
Hardware: Unspecified
OS: Unspecified
high
urgent
Target Milestone: rc
: 7.8
Assignee: Chris Leech
QA Contact: Filip Suba
URL:
Whiteboard:
: 1624678 (view as bug list)
Depends On:
Blocks: 1554642 1577173 1597320 1727425 1625824 1646945 1654409 1657156
TreeView+ depends on / blocked
 
Reported: 2018-09-03 02:56 UTC by Xiubo Li
Modified: 2020-02-17 16:20 UTC (History)
6 users (show)

Fixed In Version: iscsi-initiator-utils-6.2.0.874-13.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Target Upstream Version:


Attachments (Terms of Use)

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.


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