Hey Nick and Florian,
Starting in 4.14 iscsi logins will fail around 50% of the time.
I git bisected the issue down to this commit:
commit e7942d0633c47c791ece6afa038be9cf977226de
Author: Florian Westphal <fw@xxxxxxxxx>
Date: Sun Jul 30 03:57:18 2017 +0200
tcp: remove prequeue support
Nick, attached is the iscsi target log info when the login fails.
You can see at:
Dec 13 17:55:01 rhel73n1 kernel: Got Login Command, Flags 0x81, ITT:
0x00000000, CmdSN: 0x00000000, ExpStatSN: 0xf86dc69b, CID: 0, Length: 65
we have got a login command and we seem to then go into
iscsit_do_rx_data -> sock_recvmsg
We seem to get stuck in there though, because we stay blocked until:
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_sk_data_ready:
conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn:
ffff88b35cbb3000 >>>>
where initiator side timeout fires 15 seconds later and it disconnects
the tcp connection, and we eventually break out of the recvmsg call:
Dec 13 17:55:16 rhel73n1 kernel: Entering iscsi_target_sk_state_change
Dec 13 17:55:16 rhel73n1 kernel: __iscsi_target_sk_check_close:
TCP_CLOSE_WAIT|TCP_CLOSE,returning FALSE
....
Dec 13 17:55:16 rhel73n1 kernel: rx_loop: 68, total_rx: 68, data: 68
Dec 13 17:55:16 rhel73n1 kernel: iscsi_target_do_login_rx after
rx_login_io, ffff88b35cbb3000, kworker/2:2:1829
Is the iscsi target doing something incorrect in its use of
sk_data_ready and sock_recvmsg or is the tcp patch at fault?
Dec 13 17:55:01 rhel73n1 kernel: Added timeout timer to iSCSI login request for 15 seconds.
Dec 13 17:55:01 rhel73n1 kernel: Moving to TARG_CONN_STATE_XPT_UP.
Dec 13 17:55:01 rhel73n1 kernel: rx_loop: 48, total_rx: 48, data: 48
Dec 13 17:55:01 rhel73n1 kernel: Got Login Command, Flags 0x81, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x00000000, CID: 0, Length: 144
Dec 13 17:55:01 rhel73n1 kernel: rx_loop: 144, total_rx: 144, data: 144
Dec 13 17:55:01 rhel73n1 kernel: Received iSCSI login request from 20.15.0.202:60372 on iSCSI/TCP Network Portal 20.15.0.131:3260
Dec 13 17:55:01 rhel73n1 kernel: Moving to TARG_CONN_STATE_IN_LOGIN.
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_set_sock_callbacks: conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: Located Storage Object: iqn.2003-01.com.redhat:ceph-iscsi
Dec 13 17:55:01 rhel73n1 kernel: Located Portal Group Object: 1
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to TargetPortalGroupTag=1
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to ErrorRecoveryLevel=0
Dec 13 17:55:01 rhel73n1 kernel: Got key: InitiatorName=iqn.2005-03.com.ceph:ini1
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to InitiatorName=iqn.2005-03.com.ceph:ini1
Dec 13 17:55:01 rhel73n1 kernel: Got key: InitiatorAlias=rh2
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to InitiatorAlias=rh2
Dec 13 17:55:01 rhel73n1 kernel: Got key: TargetName=iqn.2003-01.com.redhat:ceph-iscsi
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to TargetName=iqn.2003-01.com.redhat:ceph-iscsi
Dec 13 17:55:01 rhel73n1 kernel: Got key: SessionType=Normal
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to SessionType=Normal
Dec 13 17:55:01 rhel73n1 kernel: Got key: AuthMethod=CHAP,None
Dec 13 17:55:01 rhel73n1 kernel: iSCSI Parameter updated to AuthMethod=CHAP
Dec 13 17:55:01 rhel73n1 kernel: Sending key: AuthMethod=CHAP
Dec 13 17:55:01 rhel73n1 kernel: Sending key: TargetAlias=LIO Target
Dec 13 17:55:01 rhel73n1 kernel: Sending key: TargetPortalGroupTag=1
Dec 13 17:55:01 rhel73n1 kernel: Sending Login Response, Flags: 0x00, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x9bc66df6, Length: 62
Dec 13 17:55:01 rhel73n1 kernel: tx_loop: 112, total_tx: 112, data: 112
Dec 13 17:55:01 rhel73n1 kernel: Moving to TARG_CONN_STATE_FREE.
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
Dec 13 17:55:01 rhel73n1 kernel: entering iscsi_target_do_login_rx, conn: ffff88b35cbb3000, kworker/2:2:1829
Dec 13 17:55:01 rhel73n1 kernel: Starting login_timer for kworker/2:2/1829
Dec 13 17:55:01 rhel73n1 kernel: rx_loop: 48, total_rx: 48, data: 48
Dec 13 17:55:01 rhel73n1 kernel: Got Login Command, Flags 0x00, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0xf76dc69b, CID: 0, Length: 9
Dec 13 17:55:01 rhel73n1 kernel: rx_loop: 12, total_rx: 12, data: 12
Dec 13 17:55:01 rhel73n1 kernel: iscsi_target_do_login_rx after rx_login_io, ffff88b35cbb3000, kworker/2:2:1829
Dec 13 17:55:01 rhel73n1 kernel: Got key: CHAP_A=5
Dec 13 17:55:01 rhel73n1 kernel: Selected MD5 Algorithm
Dec 13 17:55:01 rhel73n1 kernel: [server] Got CHAP_A=5
Dec 13 17:55:01 rhel73n1 kernel: [server] Sending CHAP_A=5
Dec 13 17:55:01 rhel73n1 kernel: [server] Sending CHAP_I=2
Dec 13 17:55:01 rhel73n1 kernel: [server] Sending CHAP_C=0x3eb639d370fb7c841a4038474531cbaa
Dec 13 17:55:01 rhel73n1 kernel: Received OK response from LIO Authentication, continuing.
Dec 13 17:55:01 rhel73n1 kernel: Sending Login Response, Flags: 0x00, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x9bc66df7, Length: 60
Dec 13 17:55:01 rhel73n1 kernel: tx_loop: 108, total_tx: 108, data: 108
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: entering iscsi_target_do_login_rx, conn: ffff88b35cbb3000, kworker/2:2:1829
Dec 13 17:55:01 rhel73n1 kernel: Starting login_timer for kworker/2:2/1829
Dec 13 17:55:01 rhel73n1 kernel: rx_loop: 48, total_rx: 48, data: 48
Dec 13 17:55:01 rhel73n1 kernel: Got Login Command, Flags 0x81, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0xf86dc69b, CID: 0, Length: 65
Dec 13 17:55:01 rhel73n1 kernel: Entering iscsi_target_sk_data_ready: conn: ffff88b35cbb3000
Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
Dec 13 17:55:01 rhel73n1 systemd[1]: Created slice User Slice of pcp.
Dec 13 17:55:01 rhel73n1 systemd[1]: Starting User Slice of pcp.
Dec 13 17:55:01 rhel73n1 systemd[1]: Started Session 8 of user pcp.
Dec 13 17:55:01 rhel73n1 systemd[1]: Starting Session 8 of user pcp.
Dec 13 17:55:01 rhel73n1 CROND[1848]: (pcp) CMD ( /usr/libexec/pcp/bin/pmlogger_check -C)
Dec 13 17:55:01 rhel73n1 systemd[1]: Removed slice User Slice of pcp.
Dec 13 17:55:01 rhel73n1 systemd[1]: Stopping User Slice of pcp.
Dec 13 17:55:16 rhel73n1 kernel: Entering iscsi_target_sk_state_change
Dec 13 17:55:16 rhel73n1 kernel: __iscsi_target_sk_check_close: TCP_CLOSE_WAIT|TCP_CLOSE,returning FALSE
Dec 13 17:55:16 rhel73n1 kernel: __iscsi_target_sk_close_change: state: 1
Dec 13 17:55:16 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1 sk_state_change conn: ffff88b35cbb3000
Dec 13 17:55:16 rhel73n1 kernel: rx_loop: 68, total_rx: 68, data: 68
Dec 13 17:55:16 rhel73n1 kernel: iscsi_target_do_login_rx after rx_login_io, ffff88b35cbb3000, kworker/2:2:1829
Dec 13 17:55:16 rhel73n1 kernel: Got key: CHAP_N=myiscsiusername
Dec 13 17:55:16 rhel73n1 kernel: [server] Got CHAP_N=myiscsiusername
Dec 13 17:55:16 rhel73n1 kernel: [server] Got CHAP_R=a33b56452f1f06d331c9ef990a8a2e24
Dec 13 17:55:16 rhel73n1 kernel: [server] MD5 Server Digest: a33b56452f1f06d331c9ef990a8a2e24
Dec 13 17:55:16 rhel73n1 kernel: [server] MD5 Digests match, CHAP connection successful.
Dec 13 17:55:16 rhel73n1 kernel: iSCSI security negotiation completed successfully.
Dec 13 17:55:16 rhel73n1 kernel: Sending Login Response, Flags: 0x81, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x9bc66df8, Length: 0
Dec 13 17:55:16 rhel73n1 kernel: tx_loop: -104 total_tx 0
Dec 13 17:55:16 rhel73n1 kernel: tx_data returned -104, expecting 48.
Dec 13 17:55:16 rhel73n1 kernel: Entering iscsi_target_restore_sock_callbacks: conn: ffff88b35cbb3000
Dec 13 17:55:16 rhel73n1 kernel: iSCSI Login negotiation failed.
