Re: iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju <krishna2@chelsio.com>]

On Wednesday, June 06/03/20, 2020 at 13:27:29 -0700, Sagi Grimberg wrote:
> 
> >Hi,
> >
> >I observe, iscsit_allocate_cmd() process waiting indefinitely for
> >'iscsit tag' to become available.
> >
> >Here is the scenario:
> >- at initiator, run "iozone -i 0 -I -+d -s 100000 -r 16384 -w" in an
> >   infinite loop.
> >- after few seconds, target fails to obtain 'tag' from
> >   sbitmap_queue_get(), while processing ISCSI_CTRL PDU via
> >isert_recv_done().
> >- then iscsit waits there for tag to become available, by calling
> >   schedule() in iscsit_wait_for_tag()
> >- and the process never scheduled back again, not sure why.
> 
> The trace shows only the failed login attempt that
> happened probably after what you are talking about.
> 
> Do you have a trace that shows your analysis?
> 
> >Due to this blockage the whole completion logic at iSER target went to
> >grinding halt, causing NOPOUT request timeouts at initator, and below
> >hung traces at target. Is this a known issue?
> 
> No, its not a known issue.
> 
> I was not able to reproduce it on my VM with siw...
Hi Sagi,

Thanks for looking into this issue.

I don't think this issue could be recreated easily with SIW driver, as
SIW may not pump enough traffic to exhaust the tags at iscsit. iw_cxgb4
helps recreate this issue quickly.

I have changed iscsit driver to recreate this issue quickly, over SIW.
Not sure the change is valid or not, but this recreates the exact issue.

