From: Mike Christie <mchristi@redhat.com>
To: target-devel@vger.kernel.org
Subject: iscsi target regression due to "tcp: remove prequeue support" patch
Date: Thu, 14 Dec 2017 05:56:29 +0000 [thread overview]
Message-ID: <5A32128D.4050207@redhat.com> (raw)
[-- Attachment #1: Type: text/plain, Size: 1498 bytes --]
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@strlen.de>
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?
[-- Attachment #2: iscsi-chap-login-failure.txt --]
[-- Type: text/plain, Size: 6563 bytes --]
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.
next reply other threads:[~2017-12-14 5:56 UTC|newest]
Thread overview: 16+ messages / expand[flat|nested] mbox.gz Atom feed top
2017-12-14 5:56 Mike Christie [this message]
2018-01-09 6:32 ` iscsi target regression due to "tcp: remove prequeue support" patch Nicholas A. Bellinger
2018-01-09 6:32 ` Nicholas A. Bellinger
2018-01-15 6:41 ` Nicholas A. Bellinger
2018-01-15 6:41 ` Nicholas A. Bellinger
2018-01-15 20:33 ` Mike Christie
2018-01-15 20:33 ` Mike Christie
2018-01-18 8:41 ` Nicholas A. Bellinger
2018-01-18 8:41 ` Nicholas A. Bellinger
2018-01-15 10:41 ` Florian Westphal
2018-01-18 8:38 ` Nicholas A. Bellinger
2018-01-18 8:38 ` Nicholas A. Bellinger
2018-01-18 15:10 ` Florian Westphal
2018-01-18 15:10 ` Florian Westphal
2018-01-19 4:28 ` Mike Christie
2018-01-19 4:28 ` Mike Christie
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=5A32128D.4050207@redhat.com \
--to=mchristi@redhat.com \
--cc=target-devel@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.