[PATCH v4 0/2] iscsi-target: fix login error when receiving is too fast

[PATCH v4 0/2] iscsi-target: fix login error when receiving is too fast

[Hou Pu]

Hi,
We encountered "iSCSI Login negotiation failed" several times.
After enable debug log in iscsi_target_nego.c of iSCSI target.
Error shows:
  "Got LOGIN_FLAGS_READ_ACTIVE=1, conn: xxxxxxxxxx >>>>"

Patch 1 is trying to fix this problem. Please see comment in patch 1
for details.

Sorry for delay of v4. Version 3 of this patchset could be found here[1].

Changes from v4:
* In iscsi_target_do_login_rx(), call cancel_delayed_work() if it is final
  login pdu. Also call cancel_delayed_work() if current negotiation is failed.
  This is advised by Mike Christie. See below[1] for more details.

Changes from v3:
* Fix style problem found by checkpatch.pl.

Changes from v2:
* Improve comments in patch #1.
* Change bit possition of login_flags in patch #1.


[1]:
https://www.spinics.net/lists/target-devel/msg18281.html

Hou Pu (2):
  iscsi-target: fix login error when receiving is too fast
  iscsi-target: Fix inconsistent debug message in
    __iscsi_target_sk_check_close

 drivers/target/iscsi/iscsi_target_nego.c | 36 +++++++++++++++++++++++++++-----
 include/target/iscsi/iscsi_target_core.h |  9 ++++----
 2 files changed, 36 insertions(+), 9 deletions(-)

-- 
2.11.0

[PATCH v4 1/2] iscsi-target: fix login error when receiving is too fast

[Hou Pu]

iscsi_target_sk_data_ready() could be invoked indirectly
by iscsi_target_do_login_rx() from workqueue like following:

iscsi_target_do_login_rx()
  iscsi_target_do_login()
    iscsi_target_do_tx_login_io()
      iscsit_put_login_tx()
        iscsi_login_tx_data()
          tx_data()
            sock_sendmsg_nosec()
              tcp_sendmsg()
                release_sock()
                  sk_backlog_rcv()
                    tcp_v4_do_rcv()
                      tcp_data_ready()
                        iscsi_target_sk_data_ready()

At that time LOGIN_FLAGS_READ_ACTIVE is not cleared.
and iscsi_target_sk_data_ready will not read data
from the socket. And some iscsi initiator(i.e. libiscsi)
will wait forever for a reply.

LOGIN_FLAGS_READ_ACTIVE should be cleared early just after
doing the receive and before writing to the socket in
iscsi_target_do_login_rx.

But sad news is that LOGIN_FLAGS_READ_ACTIVE is also used
by sk_state_change to do login cleanup if a socket was closed
at login time. It is supposed to be cleared after the login
pdu is successfully processed and replied.

So introduce another flag LOGIN_FLAGS_WRITE_ACTIVE to cover
the transmit part so that sk_state_change could work well
and clear LOGIN_FLAGS_READ_ACTIVE early so that sk_data_ready
could also work.

While at here, use login_flags more efficient.

Signed-off-by: Hou Pu <houpu@bytedance.com>
---
 drivers/target/iscsi/iscsi_target_nego.c | 34 ++++++++++++++++++++++++++++----
 include/target/iscsi/iscsi_target_core.h |  9 +++++----
 2 files changed, 35 insertions(+), 8 deletions(-)

diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
index 685d771b51d4..10477e44d17b 100644
--- a/drivers/target/iscsi/iscsi_target_nego.c
+++ b/drivers/target/iscsi/iscsi_target_nego.c
@@ -625,13 +625,37 @@ static void iscsi_target_do_login_rx(struct work_struct *work)
 	pr_debug("iscsi_target_do_login_rx after rx_login_io, %p, %s:%d\n",
 			conn, current->comm, current->pid);
 