diff --git a/drivers/target/iscsi/iscsi_target_nego.c
b/drivers/target/iscsi/iscsi_target_nego.c
index 685d771..b278702 100644
--- a/drivers/target/iscsi/iscsi_target_nego.c
+++ b/drivers/target/iscsi/iscsi_target_nego.c
@@ -1255,8 +1255,8 @@ int iscsi_target_locate_portal(
         * in per-cpu-ida tag allocation logic + small queue_depth.
         */
 alloc_tags:
-       tag_num = max_t(u32, ISCSIT_MIN_TAGS, queue_depth);
-       tag_num = (tag_num * 2) + ISCSIT_EXTRA_TAGS;
+       tag_num = 0x20; //hack to exhaust Tags quickly
        tag_size = sizeof(struct iscsi_cmd) +
conn->conn_transport->priv_size;

        ret = transport_alloc_session_tags(sess->se_sess, tag_num,
tag_size);

Run command iozone -i 0 -I -+d -s 90000 -r 16384 -w  (you may give
higher size for "-s" if are not able to recreate the issue)
====================================================
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e439000, iSCSI
opcode: 0x01, ITT: 0x0000001d, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0xffeadf11
write_va: 0xffff8d2415f68000
[  +0.000001] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000050] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 00000000824d7bc3 RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000007] isert: isert_get_dataout: Cmd: 00000000824d7bc3 posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e43f000, iSCSI
opcode: 0x01, ITT: 0x00000020, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0xf79eba11
write_va: 0xffff8d2415fe8000
[  +0.000001] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000052] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 00000000b66c6a25 RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000007] isert: isert_get_dataout: Cmd: 00000000b66c6a25 posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e445000, iSCSI
opcode: 0x01, ITT: 0x00000021, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0x949a4409
write_va: 0xffff8d2416468000
[  +0.000000] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000029] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 00000000186b1279 RDMA_READ
data_length: 249856 write_data_done: 8192
[  +0.000006] isert: isert_get_dataout: Cmd: 00000000186b1279 posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e44e000, iSCSI
opcode: 0x01, ITT: 0x00000022, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0x59fb5612
write_va: 0xffff8d24164a5000
[  +0.000001] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000032] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 00000000ffcf6232 RDMA_READ
data_length: 274432 write_data_done: 8192
[  +0.000005] isert: isert_get_dataout: Cmd: 00000000ffcf6232 posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000002] isert: isert_recv_done: DMA: 0xffff92c16e451000, iSCSI
opcode: 0x01, ITT: 0x00000023, flags: 0xa1 dlen: 8192
[  +0.000000] isert: isert_recv_done: ISER_WSV: write_stag: 0x6f90e912
write_va: 0xffff8d24164e8000
[  +0.000001] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000051] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 00000000d4a7e7cc RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000006] isert: isert_get_dataout: Cmd: 00000000d4a7e7cc posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000002] isert: isert_recv_done: DMA: 0xffff92c16e454000, iSCSI
opcode: 0x01, ITT: 0x00000024, flags: 0xa1 dlen: 8192
[  +0.000000] isert: isert_recv_done: ISER_WSV: write_stag: 0x47454916
write_va: 0xffff8d2416568000
[  +0.000001] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000051] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 0000000018f430df RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000009] isert: isert_get_dataout: Cmd: 0000000018f430df posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000002] isert: isert_rdma_read_done: Cmd 00000000c9c773ad
[  +0.000004] isert: isert_rdma_read_done: Cmd: 00000000c9c773ad
RDMA_READ comp calling execute_cmd
[  +0.000065] isert: isert_rdma_read_done: Cmd 00000000e7b453b8
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000e7b453b8
RDMA_READ comp calling execute_cmd
[  +0.000118] isert: isert_rdma_read_done: Cmd 000000002c56d447
[  +0.000003] isert: isert_rdma_read_done: Cmd: 000000002c56d447
RDMA_READ comp calling execute_cmd
[  +0.000067] isert: isert_rdma_read_done: Cmd 0000000081befe9b
[  +0.000004] isert: isert_rdma_read_done: Cmd: 0000000081befe9b
RDMA_READ comp calling execute_cmd
[  +0.000070] isert: isert_rdma_read_done: Cmd 000000003d4991f1
[  +0.000004] isert: isert_rdma_read_done: Cmd: 000000003d4991f1
RDMA_READ comp calling execute_cmd
[  +0.000137] isert: isert_rdma_read_done: Cmd 00000000d57c68cc
[  +0.000004] isert: isert_rdma_read_done: Cmd: 00000000d57c68cc
RDMA_READ comp calling execute_cmd
[  +0.000154] isert: isert_rdma_read_done: Cmd 00000000622c2213
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000622c2213
RDMA_READ comp calling execute_cmd
[  +0.000131] isert: isert_rdma_read_done: Cmd 000000009b2a9991
[  +0.000005] isert: isert_rdma_read_done: Cmd: 000000009b2a9991
RDMA_READ comp calling execute_cmd
[  +0.000064] isert: isert_rdma_read_done: Cmd 000000006277fe2f
[  +0.000002] isert: isert_rdma_read_done: Cmd: 000000006277fe2f
RDMA_READ comp calling execute_cmd
[  +0.000071] isert: isert_rdma_read_done: Cmd 00000000ba675bdd
[  +0.000004] isert: isert_rdma_read_done: Cmd: 00000000ba675bdd
RDMA_READ comp calling execute_cmd
[  +0.000138] isert: isert_rdma_read_done: Cmd 00000000b84dc06f
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000b84dc06f
RDMA_READ comp calling execute_cmd
[  +0.000134] isert: isert_rdma_read_done: Cmd 00000000b455581f
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000b455581f
RDMA_READ comp calling execute_cmd
[  +0.000139] isert: isert_rdma_read_done: Cmd 000000003c6cd07a
[  +0.000003] isert: isert_rdma_read_done: Cmd: 000000003c6cd07a
RDMA_READ comp calling execute_cmd
[  +0.000064] isert: isert_rdma_read_done: Cmd 000000007546787d
[  +0.000003] isert: isert_rdma_read_done: Cmd: 000000007546787d
RDMA_READ comp calling execute_cmd
[  +0.000072] isert: isert_rdma_read_done: Cmd 00000000b7b67720
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000b7b67720
RDMA_READ comp calling execute_cmd
[  +0.000131] isert: isert_rdma_read_done: Cmd 00000000163352e9
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000163352e9
RDMA_READ comp calling execute_cmd
[  +0.000138] isert: isert_rdma_read_done: Cmd 0000000068f2a18e
[  +0.000002] isert: isert_rdma_read_done: Cmd: 0000000068f2a18e
RDMA_READ comp calling execute_cmd
[  +0.000113] isert: isert_rdma_read_done: Cmd 00000000a73411ac
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000a73411ac
RDMA_READ comp calling execute_cmd
[  +0.000118] isert: __isert_create_send_desc: tx_desc 00000000cb753dbc
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb68a20 length: 76 lkey: 0x1936400
[  +0.000002] isert: isert_put_response: Posting SCSI Response
[  +0.000005] isert: __isert_create_send_desc: tx_desc 0000000076ae6083
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb69030 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 0000000000df1306
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb665c0 length: 76 lkey: 0x1936400
[  +0.000002] isert: isert_put_response: Posting SCSI Response
[  +0.000003] isert: __isert_create_send_desc: tx_desc 00000000c1fc9644
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb66bd0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000a5972477
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb671e0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000ff9f1de4
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb677f0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000d88a86a9
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb67e00 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 000000004552b346
lkey mismatch, fixing
[  +0.000002] isert: isert_send_done: Cmd 0000000036f41ece
[  +0.000001] isert: isert_unmap_tx_desc: unmap single for
tx_desc->dma_addr
[  +0.000001] isert: isert_put_cmd: Cmd 0000000036f41ece
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb68410 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: __isert_create_send_desc: tx_desc 00000000c6a54549
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb69640 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: __isert_create_send_desc: tx_desc 00000000fa96828a
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb69c50 length: 76 lkey: 0x1936400
[  +0.000000] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000b192faa5
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6a260 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 000000003cdfdcda
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6a870 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 000000000d8c8e53
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6ae80 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: isert_send_done: Cmd 0000000068c68afd
[  +0.000001] isert: __isert_create_send_desc: tx_desc 000000002bae438e
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6b490 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: isert_unmap_tx_desc: unmap single for
tx_desc->dma_addr
[  +0.000001] isert: __isert_create_send_desc: tx_desc 000000007a2e2413
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6baa0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: isert_put_cmd: Cmd 0000000068c68afd
[  +0.000001] isert: __isert_create_send_desc: tx_desc 0000000010cdeb9f
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb6c0b0 length: 76 lkey: 0x1936400
[  +0.000002] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000d2df7ba7
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb604c0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: __isert_create_send_desc: tx_desc 000000006a9e303e
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb60ad0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000f312b66f
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb610e0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000001] isert: __isert_create_send_desc: tx_desc 0000000092478beb
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb616f0 length: 76 lkey: 0x1936400
[  +0.000000] isert: isert_put_response: Posting SCSI Response
[  +0.000002] isert: __isert_create_send_desc: tx_desc 000000007795779b
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb61d00 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000335] isert: isert_rdma_read_done: Cmd 0000000084fba6ef
[  +0.000004] isert: isert_rdma_read_done: Cmd: 0000000084fba6ef
RDMA_READ comp calling execute_cmd
[  +0.000091] isert: __isert_create_send_desc: tx_desc 000000007dd73789
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb62310 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000220] isert: isert_rdma_read_done: Cmd 00000000202070d9
[  +0.000004] isert: isert_rdma_read_done: Cmd: 00000000202070d9
RDMA_READ comp calling execute_cmd
[  +0.000086] isert: __isert_create_send_desc: tx_desc 00000000a860fa0f
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb62920 length: 76 lkey: 0x1936400
[  +0.000002] isert: isert_put_response: Posting SCSI Response
[  +0.000205] isert: isert_rdma_read_done: Cmd 000000001b611453
[  +0.000005] isert: isert_rdma_read_done: Cmd: 000000001b611453
RDMA_READ comp calling execute_cmd
[  +0.000085] isert: __isert_create_send_desc: tx_desc 00000000578e552f
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb62f30 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000196] isert: isert_rdma_read_done: Cmd 000000002de94d9d
[  +0.000003] isert: isert_rdma_read_done: Cmd: 000000002de94d9d
RDMA_READ comp calling execute_cmd
[  +0.000074] isert: __isert_create_send_desc: tx_desc 00000000594dc732
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb63540 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000161] isert: isert_rdma_read_done: Cmd 000000009d010ac4
[  +0.000003] isert: isert_rdma_read_done: Cmd: 000000009d010ac4
RDMA_READ comp calling execute_cmd
[  +0.000075] isert: __isert_create_send_desc: tx_desc 00000000f5e0992e
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb63b50 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000147] isert: isert_rdma_read_done: Cmd 00000000824d7bc3
[  +0.000005] isert: isert_rdma_read_done: Cmd: 00000000824d7bc3
RDMA_READ comp calling execute_cmd
[  +0.000075] isert: __isert_create_send_desc: tx_desc 000000007a0c4472
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb64160 length: 76 lkey: 0x1936400
[  +0.000000] isert: isert_put_response: Posting SCSI Response
[  +0.000182] isert: isert_rdma_read_done: Cmd 00000000b66c6a25
[  +0.000003] isert: isert_rdma_read_done: Cmd: 00000000b66c6a25
RDMA_READ comp calling execute_cmd
[  +0.000074] isert: __isert_create_send_desc: tx_desc 000000008408d294
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb64770 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000068] isert: isert_rdma_read_done: Cmd 00000000186b1279
[  +0.000005] isert: isert_rdma_read_done: Cmd: 00000000186b1279
RDMA_READ comp calling execute_cmd
[  +0.000043] isert: __isert_create_send_desc: tx_desc 00000000d771cd58
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb64d80 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000111] isert: isert_rdma_read_done: Cmd 00000000ffcf6232
[  +0.000005] isert: isert_rdma_read_done: Cmd: 00000000ffcf6232
RDMA_READ comp calling execute_cmd
[  +0.000047] isert: __isert_create_send_desc: tx_desc 00000000e68d6957
lkey mismatch, fixing
[  +0.000002] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb65390 length: 76 lkey: 0x1936400
[  +0.000002] isert: isert_put_response: Posting SCSI Response
[  +0.000145] isert: isert_rdma_read_done: Cmd 00000000d4a7e7cc
[  +0.000004] isert: isert_rdma_read_done: Cmd: 00000000d4a7e7cc
RDMA_READ comp calling execute_cmd
[  +0.000082] isert: __isert_create_send_desc: tx_desc 000000001a916153
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb659a0 length: 76 lkey: 0x1936400
[  +0.000001] isert: isert_put_response: Posting SCSI Response
[  +0.000158] isert: isert_rdma_read_done: Cmd 0000000018f430df
[  +0.000003] isert: isert_rdma_read_done: Cmd: 0000000018f430df
RDMA_READ comp calling execute_cmd
[  +0.000074] isert: isert_recv_done: DMA: 0xffff92c16e457000, iSCSI
opcode: 0x01, ITT: 0x00000025, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0x7c097f0f
write_va: 0xffff8d24165e8000
[  +0.000000] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000074] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000002] isert: isert_get_dataout: Cmd: 0000000036f41ece RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000010] isert: isert_get_dataout: Cmd: 0000000036f41ece posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e45a000, iSCSI
opcode: 0x01, ITT: 0x00000028, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0x56b6ec0f
write_va: 0xffff8d2416668000
[  +0.000000] isert: isert_recv_done: ISER ISCSI_CTRL PDU
[  +0.000060] isert: isert_handle_scsi_cmd: Copy Immediate sg_nents: 2
imm_data_len: 8192
[  +0.000001] isert: isert_get_dataout: Cmd: 0000000068c68afd RDMA_READ
data_length: 524288 write_data_done: 8192
[  +0.000006] isert: isert_get_dataout: Cmd: 0000000068c68afd posted
RDMA_READ memory for ISER Data WRITE rc: 0
[  +0.000001] isert: isert_recv_done: DMA: 0xffff92c16e45d000, iSCSI
opcode: 0x01, ITT: 0x00000027, flags: 0xa1 dlen: 8192
[  +0.000001] isert: isert_recv_done: ISER_WSV: write_stag: 0xce2c20d1
write_va: 0xffff8d24166e8000


