iSERT completions hung due to unavailable iscsit tag

iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju]

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.

Re: iSERT completions hung due to unavailable iscsit tag

[Sagi Grimberg]

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


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

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

Re: iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju]

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

Re: iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju]

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.

Re: iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju]

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.

Re: iSERT completions hung due to unavailable iscsit tag

[Krishnamraju Eraparaju]

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.

diff --git a/drivers/target/iscsi/iscsi_target.c
b/drivers/target/iscsi/iscsi_target.c
index 59379d6..d3347ab 100644
--- a/drivers/target/iscsi/iscsi_target.c
+++ b/drivers/target/iscsi/iscsi_target.c
@@ -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);
diff --git a/drivers/target/iscsi/iscsi_target_configfs.c
b/drivers/target/iscsi/iscsi_target_configfs.c
index 0fa1d57..32b3c64 100644
--- a/drivers/target/iscsi/iscsi_target_configfs.c
+++ b/drivers/target/iscsi/iscsi_target_configfs.c
@@ -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.

Re: iSERT completions hung due to unavailable iscsit tag

[Max Gurtovoy]

On 6/1/2020 4:46 PM, Krishnamraju Eraparaju 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.


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 ?


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