+	/*
+	 * LOGIN_FLAGS_READ_ACTIVE is cleared so that sk_data_ready
+	 * could be trigger again after this.
+	 *
+	 * LOGIN_FLAGS_WRITE_ACTIVE is cleared after we successfully
+	 * process a login pdu, so that sk_state_chage could do login
+	 * cleanup as needed if the socket is closed. If a delayed work is
+	 * ongoing (LOGIN_FLAGS_WRITE_ACTIVE or LOGIN_FLAGS_READ_ACTIVE),
+	 * sk_state_change will leave the cleanup to the delayed work or
+	 * it will schedule a delayed work to do cleanup.
+	 */
+	if (conn->sock) {
+		struct sock *sk = conn->sock->sk;
+
+		write_lock_bh(&sk->sk_callback_lock);
+		if (!test_bit(LOGIN_FLAGS_INITIAL_PDU, &conn->login_flags)) {
+			clear_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags);
+			set_bit(LOGIN_FLAGS_WRITE_ACTIVE, &conn->login_flags);
+		}
+		write_unlock_bh(&sk->sk_callback_lock);
+	}
+
 	rc = iscsi_target_do_login(conn, login);
 	if (rc < 0) {
 		goto err;
 	} else if (!rc) {
-		if (iscsi_target_sk_check_and_clear(conn, LOGIN_FLAGS_READ_ACTIVE))
+		if (iscsi_target_sk_check_and_clear(conn,
+						    LOGIN_FLAGS_WRITE_ACTIVE))
 			goto err;
 	} else if (rc == 1) {
+		cancel_delayed_work(&conn->login_work);
 		iscsi_target_nego_release(conn);
 		iscsi_post_login_handler(np, conn, zero_tsih);
 		iscsit_deaccess_np(np, tpg, tpg_np);
@@ -640,6 +664,7 @@ static void iscsi_target_do_login_rx(struct work_struct *work)
 
 err:
 	iscsi_target_restore_sock_callbacks(conn);
+	cancel_delayed_work(&conn->login_work);
 	iscsi_target_login_drop(conn, login);
 	iscsit_deaccess_np(np, tpg, tpg_np);
 }
@@ -670,9 +695,10 @@ static void iscsi_target_sk_state_change(struct sock *sk)
 	state = __iscsi_target_sk_check_close(sk);
 	pr_debug("__iscsi_target_sk_close_change: state: %d\n", state);
 