[  +0.000000] isert: isert_recv_done: ISER ISCSI_CTRL PDU ======> Hungs
at: recv_done()->iscsit_allocate_cmd()->schedule()


[  +0.000002] isert: __isert_create_send_desc: tx_desc 00000000a7c56808
lkey mismatch, fixing
[  +0.000001] isert: isert_init_tx_hdrs: Setup tx_sg[0].addr:
0xffff92c16eb65fb0 length: 76 lkey: 0x1936400
[  +0.000000] isert: isert_put_response: Posting SCSI Response
[ +10.224473] isert: isert_cma_handler: disconnected (10): status 0 id
00000000403c8045 np 00000000211da644
[  +0.000074] isert: isert_wait_conn: Starting conn 00000000a904f010
[  +0.000003] isert: isert_conn_terminate: Terminating conn
00000000a904f010 state 3
[  +2.008824] isert: isert_cma_handler: connect request (4): status 0 id
00000000e8b2a094 np 00000000211da644
[  +0.000002] isert: isert_connect_request: cma_id: 00000000e8b2a094,
portal: 00000000211da644
[  +0.000019] isert: isert_device_get: Found iser device
000000008276e2fd refcount 2
[  +0.000001] isert: isert_set_nego_params: Using initiator_depth: 128
[  +0.000000] isert: isert_set_nego_params: Using remote invalidation
[  +0.000001] isert: isert_comp_get: conn 00000000ee44cd70, using comp
000000006050e4e6 min_index: 1
[  +0.001285] isert: isert_login_post_recv: Setup sge: addr:
ffff92c1c3158000 length: 8268 0x01936400
[  +0.000075] isert: isert_cma_handler: established (9): status 0 id
00000000e8b2a094 np 00000000211da644
[  +0.000001] isert: isert_connected_handler: conn 00000000ee44cd70
[  +0.000001] isert: isert_connected_handler: np 00000000211da644: Allow
accept_np to continue
[  +0.000006] isert: isert_accept_np: Processing isert_conn:
00000000ee44cd70
[  +0.000019] isert: isert_get_login_rx: before login_req comp conn:
00000000ee44cd70
[  +0.999451] isert: isert_rx_login_req: conn 00000000ee44cd70
[  +0.000005] isert: isert_rx_login_req: Using login payload size: 488,
rx_buflen: 488 MAX_KEY_VALUE_PAIRS: 8192
[  +0.000003] isert: isert_get_login_rx: before login_comp conn:
0000000023ea8fab
[  +0.000002] isert: isert_get_login_rx: processing login->req:
000000008556731b
[  +0.000068] isert: isert_get_sup_prot_ops: conn 00000000ee44cd70 PI
offload disabled
[ +13.997880] isert: isert_cma_handler: disconnected (10): status 0 id
00000000e8b2a094 np 00000000211da644
[  +0.183884] iSCSI Login timeout on Network Portal 102.1.1.4:3261

