On 2/23/2015 10:34 AM, Nicholas A. Bellinger wrote:
On Sun, 2015-02-22 at 18:36 +0200, Sagi Grimberg wrote:
On 2/21/2015 9:54 AM, Nicholas A. Bellinger wrote:
Hi Sagi,
Apologies for the delayed response.. Comments below.
On Sat, 2015-02-14 at 12:21 +0200, Sagi Grimberg wrote:
On 2/12/2015 10:47 AM, Nicholas A. Bellinger wrote:
On Wed, 2015-02-11 at 10:17 +0200, Sagi Grimberg wrote:
Hey Nic,
So Our QA guys recently stepped on this bug when performing stress
login-logout from a single initiator to 10 targets each exposed over
4 portals, so overall 40 sessions (needless to say we are talking on
iser...). So there are lots of logins in parallel with lots of logouts.
It seems that the connection termination causes iscsi_tx_thread to
access the connection after it is freed or something (list corruption
probably coming from iscsit_handle_immediate_queue or
iscsit_handle_response_queue, and NULL deref coming from
iscsit_take_action_for_connection_exit).
Note, isert_wait_conn waits for session commands and QP flush which is
normally pretty fast, the conn termination is done in a work that waits
for DISCONNECTED event which might take longer (which is why we do it
outside wait_conn context to avoid blocking it).
I didn't get too far with this until now, do you have any idea on what
might have happened?
Mmm, it looks like iscsit_take_action_for_connection_exit() in TX thread
context is calling iscsi_close_connection() after hitting the following
check in iscsi_target_erl0.c:
if (conn->conn_state == TARG_CONN_STATE_IN_LOGOUT) {
spin_unlock_bh(&conn->state_lock);
iscsit_close_connection(conn);
return;
}
.. once iscsi_close_connection() has already being called earlier by
iser-target code.
Not sure I understand where iscsit_close_connection is called earlier
by iser target. The iser code usually only notifies any problems to the
iscsi layer to do it's thing.
Care to explain how iscsit_close_connection might be called twice?
It appears iscsit_close_connection() is getting invoked first from
iscsi_trx context after isert_cq_comp_err() has previously called
iscsit_cause_connection_reinstatement() to force a connection failure to
occur during explicit logout + ISCSI_LOGOUT_REASON_CLOSE_SESSION
operation.
Yes, that is correct.
You can tell because isert_wait_conn() + isert_wait4cmds() debug output
appears before list_del corruption in iscsi_ttx context, which can only
be invoked via iscsit_close_connection() -> transport->wait_for_conn()
-> isert_wait_conn().
Given the fact that there are lots of connections tearing down in
parallel, I wouldn't rely on the proximity of these debug prints to
the stack trace.
Once iscsi_ttx context runs, it's hitting the TARG_CONN_STATE_IN_LOGOUT
state check in iscsit_take_action_for_connection_exit() and re-invokes
iscsit_close_connection(), after iscsit_logout_closesession() from
isert_rx_completion() context handles REASON_CLOSE_SESSION and changed
connection state to IN_LOGOUT, but before the logout response was posted
and successfully completed in isert_do_control_comp().
iscsit_take_action_for_connection_exit() is invoked both by RX/TX
threads. But only one should get to iscsit_close_connection() since
conn->connection_exit is set under conn->state_lock. I'd say that if
iscsit_close_connection() was invoked twice, the bug is in
iscsit_take_action_for_connection_exit() isn't it?
Sorry, yes.
After looking at this further, I think the previous isert_cq_comp_err()
patch still makes sense for the special logout response failure case,
but as you've noted it does not address root cause of the original
OOPsen.
I'm now thinking it's related to complete(conn->conn_logout_comp)
happening the start of iscsit_close_connection() (as originally intended
for non-iser logout response failure case), that is causing
isert_wait4logout() to immediately complete instead of allowing
iscsit_logout_post_handler() to perform complete(conn->conn_logout_comp)
after completion interrupt -> isert_do_control_comp() happens.
This could result in iscsit_release_commands_from_conn() corrupting
conn_cmd_list list when attempting to release the logout response
before/during iser logout response completion interrupt handling.
Here's a quick patch to test the theory.
--nab
diff --git a/drivers/target/iscsi/iscsi_target.c b/drivers/target/iscsi/iscsi_target.c
index 50bad55..ddbd022 100644
--- a/drivers/target/iscsi/iscsi_target.c
+++ b/drivers/target/iscsi/iscsi_target.c
@@ -4256,11 +4256,12 @@ int iscsit_close_connection(
pr_debug("Closing iSCSI connection CID %hu on SID:"
" %u\n", conn->cid, sess->sid);
/*
- * Always up conn_logout_comp just in case the RX Thread is sleeping
- * and the logout response never got sent because the connection
- * failed.
+ * Always up conn_logout_comp for the traditional TCP case just in case
+ * the RX Thread in iscsi_target_rx_opcode() is sleeping and the logout
+ * response never got sent because the connection failed.
*/
- complete(&conn->conn_logout_comp);
+ if (conn->conn_transport->transport_type == ISCSI_TCP)
+ complete(&conn->conn_logout_comp);
iscsi_release_thread_set(conn);
This does seem to make the list corruption go away. I increased the
session count to ~120 doing login/logout loop and at some point I am in
a point where I have 16066 iscsi_ttx and 16064 iscsi_trx threads
causing me to fail any other kthread creation (see dump_stack).
CPU: 12 PID: 22517 Comm: iscsi_ttx Tainted: G E 3.19.0-rc1+ #34
Hardware name: Supermicro SYS-1027R-WRF/X9DRW, BIOS 3.0a 08/08/2013
0000000000000000 ffff8804469dfdc8 ffffffff8153805c ffff8804469dfe58
ffff8803a5e05700 ffff8804469dfdf8 ffffffffa053b4fe ffff8803b1e95028
ffff8803b1e95000 ffff8803b1e95000 ffff8804469dfe58 ffff8804469dfe08
Call Trace:
[<ffffffff8153805c>] dump_stack+0x48/0x5c
[<ffffffffa053b4fe>] iscsi_allocate_thread_sets+0x21e/0x280
[iscsi_target_mod]
[<ffffffffa053b59a>] iscsi_check_to_add_additional_sets+0x3a/0x40
[iscsi_target_mod]
[<ffffffffa053b691>] iscsi_tx_thread_pre_handler+0xf1/0x170
[iscsi_target_mod]
[<ffffffffa054e0a7>] iscsi_target_tx_thread+0x47/0x220 [iscsi_target_mod]
[<ffffffff81538493>] ? __schedule+0x333/0x620
[<ffffffffa054e060>] ? iscsit_handle_snack+0x180/0x180 [iscsi_target_mod]
[<ffffffff8106ac5e>] kthread+0xce/0xf0
[<ffffffff8106ab90>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8153beec>] ret_from_fork+0x7c/0xb0
[<ffffffff8106ab90>] ? kthread_freezable_should_stop+0x70/0x70
Unable to start iscsi_target_tx_thread
For some reason the iscsi extra thread sets are not cleaned up well
and/or not reused from inactive list...
Any thoughts?
Sagi.
--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
