iSERT completions hung due to unavailable iscsit tag

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.

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?

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

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?

No, its not a known issue.

I was not able to reproduce it on my VM with siw...

Can you output what kmemleak complains about?

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.

b/drivers/target/iscsi/iscsi_target_nego.c
index 685d771..b278702 100644

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

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.

Hi Sagi/Max Gurtovoy,

Please suggest what else to look into for debugging this issue further.

Sagi, by any chance were you able to repoduce this on your VM(with SIW) by reducing "tag_num" in iscsit?

I think, this issue will hit with any provider driver if we somehow let the recv_done() handler reach the below "schedule()", while performing IO.

------
static int iscsit_wait_for_tag(struct se_session *se_sess, int state, int *cpup)

{
	int tag = -1;
	DEFINE_SBQ_WAIT(wait);
	struct sbq_wait_state *ws;
	struct sbitmap_queue *sbq;

	if (state == TASK_RUNNING)
		return tag;

	sbq = &se_sess->sess_tag_pool;
	ws = &sbq->ws[0];
	for (;;) {
		sbitmap_prepare_to_wait(sbq, ws, &wait, state);
		if (signal_pending_state(state, current))
			break;
		tag = sbitmap_queue_get(sbq, cpup);
		if (tag >= 0)
			break;
			
			
			
		schedule();		<======
		
		
		
	}

	sbitmap_finish_wait(sbq, ws, &wait);
	return tag;
}

Thanks,
Krishna.

Hi Bart,

Looks like this issue belongs iscsit as the hung is at schedule() in iscsit_wait_for_tag(), as I mentioned in my initial post. This issue is observed with both iWARP and ROCE adapter drivers.

Note that this issue will occur only if the disk(I used RAMDISK) size is 511MB or below. Even 512MB will not recreate.

Thanks,
Krishna.

Hi Sagi,

I assume you are using SIW on both target and initiator.

And I belive you have a workaround something like below, because existing iSER target won't work with SIW as both ISCSI_TCP and ISCSI_INFINIBAND transports tries to listen on same IP:PPORT.

b/drivers/target/iscsi/iscsi_target.c
index 59379d6..d3347ab 100644

@@ -739,14 +739,12 @@ static int __init iscsi_target_init_module(void)
 		goto ooo_out;
 	}
 
-	iscsit_register_transport(&iscsi_target_transport);
 
 	if (iscsit_load_discovery_tpg() < 0)
 		goto r2t_out;
 
 	return ret;
 r2t_out:
-	iscsit_unregister_transport(&iscsi_target_transport);
 	kmem_cache_destroy(lio_r2t_cache);
 ooo_out:
 	kmem_cache_destroy(lio_ooo_cache);

@@ -769,7 +767,6 @@ static int __init iscsi_target_init_module(void)
 static void __exit iscsi_target_cleanup_module(void)
 {
 	iscsit_release_discovery_tpg();
-	iscsit_unregister_transport(&iscsi_target_transport);
 	kmem_cache_destroy(lio_qr_cache);
 	kmem_cache_destroy(lio_dr_cache);
 	kmem_cache_destroy(lio_ooo_cache);

b/drivers/target/iscsi/iscsi_target_configfs.c
index 0fa1d57..32b3c64 100644

@@ -234,7 +234,7 @@ static struct se_tpg_np *lio_target_call_addnptotpg(
 	 *
 	 */
 	tpg_np = iscsit_tpg_add_network_portal(tpg, &sockaddr, NULL,
-				ISCSI_TCP);
+				ISCSI_INFINIBAND);
 	if (IS_ERR(tpg_np)) {
 		iscsit_put_tpg(tpg);
 		return ERR_CAST(tpg_np);

someone may ask iwpmd should detect that ISCSI_TCP is already using that same port and should map to other available port from tcp portspace, but this hold true only for hard iWARP case, for SIW case, iwpmd does not perfrom any mapping as SIW runs on top of TCP kernel sockets.

Please share if you are using some other workaround to handle this issue.

Thanks,
Krishna.

can you increase the debug level on the target ?

and share the logs in initiator side as well ?

Seems that there is some reconnection that caused by io timeout.

Also, is the drain_qp function of the iw_cxgb4 finished successfully ?