> 
> 
> >Target:
> >[May 7 20:30] iSCSI Login timeout on Network Portal 102.1.1.6:3260
> >[May 7 20:33] kworker/dying (2185) used greatest stack depth: 11672
> >bytes left
> >[  +2.640115] kmemleak: 2 new suspected memory leaks (see
> >/sys/kernel/debug/kmemleak)
> 
> Can you output what kmemleak complains about?
I think, I got this memory leak with older kernels, sorry I did not
saved it.
Anyways, with latest kernels I don't see this memory leak. so you may
ignore this leak.
> 
> >[ +26.031050] INFO: task iscsi_np:8387 blocked for more than 122
> >seconds.
> >[  +0.000004]       Not tainted 5.7.0-rc2+ #2
> >[  +0.000001] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> >disables this message.
> >[  +0.000001] iscsi_np        D14304  8387      2 0x80004084
> >[  +0.000005] Call Trace:
> >[  +0.000008]  ? __schedule+0x274/0x5e0
> >[  +0.000003]  ? stack_trace_save+0x46/0x70
> >[  +0.000002]  schedule+0x45/0xb0
> >[  +0.000002]  schedule_timeout+0x1d6/0x290
> >[  +0.000001]  wait_for_completion+0x82/0xe0
> >[  +0.000007]  iscsi_check_for_session_reinstatement+0x205/0x260
> >[iscsi_target_mod]
> >[  +0.000004]  iscsi_target_do_login+0xe3/0x5c0 [iscsi_target_mod]
> >[  +0.000004]  iscsi_target_start_negotiation+0x4c/0xa0
> >[iscsi_target_mod]
> >[  +0.000004]  iscsi_target_login_thread+0x86f/0x1000 [iscsi_target_mod]
> >[  +0.000003]  kthread+0xf3/0x130
> >[  +0.000004]  ? iscsi_target_login_sess_out+0x1f0/0x1f0
> >[iscsi_target_mod]
> >[  +0.000001]  ? kthread_bind+0x10/0x10
> >[  +0.000002]  ret_from_fork+0x35/0x40
> >[  +0.000003] INFO: task iscsi_ttx:8863 blocked for more than 122
> >seconds.
> >[  +0.000001]       Not tainted 5.7.0-rc2+ #2
> >[  +0.000000] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> >disables this message.
> >[  +0.000001] iscsi_ttx       D14384  8863      2 0x80004084
> >[  +0.000003] Call Trace:
> >[  +0.000002]  ? __schedule+0x274/0x5e0
> >[  +0.000004]  ? c4iw_ib_modify_qp+0xf3/0x160 [iw_cxgb4]
> >[  +0.000002]  schedule+0x45/0xb0
> >[  +0.000002]  schedule_timeout+0x1d6/0x290
> >[  +0.000001]  wait_for_completion+0x82/0xe0
> >[  +0.000003]  __ib_drain_sq+0x147/0x170
> >[  +0.000002]  ? ib_sg_to_pages+0x1a0/0x1a0
> >[  +0.000003]  ib_drain_sq+0x6e/0x80
> >[  +0.000002]  ib_drain_qp+0x9/0x20
> >[  +0.000002]  isert_wait_conn+0x51/0x2c0 [ib_isert]
> >[  +0.000004]  iscsit_close_connection+0x14c/0x840 [iscsi_target_mod]
> >[  +0.000002]  ? __schedule+0x27c/0x5e0
> >[  +0.000004]  iscsit_take_action_for_connection_exit+0x79/0x100
> >[iscsi_target_mod]
> >[  +0.000003]  iscsi_target_tx_thread+0x160/0x200 [iscsi_target_mod]
> >[  +0.000004]  ? wait_woken+0x80/0x80
> >[  +0.000002]  kthread+0xf3/0x130
> >[  +0.000003]  ? iscsit_thread_get_cpumask+0x80/0x80 [iscsi_target_mod]
> >[  +0.000001]  ? kthread_bind+0x10/0x10
> >[  +0.000001]  ret_from_fork+0x35/0x40
> >[  +0.000003] NMI backtrace for cpu 7
> >[  +0.000002] CPU: 7 PID: 493 Comm: khungtaskd Not tainted 5.7.0-rc2+ #2
> >[  +0.000001] Hardware name: Supermicro X10SRA-F/X10SRA-F, BIOS 2.1a
> >10/24/2018
> >[  +0.000001] Call Trace:
> >[  +0.000003]  dump_stack+0x50/0x6b
> >[  +0.000002]  nmi_cpu_backtrace+0x9e/0xb0
> >[  +0.000003]  ? lapic_can_unplug_cpu+0x90/0x90
> >[  +0.000002]  nmi_trigger_cpumask_backtrace+0x9c/0xf0
> >[  +0.000003]  watchdog+0x310/0x4f0
> >[  +0.000002]  kthread+0xf3/0x130
> >[  +0.000002]  ? hungtask_pm_notify+0x40/0x40
> >[  +0.000001]  ? kthread_bind+0x10/0x10
> >[  +0.000001]  ret_from_fork+0x35/0x40
> >[  +0.000002] Sending NMI from CPU 7 to CPUs 0-6:
> >[  +0.000009] NMI backtrace for cpu 0 skipped: idling at
> >acpi_processor_ffh_cstate_enter+0x6f/0xc0
> >[  +0.000001] NMI backtrace for cpu 4 skipped: idling at
> >acpi_processor_ffh_cstate_enter+0x6f/0xc0
> >[  +0.000002] NMI backtrace for cpu 1 skipped: idling at
> >acpi_processor_ffh_cstate_enter+0x6f/0xc0
> >[  +0.000019] NMI backtrace for cpu 2 skipped: idling at
> >acpi_processor_ffh_cstate_enter+0x6f/0xc0
> >[  +0.000001] NMI backtrace for cpu 6 skipped: idling at
> >acpi_processor_ffh_cstate_enter+0x6f/0xc0
> >[  +0.000010] NMI backtrace for cpu 5
> >[  +0.000000] CPU: 5 PID: 4465 Comm: kworker/5:1H Not tainted 5.7.0-rc2+
> >#2
> >[  +0.000000] Hardware name: Supermicro X10SRA-F/X10SRA-F, BIOS 2.1a
> >10/24/2018
> >[  +0.000001] Workqueue: ib-comp-wq ib_cq_poll_work
> >[  +0.000000] RIP: 0010:__free_pages+0xe/0x60
> >
> >
> >Initiator:
> >[ 2002.689250]  connection5:0: ping timeout of 5 secs expired, recv
> >timeout 5, last rx 4296659424, last ping 4296664448, now 4296669696
> >[ 2002.689275]  connection5:0: detected conn error (1022)
> >
> >
> >
> >Thanks,
> >Krishna.
> >