iscsi target regression due to "tcp: remove prequeue support" patch

iscsi target regression due to "tcp: remove prequeue support" patch

[Mike Christie]

[-- 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.

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hi MNC & Florian,

(Adding net-dev + DaveM CC')

Catching up on pre-holiday threads, thanks for the heads up.

Comments below.

On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
> 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
> 

Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
TPG login_timeout subsequently fires after 15 seconds of inactivity to
terminate this login attempt.

> Is the iscsi target doing something incorrect in its use of
> sk_data_ready and sock_recvmsg or is the tcp patch at fault?

From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
appear firing as expected.

iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
after iscsi_target_sk_data_ready() callback queues up
iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
struct kvec iovec for struct msg_hdr.

AFAICT, iscsi-target uses blocking kernel socket reads from process
context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.

Florian + DaveM, any idea why the removal of prequeue support is having
an effect here..?

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hi MNC & Florian,

(Adding net-dev + DaveM CC')

Catching up on pre-holiday threads, thanks for the heads up.

Comments below.

On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
> 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
> 

Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
TPG login_timeout subsequently fires after 15 seconds of inactivity to
terminate this login attempt.

> Is the iscsi target doing something incorrect in its use of
> sk_data_ready and sock_recvmsg or is the tcp patch at fault?

>From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
appear firing as expected.

iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
after iscsi_target_sk_data_ready() callback queues up
iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
struct kvec iovec for struct msg_hdr.

AFAICT, iscsi-target uses blocking kernel socket reads from process
context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.

Florian + DaveM, any idea why the removal of prequeue support is having
an effect here..?

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hey MNC & Co,

Ping on the earlier iscsi-target authentication login failures atop
4.14 + commit e7942d063 removing tcp prequeue support.

For reference, what is your pre 4.14 environment using for
sysctl_tcp_low_latency..?

netdev folks, how would you like to proceed for -rc1..?

On Mon, 2018-01-08 at 22:32 -0800, Nicholas A. Bellinger wrote:
> Hi MNC & Florian,
> 
> (Adding net-dev + DaveM CC')
> 
> Catching up on pre-holiday threads, thanks for the heads up.
> 
> Comments below.
> 
> On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
> > 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
> > 
> 
> Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
> containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
> TPG login_timeout subsequently fires after 15 seconds of inactivity to
> terminate this login attempt.
> 
> > Is the iscsi target doing something incorrect in its use of
> > sk_data_ready and sock_recvmsg or is the tcp patch at fault?
> 
> From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
> appear firing as expected.
> 
> iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
> sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
> after iscsi_target_sk_data_ready() callback queues up
> iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
> struct kvec iovec for struct msg_hdr.
> 
> AFAICT, iscsi-target uses blocking kernel socket reads from process
> context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.
> 
> Florian + DaveM, any idea why the removal of prequeue support is having
> an effect here..?
> 
> --
> To unsubscribe from this list: send the line "unsubscribe target-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hey MNC & Co,

Ping on the earlier iscsi-target authentication login failures atop
4.14 + commit e7942d063 removing tcp prequeue support.

For reference, what is your pre 4.14 environment using for
sysctl_tcp_low_latency..?

netdev folks, how would you like to proceed for -rc1..?

On Mon, 2018-01-08 at 22:32 -0800, Nicholas A. Bellinger wrote:
> Hi MNC & Florian,
> 
> (Adding net-dev + DaveM CC')
> 
> Catching up on pre-holiday threads, thanks for the heads up.
> 
> Comments below.
> 
> On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
> > 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
> > 
> 
> Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
> containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
> TPG login_timeout subsequently fires after 15 seconds of inactivity to
> terminate this login attempt.
> 
> > Is the iscsi target doing something incorrect in its use of
> > sk_data_ready and sock_recvmsg or is the tcp patch at fault?
> 
> From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
> appear firing as expected.
> 
> iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
> sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
> after iscsi_target_sk_data_ready() callback queues up
> iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
> struct kvec iovec for struct msg_hdr.
> 
> AFAICT, iscsi-target uses blocking kernel socket reads from process
> context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.
> 
> Florian + DaveM, any idea why the removal of prequeue support is having
> an effect here..?
> 
> --
> To unsubscribe from this list: send the line "unsubscribe target-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Mike Christie]

On 01/15/2018 12:41 AM, Nicholas A. Bellinger wrote:
> Hey MNC & Co,
> 
> Ping on the earlier iscsi-target authentication login failures atop
> 4.14 + commit e7942d063 removing tcp prequeue support.
> 
> For reference, what is your pre 4.14 environment using for
> sysctl_tcp_low_latency..?

tcp_low_latency=1.

I have tested the current kernel with 1 and 0, and it does not make a
difference.

> 
> netdev folks, how would you like to proceed for -rc1..?
> 
> On Mon, 2018-01-08 at 22:32 -0800, Nicholas A. Bellinger wrote:
>> Hi MNC & Florian,
>>
>> (Adding net-dev + DaveM CC')
>>
>> Catching up on pre-holiday threads, thanks for the heads up.
>>
>> Comments below.
>>
>> On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
>>> 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
>>>
>>
>> Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
>> containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
>> TPG login_timeout subsequently fires after 15 seconds of inactivity to
>> terminate this login attempt.
>>
>>> Is the iscsi target doing something incorrect in its use of
>>> sk_data_ready and sock_recvmsg or is the tcp patch at fault?
>>
>> From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
>> appear firing as expected.
>>
>> iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
>> sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
>> after iscsi_target_sk_data_ready() callback queues up
>> iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
>> struct kvec iovec for struct msg_hdr.
>>
>> AFAICT, iscsi-target uses blocking kernel socket reads from process
>> context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.
>>
>> Florian + DaveM, any idea why the removal of prequeue support is having
>> an effect here..?
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe target-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Mike Christie]

On 01/15/2018 12:41 AM, Nicholas A. Bellinger wrote:
> Hey MNC & Co,
> 
> Ping on the earlier iscsi-target authentication login failures atop
> 4.14 + commit e7942d063 removing tcp prequeue support.
> 
> For reference, what is your pre 4.14 environment using for
> sysctl_tcp_low_latency..?

tcp_low_latency=1.

I have tested the current kernel with 1 and 0, and it does not make a
difference.

> 
> netdev folks, how would you like to proceed for -rc1..?
> 
> On Mon, 2018-01-08 at 22:32 -0800, Nicholas A. Bellinger wrote:
>> Hi MNC & Florian,
>>
>> (Adding net-dev + DaveM CC')
>>
>> Catching up on pre-holiday threads, thanks for the heads up.
>>
>> Comments below.
>>
>> On Wed, 2017-12-13 at 23:56 -0600, Mike Christie wrote:
>>> 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
>>>
>>
>> Ok, the 3rd third login request payload (65 + 3 padded to 68 bytes)
>> containing CHAP_N + CHAP_R keys remains blocked on sock_recvmsg(), until
>> TPG login_timeout subsequently fires after 15 seconds of inactivity to
>> terminate this login attempt.
>>
>>> Is the iscsi target doing something incorrect in its use of
>>> sk_data_ready and sock_recvmsg or is the tcp patch at fault?
>>
>> From the logs, sk_data_ready() -> iscsi_target_sk_data_ready() callbacks
>> appear firing as expected.
>>
>> iscsi-target login does iscsit_rx_do_data() -> rx_data() ->
>> sock_recvmsg(..., MSG_WAITALL) from a system_wq kworker process context
>> after iscsi_target_sk_data_ready() callback queues up
>> iscsi_conn->login_work for execution, and sock_recvmsg() uses a single
>> struct kvec iovec for struct msg_hdr.
>>
>> AFAICT, iscsi-target uses blocking kernel socket reads from process
>> context, similar to kernel_recvmsg(..., MSG_WAITALL) with DRBD.
>>
>> Florian + DaveM, any idea why the removal of prequeue support is having
>> an effect here..?
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe target-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

On Mon, 2018-01-15 at 14:33 -0600, Mike Christie wrote:
> On 01/15/2018 12:41 AM, Nicholas A. Bellinger wrote:
> > Hey MNC & Co,
> > 
> > Ping on the earlier iscsi-target authentication login failures atop
> > 4.14 + commit e7942d063 removing tcp prequeue support.
> > 
> > For reference, what is your pre 4.14 environment using for
> > sysctl_tcp_low_latency..?
> 
> tcp_low_latency=1.
> 
> I have tested the current kernel with 1 and 0, and it does not make a
> difference.
> 

Likewise, I've always used tcp_low_latency=1 on pre 4.14.y kernels and
never triggered this bug with multi login PDU exchanges.

What's strange from groking commit e7942d0 though, it appear the removal
of tcp prequeue logic should only effect tcp_low_latency=0 users,
right..?

But here, that doesn't seem to be the case..

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

On Mon, 2018-01-15 at 14:33 -0600, Mike Christie wrote:
> On 01/15/2018 12:41 AM, Nicholas A. Bellinger wrote:
> > Hey MNC & Co,
> > 
> > Ping on the earlier iscsi-target authentication login failures atop
> > 4.14 + commit e7942d063 removing tcp prequeue support.
> > 
> > For reference, what is your pre 4.14 environment using for
> > sysctl_tcp_low_latency..?
> 
> tcp_low_latency=1.
> 
> I have tested the current kernel with 1 and 0, and it does not make a
> difference.
> 

Likewise, I've always used tcp_low_latency=1 on pre 4.14.y kernels and
never triggered this bug with multi login PDU exchanges.

What's strange from groking commit e7942d0 though, it appear the removal
of tcp prequeue logic should only effect tcp_low_latency=0 users,
right..?

But here, that doesn't seem to be the case..

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Florian Westphal]

Mike Christie <mchristi@redhat.com> wrote:
 
> 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?

I have not received any bug reports except this one.

I also have a hard time following iscsi code flow.

> 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

Looks like things are fine up to this point.

> Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>

This makes things return early from sk_data_ready callback.

> 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.

irrelevant.

> 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

So it looks like all data is there, and probably has been there all the
past 15 seconds, but nothing noticed.

Why is LOGIN_FLAGS_READ_ACTIVE set?  Who sets this?  Who is supposed to clear that?
Why does it exist in first place?

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hi Florian,

(Adding netdev + DaveM CC')

Thanks for the response.  Comments below.

On Mon, 2018-01-15 at 11:41 +0100, Florian Westphal wrote:
> Mike Christie <mchristi@redhat.com> wrote:
>  
> > 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?
> 
> I have not received any bug reports except this one.
> 
> I also have a hard time following iscsi code flow.
> 
> > 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
> 
> Looks like things are fine up to this point.
> 
> > Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
> 
> This makes things return early from sk_data_ready callback.

Correct.

This is existing behavior for individual iscsi_conn login delayed_work
contexts (conn->login_work) which have not yet returned from a previous
sock_recvmsg(..., MSG_WAITALL) blocking call.

This causes the next iscsi_target_sk_data_ready() callback to hit
LOGIN_FLAGS_READ_ACTIVE=1, and return immediately without kicking
conn->login_work to process iscsi_target_do_login_rx() ->
sock_recvmsg(..., MSG_WAITALL).

> > 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
> 
> So it looks like all data is there, and probably has been there all the
> past 15 seconds, but nothing noticed.
> 
> Why is LOGIN_FLAGS_READ_ACTIVE set?  Who sets this?  Who is supposed to clear that?
> Why does it exist in first place?

The bit is set in iscsi_target_sk_data_ready() when conn->login_work is
not already blocked by sock_recvmsg(..., MSG_WAITALL).  Once it's set,
conn->login_work is kicked to run iscsi_target_do_login_rx() ->
sock_recvmsg(..., MSG_WAITALL) which blocks waiting for the next 48 byte
login request PDU + payload.

Once the active conn->login_work context in iscsi_target_do_login_rx()
returns from sock_recvmsg(..., MSG_WAITALL) with full login request PDU
+ payload bytes, the bit is cleared.

AFAICT, there was a wake_up removed by commit e7942d063 that results in
multi iscsi login PDU authentication exchanges blocking on a incoming
login request payload.

So I don't know if this is a pre-existing bug hidden in iscsi-target by
tcp prequeue login, or not...?

It would indicate users providing their own ->sk_data_ready() callback
must be responsible for waking up a kthread context blocked on
sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
received before the first sock_recvmsg(..., MSG_WAITALL) completes.

I don't know if this is a pre-existing bug in iscsi-target hidden by tcp
prequeue logic, or not...?

Any ideas..?

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Nicholas A. Bellinger]

Hi Florian,

(Adding netdev + DaveM CC')

Thanks for the response.  Comments below.

On Mon, 2018-01-15 at 11:41 +0100, Florian Westphal wrote:
> Mike Christie <mchristi@redhat.com> wrote:
>  
> > 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?
> 
> I have not received any bug reports except this one.
> 
> I also have a hard time following iscsi code flow.
> 
> > 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
> 
> Looks like things are fine up to this point.
> 
> > Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
> 
> This makes things return early from sk_data_ready callback.

Correct.

This is existing behavior for individual iscsi_conn login delayed_work
contexts (conn->login_work) which have not yet returned from a previous
sock_recvmsg(..., MSG_WAITALL) blocking call.

This causes the next iscsi_target_sk_data_ready() callback to hit
LOGIN_FLAGS_READ_ACTIVE=1, and return immediately without kicking
conn->login_work to process iscsi_target_do_login_rx() ->
sock_recvmsg(..., MSG_WAITALL).

> > 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
> 
> So it looks like all data is there, and probably has been there all the
> past 15 seconds, but nothing noticed.
> 
> Why is LOGIN_FLAGS_READ_ACTIVE set?  Who sets this?  Who is supposed to clear that?
> Why does it exist in first place?

The bit is set in iscsi_target_sk_data_ready() when conn->login_work is
not already blocked by sock_recvmsg(..., MSG_WAITALL).  Once it's set,
conn->login_work is kicked to run iscsi_target_do_login_rx() ->
sock_recvmsg(..., MSG_WAITALL) which blocks waiting for the next 48 byte
login request PDU + payload.

Once the active conn->login_work context in iscsi_target_do_login_rx()
returns from sock_recvmsg(..., MSG_WAITALL) with full login request PDU
+ payload bytes, the bit is cleared.

AFAICT, there was a wake_up removed by commit e7942d063 that results in
multi iscsi login PDU authentication exchanges blocking on a incoming
login request payload.

So I don't know if this is a pre-existing bug hidden in iscsi-target by
tcp prequeue login, or not...?

It would indicate users providing their own ->sk_data_ready() callback
must be responsible for waking up a kthread context blocked on
sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
received before the first sock_recvmsg(..., MSG_WAITALL) completes.

I don't know if this is a pre-existing bug in iscsi-target hidden by tcp
prequeue logic, or not...?

Any ideas..?

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Florian Westphal]

Nicholas A. Bellinger <nab@linux-iscsi.org> wrote:
> On Mon, 2018-01-15 at 11:41 +0100, Florian Westphal wrote:
> > Mike Christie <mchristi@redhat.com> wrote:
> >  
> > > 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: 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?
> > 
> > I have not received any bug reports except this one.
> > 
> > I also have a hard time following iscsi code flow.
> > 
> > > 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
> > 
> > Looks like things are fine up to this point.
> > 
> > > Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
> > 
> > This makes things return early from sk_data_ready callback.
> 
> Correct.
>
> This is existing behavior for individual iscsi_conn login delayed_work
> contexts (conn->login_work) which have not yet returned from a previous
> sock_recvmsg(..., MSG_WAITALL) blocking call.
>
> This causes the next iscsi_target_sk_data_ready() callback to hit
> LOGIN_FLAGS_READ_ACTIVE=1, and return immediately without kicking
> conn->login_work to process iscsi_target_do_login_rx() ->
> sock_recvmsg(..., MSG_WAITALL).

Who is responsible to remove the worker/sk from the wait queue?

> > > 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
> > 
> > So it looks like all data is there, and probably has been there all the
> > past 15 seconds, but nothing noticed.
> > 
> > Why is LOGIN_FLAGS_READ_ACTIVE set?  Who sets this?  Who is supposed to clear that?
> > Why does it exist in first place?
> 
> The bit is set in iscsi_target_sk_data_ready() when conn->login_work is
> not already blocked by sock_recvmsg(..., MSG_WAITALL).  Once it's set,
> conn->login_work is kicked to run iscsi_target_do_login_rx() ->
> sock_recvmsg(..., MSG_WAITALL) which blocks waiting for the next 48 byte
> login request PDU + payload.
> 
> Once the active conn->login_work context in iscsi_target_do_login_rx()
> returns from sock_recvmsg(..., MSG_WAITALL) with full login request PDU
> + payload bytes, the bit is cleared.
> 
> AFAICT, there was a wake_up removed by commit e7942d063 that results in
> multi iscsi login PDU authentication exchanges blocking on a incoming
> login request payload.

With you so far, BUT -- Mike has lowlatency=1 set -- so all the
tcp_prequeue code paths should never be hit in first place.

I just tried a 4.13 kernel and no tcp prequeue is path is hit when
lowlatency sysctl is set afaics.

> It would indicate users providing their own ->sk_data_ready() callback
> must be responsible for waking up a kthread context blocked on
> sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
> received before the first sock_recvmsg(..., MSG_WAITALL) completes.

I agree, it looks like we need something like this?
(not even build tested):

diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
index b686e2ce9c0e..3723f8f419aa 100644
--- a/drivers/target/iscsi/iscsi_target_nego.c
+++ b/drivers/target/iscsi/iscsi_target_nego.c
@@ -432,6 +432,9 @@ static void iscsi_target_sk_data_ready(struct sock *sk)
        if (test_and_set_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags)) {
                write_unlock_bh(&sk->sk_callback_lock);
                pr_debug("Got LOGIN_FLAGS_READ_ACTIVE=1, conn: %p >>>>\n", conn);
+               if (WARN_ON(iscsi_target_sk_data_ready = conn->orig_data_ready))
+                       return;
+               conn->orig_data_ready(sk);
                return;
        }

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Florian Westphal]

Nicholas A. Bellinger <nab@linux-iscsi.org> wrote:
> On Mon, 2018-01-15 at 11:41 +0100, Florian Westphal wrote:
> > Mike Christie <mchristi@redhat.com> wrote:
> >  
> > > 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: 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?
> > 
> > I have not received any bug reports except this one.
> > 
> > I also have a hard time following iscsi code flow.
> > 
> > > 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
> > 
> > Looks like things are fine up to this point.
> > 
> > > Dec 13 17:55:01 rhel73n1 kernel: Got LOGIN_FLAGS_READ_ACTIVE=1, conn: ffff88b35cbb3000 >>>>
> > 
> > This makes things return early from sk_data_ready callback.
> 
> Correct.
>
> This is existing behavior for individual iscsi_conn login delayed_work
> contexts (conn->login_work) which have not yet returned from a previous
> sock_recvmsg(..., MSG_WAITALL) blocking call.
>
> This causes the next iscsi_target_sk_data_ready() callback to hit
> LOGIN_FLAGS_READ_ACTIVE=1, and return immediately without kicking
> conn->login_work to process iscsi_target_do_login_rx() ->
> sock_recvmsg(..., MSG_WAITALL).

Who is responsible to remove the worker/sk from the wait queue?

> > > 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
> > 
> > So it looks like all data is there, and probably has been there all the
> > past 15 seconds, but nothing noticed.
> > 
> > Why is LOGIN_FLAGS_READ_ACTIVE set?  Who sets this?  Who is supposed to clear that?
> > Why does it exist in first place?
> 
> The bit is set in iscsi_target_sk_data_ready() when conn->login_work is
> not already blocked by sock_recvmsg(..., MSG_WAITALL).  Once it's set,
> conn->login_work is kicked to run iscsi_target_do_login_rx() ->
> sock_recvmsg(..., MSG_WAITALL) which blocks waiting for the next 48 byte
> login request PDU + payload.
> 
> Once the active conn->login_work context in iscsi_target_do_login_rx()
> returns from sock_recvmsg(..., MSG_WAITALL) with full login request PDU
> + payload bytes, the bit is cleared.
> 
> AFAICT, there was a wake_up removed by commit e7942d063 that results in
> multi iscsi login PDU authentication exchanges blocking on a incoming
> login request payload.

With you so far, BUT -- Mike has lowlatency=1 set -- so all the
tcp_prequeue code paths should never be hit in first place.

I just tried a 4.13 kernel and no tcp prequeue is path is hit when
lowlatency sysctl is set afaics.

> It would indicate users providing their own ->sk_data_ready() callback
> must be responsible for waking up a kthread context blocked on
> sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
> received before the first sock_recvmsg(..., MSG_WAITALL) completes.

I agree, it looks like we need something like this?
(not even build tested):

diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
index b686e2ce9c0e..3723f8f419aa 100644
--- a/drivers/target/iscsi/iscsi_target_nego.c
+++ b/drivers/target/iscsi/iscsi_target_nego.c
@@ -432,6 +432,9 @@ static void iscsi_target_sk_data_ready(struct sock *sk)
        if (test_and_set_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags)) {
                write_unlock_bh(&sk->sk_callback_lock);
                pr_debug("Got LOGIN_FLAGS_READ_ACTIVE=1, conn: %p >>>>\n", conn);
+               if (WARN_ON(iscsi_target_sk_data_ready == conn->orig_data_ready))
+                       return;
+               conn->orig_data_ready(sk);
                return;
        }

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Mike Christie]

On 01/18/2018 09:10 AM, Florian Westphal wrote:
>> It would indicate users providing their own ->sk_data_ready() callback
>> must be responsible for waking up a kthread context blocked on
>> sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
>> received before the first sock_recvmsg(..., MSG_WAITALL) completes.
> 
> I agree, it looks like we need something like this?
> (not even build tested):
> 
> diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
> index b686e2ce9c0e..3723f8f419aa 100644
> --- a/drivers/target/iscsi/iscsi_target_nego.c
> +++ b/drivers/target/iscsi/iscsi_target_nego.c
> @@ -432,6 +432,9 @@ static void iscsi_target_sk_data_ready(struct sock *sk)
>         if (test_and_set_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags)) {
>                 write_unlock_bh(&sk->sk_callback_lock);
>                 pr_debug("Got LOGIN_FLAGS_READ_ACTIVE=1, conn: %p >>>>\n", conn);
> +               if (WARN_ON(iscsi_target_sk_data_ready = conn->orig_data_ready))
> +                       return;
> +               conn->orig_data_ready(sk);
>                 return;

This allows iscsi login to work for me.

I ran it against the target-pending for-next branch.

Re: iscsi target regression due to "tcp: remove prequeue support" patch

[Mike Christie]

On 01/18/2018 09:10 AM, Florian Westphal wrote:
>> It would indicate users providing their own ->sk_data_ready() callback
>> must be responsible for waking up a kthread context blocked on
>> sock_recvmsg(..., MSG_WAITALL), when a second ->sk_data_ready() is
>> received before the first sock_recvmsg(..., MSG_WAITALL) completes.
> 
> I agree, it looks like we need something like this?
> (not even build tested):
> 
> diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
> index b686e2ce9c0e..3723f8f419aa 100644
> --- a/drivers/target/iscsi/iscsi_target_nego.c
> +++ b/drivers/target/iscsi/iscsi_target_nego.c
> @@ -432,6 +432,9 @@ static void iscsi_target_sk_data_ready(struct sock *sk)
>         if (test_and_set_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags)) {
>                 write_unlock_bh(&sk->sk_callback_lock);
>                 pr_debug("Got LOGIN_FLAGS_READ_ACTIVE=1, conn: %p >>>>\n", conn);
> +               if (WARN_ON(iscsi_target_sk_data_ready == conn->orig_data_ready))
> +                       return;
> +               conn->orig_data_ready(sk);
>                 return;

This allows iscsi login to work for me.

I ran it against the target-pending for-next branch.