-	if (test_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags)) {
-		pr_debug("Got LOGIN_FLAGS_READ_ACTIVE=1 sk_state_change"
-			 " conn: %p\n", conn);
+	if (test_bit(LOGIN_FLAGS_READ_ACTIVE, &conn->login_flags) ||
+	    test_bit(LOGIN_FLAGS_WRITE_ACTIVE, &conn->login_flags)) {
+		pr_debug("Got LOGIN_FLAGS_{READ|WRITE}_ACTIVE=1"
+			 " sk_state_change conn: %p\n", conn);
 		if (state)
 			set_bit(LOGIN_FLAGS_CLOSED, &conn->login_flags);
 		write_unlock_bh(&sk->sk_callback_lock);
diff --git a/include/target/iscsi/iscsi_target_core.h b/include/target/iscsi/iscsi_target_core.h
index 591cd9e4692c..844bef255e89 100644
--- a/include/target/iscsi/iscsi_target_core.h
+++ b/include/target/iscsi/iscsi_target_core.h
@@ -566,10 +566,11 @@ struct iscsi_conn {
 	struct socket		*sock;
 	void			(*orig_data_ready)(struct sock *);
 	void			(*orig_state_change)(struct sock *);
-#define LOGIN_FLAGS_READ_ACTIVE		1
-#define LOGIN_FLAGS_CLOSED		2
-#define LOGIN_FLAGS_READY		4
-#define LOGIN_FLAGS_INITIAL_PDU		8
+#define LOGIN_FLAGS_READY		0
+#define LOGIN_FLAGS_INITIAL_PDU		1
+#define LOGIN_FLAGS_READ_ACTIVE		2
+#define LOGIN_FLAGS_WRITE_ACTIVE	3
+#define LOGIN_FLAGS_CLOSED		4
 	unsigned long		login_flags;
 	struct delayed_work	login_work;
 	struct iscsi_login	*login;
-- 
2.11.0

[PATCH v4 2/2] iscsi-target: Fix inconsistent debug message in __iscsi_target_sk_check_close

[Hou Pu]

The commit 25cdda95fda7 ("iscsi-target: Fix initial login PDU
asynchronous socket close OOPs") changed the return value of
__iscsi_target_sk_check_close. But the pr_debug is still printing
FALSE when returning TRUE which is a little confusing.

Signed-off-by: Hou Pu <houpu@bytedance.com>
---
 drivers/target/iscsi/iscsi_target_nego.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/target/iscsi/iscsi_target_nego.c b/drivers/target/iscsi/iscsi_target_nego.c
index 10477e44d17b..701c008d6bd5 100644
--- a/drivers/target/iscsi/iscsi_target_nego.c
+++ b/drivers/target/iscsi/iscsi_target_nego.c
@@ -481,7 +481,7 @@ static bool __iscsi_target_sk_check_close(struct sock *sk)
 {
 	if (sk->sk_state == TCP_CLOSE_WAIT || sk->sk_state == TCP_CLOSE) {
 		pr_debug("__iscsi_target_sk_check_close: TCP_CLOSE_WAIT|TCP_CLOSE,"
-			"returning FALSE\n");
+			"returning TRUE\n");
 		return true;
 	}
 	return false;
-- 
2.11.0

Re: [PATCH v4 0/2] iscsi-target: fix login error when receiving is too fast

[Mike Christie]

On 7/16/20 5:02 AM, Hou Pu wrote:
> Hi,
> We encountered "iSCSI Login negotiation failed" several times.
> After enable debug log in iscsi_target_nego.c of iSCSI target.
> Error shows:
>   "Got LOGIN_FLAGS_READ_ACTIVE=1, conn: xxxxxxxxxx >>>>"
> 
> Patch 1 is trying to fix this problem. Please see comment in patch 1
> for details.
> 
> Sorry for delay of v4. Version 3 of this patchset could be found here[1].
> 
> Changes from v4:
> * In iscsi_target_do_login_rx(), call cancel_delayed_work() if it is final
>   login pdu. Also call cancel_delayed_work() if current negotiation is failed.
>   This is advised by Mike Christie. See below[1] for more details.
> 
> Changes from v3:
> * Fix style problem found by checkpatch.pl.
> 
Ah sorry, I thought I replied a little later about my concerns being overly paranoid and your patch being ok. I don't see it on the list so not sure what happened.

If you are still not liking the cancel call, I'm ok with v3. Add my reviewed by to either version you prefer.

Reviewed-by: Mike Christie <michael.christie@oracle.com>

Re: [PATCH v4 0/2] iscsi-target: fix login error when receiving is too fast

[Hou Pu]

On 2020/7/26 10:58 上午, Mike Christie wrote:
> On 7/16/20 5:02 AM, Hou Pu wrote:
>> Hi,
>> We encountered "iSCSI Login negotiation failed" several times.
>> After enable debug log in iscsi_target_nego.c of iSCSI target.
>> Error shows:
>>    "Got LOGIN_FLAGS_READ_ACTIVE=1, conn: xxxxxxxxxx >>>>"
>>
>> Patch 1 is trying to fix this problem. Please see comment in patch 1
>> for details.
>>
>> Sorry for delay of v4. Version 3 of this patchset could be found here[1].
>>
>> Changes from v4:
>> * In iscsi_target_do_login_rx(), call cancel_delayed_work() if it is final
>>    login pdu. Also call cancel_delayed_work() if current negotiation is failed.
>>    This is advised by Mike Christie. See below[1] for more details.
>>
>> Changes from v3:
>> * Fix style problem found by checkpatch.pl.
>>
> Ah sorry, I thought I replied a little later about my concerns being overly paranoid and your patch being ok. I don't see it on the list so not sure what happened.
> 
> If you are still not liking the cancel call, I'm ok with v3. Add my reviewed by to either version you prefer.
> 
> Reviewed-by: Mike Christie <michael.christie@oracle.com>
> 

It took me some time to understand how workqueue works and make sure
it is safe to cancel it. So it is delayed between v3 and v4. Sorry
for that.

I think it is necessary to cancel delayed work as your suggestion.

Thanks,
Hou

Re: [PATCH v4 0/2] iscsi-target: fix login error when receiving is too fast

[Martin K. Petersen]

On Thu, 16 Jul 2020 06:02:10 -0400, Hou Pu wrote:

> We encountered "iSCSI Login negotiation failed" several times.
> After enable debug log in iscsi_target_nego.c of iSCSI target.
> Error shows:
>   "Got LOGIN_FLAGS_READ_ACTIVE=1, conn: xxxxxxxxxx >>>>"
> 
> Patch 1 is trying to fix this problem. Please see comment in patch 1
> for details.
> 
> [...]

Applied to 5.9/scsi-queue, thanks!

[1/2] scsi: target: iscsi: Fix login error when receiving
      https://git.kernel.org/mkp/scsi/c/4e108d4f2816
[2/2] scsi: target: iscsi: Fix inconsistent debug message
      https://git.kernel.org/mkp/scsi/c/df2de6f28629

-- 
Martin K. Petersen	Oracle Linux Engineering