Re: Connection errors with ISER IO

[Potnuri Bharat Teja <bharat@chelsio.com>]

[-- Attachment #1: Type: text/plain, Size: 2246 bytes --]

On Wednesday, February 02/26/20, 2020 at 10:22:03 -0800, Sagi Grimberg wrote:
> 
> >Hi All,
> >I observe connection errors almost immediately after I start iozone over iser
> >luns. Atached are the connection error and hung task traces on initator and
> >target respecively.
> >Interestingly, I see connection errors only if LUN size is less than 512MB.
> >In my case I could consistently reproduce the issue with 511MB LUN and 300MB
> >lun size. Connections errors are not seen if I create 512MB or greated LUN.
> 
> Can you share log output on the target to before hung tasks?

Sure, Attached are the target and initiator dmesg logs.
> 
> >Further, after the connection errors, I noticed that the poll work queue is
> >stuck and never processes drain CQE resulting in hung tasks on the target side.
> 
> Is the drain CQE actually generated?
> 

Yes it is generated. I was able to track it with prints until queue_work() in
ib_cq_completion_workqueue(). Work Function ib_cq_poll_work() is never getting
scheduled. Therefore, I see drain CQE unpolled and hung task due to
__ib_drain_sq() waiting forever for complete() to be called from drain CQE
done() handler.

> >I tried changing the CQ poll workqueue to be UNBOUND but it did not fix the issue.
> >
> >Here is what my test does:
> >Create 8 targets with 511MB lun each, login and format disks to ext3, mount the
> >disks and run iozone over them.
> >#iozone -a -I -+d -g 256m
> 
> Does it happen specifically with iozone? or can dd/fio also
> reproduce this issue? on which I/O pattern do you see the issue?
>
I see it with iozone. I am trying with fio, shall soon update.
I see issue with at iosizes around 128k/256k block sizes of iozone. Its not 
consistent.
> >I am not sure how LUN size could cause the connection errors. I appreciate any
> >inputs on this.
> 
> I imagine that a single LUN is enough to reproduce the issue?
> 

yes, attached is the target conf.
> btw, I tried reproducing the issue with rxe (couldn't setup an iser
> listener with siw) in 2 VMs on my laptop using lio to a file backend but
> I cannot reproduce the issue..
I see the issue quickly with 40G/25G links. I have not seen the issue on a 100G 
link. BTW i a trying iwarp(T6/t5)

Thanks for looking into it.


[-- Attachment #2: dmesg_target.txt --]
[-- Type: text/plain, Size: 18836 bytes --]


################################ instance 1 ####################################################################
[  565.017867] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  566.272672] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  567.604472] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  569.079390] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  570.495877] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  572.164414] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  573.781992] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  575.401893] Rounding down aligned max_sectors from 4294967295 to 4294967288
[  611.563586] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  612.612316] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  613.666468] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  614.728169] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  615.795149] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  616.880035] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  617.964017] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  619.058387] iSCSI/iqn.1994-05.com.redhat:ac43382b2495: Unsupported SCSI Opcode 0xa3, sending CHECK_CONDITION.
[  810.389042] perf: interrupt took too long (2514 > 2500), lowering kernel.perf_event_max_sample_rate to 79000
[  918.231361] perf: interrupt took too long (3155 > 3142), lowering kernel.perf_event_max_sample_rate to 63000
[  978.745219] iSCSI Login timeout on Network Portal 10.0.2.2:3260
[ 1108.284624] INFO: task iscsi_np:10868 blocked for more than 122 seconds.
[ 1108.285623]       Not tainted 5.4.0+ #1
[ 1108.286358] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1108.287202] iscsi_np        D    0 10868      2 0x80004004
[ 1108.288091] Call Trace:
[ 1108.289004]  ? __schedule+0x2cd/0x8c0
[ 1108.289858]  schedule+0x40/0xc0
[ 1108.290746]  schedule_timeout+0x1e4/0x310
[ 1108.291630]  ? find_held_lock+0x38/0xa0
[ 1108.292392]  ? wait_for_completion+0x126/0x190
[ 1108.293121]  wait_for_completion+0x12e/0x190
[ 1108.293986]  ? wake_up_q+0x70/0x70
[ 1108.294884]  iscsi_check_for_session_reinstatement+0x1dd/0x270 [iscsi_target_mod]
[ 1108.295720]  iscsi_target_do_login+0xe8/0x5d0 [iscsi_target_mod]
[ 1108.296520]  iscsi_target_start_negotiation+0x51/0xa0 [iscsi_target_mod]
[ 1108.297285]  iscsi_target_login_thread+0x93d/0x1100 [iscsi_target_mod]
[ 1108.298114]  kthread+0x106/0x140
[ 1108.298974]  ? iscsi_target_login_sess_out+0x200/0x200 [iscsi_target_mod]
[ 1108.299825]  ? kthread_bind+0x10/0x10
[ 1108.300670]  ret_from_fork+0x3a/0x50
[ 1108.301385] INFO: task iscsi_trx:11133 blocked for more than 122 seconds.
[ 1108.302152]       Not tainted 5.4.0+ #1
[ 1108.302985] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1108.303832] iscsi_trx       D    0 11133      2 0x80004004
[ 1108.304687] Call Trace:
[ 1108.305413]  ? __schedule+0x2cd/0x8c0
[ 1108.306192]  schedule+0x40/0xc0
[ 1108.307022]  schedule_timeout+0x1e4/0x310
[ 1108.307857]  ? find_held_lock+0x38/0xa0
[ 1108.308611]  ? wait_for_completion+0x126/0x190
[ 1108.309321]  wait_for_completion+0x12e/0x190
[ 1108.310067]  ? wake_up_q+0x70/0x70
[ 1108.310892]  __ib_drain_sq+0x196/0x1d0 [ib_core]
[ 1108.311596]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[ 1108.312275]  ? wait_for_completion+0x49/0x190
[ 1108.312941]  ib_drain_qp+0xe/0x30 [ib_core]
[ 1108.313633]  isert_wait_conn+0x5e/0x330 [ib_isert]
[ 1108.314298]  ? __local_bh_enable_ip+0x80/0xf0
[ 1108.315040]  iscsit_close_connection+0x156/0x8f0 [iscsi_target_mod]
[ 1108.315827]  ? __local_bh_enable_ip+0x80/0xf0
[ 1108.316513]  iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod]
[ 1108.317191]  iscsi_target_rx_thread+0xdf/0xf0 [iscsi_target_mod]
[ 1108.317903]  kthread+0x106/0x140
[ 1108.318572]  ? iscsi_target_tx_thread+0x210/0x210 [iscsi_target_mod]
[ 1108.319209]  ? kthread_bind+0x10/0x10
[ 1108.319893]  ret_from_fork+0x3a/0x50
[ 1108.320658] 
Showing all locks held in the system:
[ 1108.321889] 1 lock held by khungtaskd/137:
[ 1108.322536]  #0: ffffffff91289ae0 (rcu_read_lock){....}, at: debug_show_all_locks+0xe/0x1a0
[ 1108.323187] 2 locks held by bash/1640:
[ 1108.323849]  #0: ffff9f538f2b30a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[ 1108.324618]  #1: ffffb2a50cd532f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[ 1108.325288] 1 lock held by dmesg/11123:
[ 1108.325984] 2 locks held by kworker/u53:5/11156:
[ 1108.326746]  #0: ffff9f3b95b39d48 ((wq_completion)ib-comp-unb-wq){+.+.}, at: process_one_work+0x18c/0x590
[ 1108.327432]  #1: ffffb2a50cd67e50 ((work_completion)(&cq->work)){+.+.}, at: process_one_work+0x18c/0x590

[ 1108.328962] =============================================
[ 1231.168185] INFO: task iscsi_np:10868 blocked for more than 245 seconds.
[ 1231.169019]       Not tainted 5.4.0+ #1
[ 1231.169937] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1231.170700] iscsi_np        D    0 10868      2 0x80004004
[ 1231.171584] Call Trace:
[ 1231.172475]  ? __schedule+0x2cd/0x8c0
[ 1231.173322]  schedule+0x40/0xc0
[ 1231.174204]  schedule_timeout+0x1e4/0x310
[ 1231.174946]  ? find_held_lock+0x38/0xa0
[ 1231.175761]  ? wait_for_completion+0x126/0x190
[ 1231.176631]  wait_for_completion+0x12e/0x190
[ 1231.177435]  ? wake_up_q+0x70/0x70
[ 1231.178190]  iscsi_check_for_session_reinstatement+0x1dd/0x270 [iscsi_target_mod]
[ 1231.178929]  iscsi_target_do_login+0xe8/0x5d0 [iscsi_target_mod]
[ 1231.179729]  iscsi_target_start_negotiation+0x51/0xa0 [iscsi_target_mod]
[ 1231.180564]  iscsi_target_login_thread+0x93d/0x1100 [iscsi_target_mod]
[ 1231.181383]  kthread+0x106/0x140
[ 1231.182238]  ? iscsi_target_login_sess_out+0x200/0x200 [iscsi_target_mod]
[ 1231.182963]  ? kthread_bind+0x10/0x10
[ 1231.183728]  ret_from_fork+0x3a/0x50
[ 1231.184539] INFO: task iscsi_trx:11133 blocked for more than 245 seconds.
[ 1231.185285]       Not tainted 5.4.0+ #1
[ 1231.185973] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1231.186675] iscsi_trx       D    0 11133      2 0x80004004
[ 1231.187464] Call Trace:
[ 1231.188260]  ? __schedule+0x2cd/0x8c0
[ 1231.188959]  schedule+0x40/0xc0
[ 1231.189750]  schedule_timeout+0x1e4/0x310
[ 1231.190468]  ? find_held_lock+0x38/0xa0
[ 1231.191248]  ? wait_for_completion+0x126/0x190
[ 1231.191923]  wait_for_completion+0x12e/0x190
[ 1231.192655]  ? wake_up_q+0x70/0x70
[ 1231.193425]  __ib_drain_sq+0x196/0x1d0 [ib_core]
[ 1231.194121]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[ 1231.194750]  ? wait_for_completion+0x49/0x190
[ 1231.195514]  ib_drain_qp+0xe/0x30 [ib_core]
[ 1231.196253]  isert_wait_conn+0x5e/0x330 [ib_isert]
[ 1231.196891]  ? __local_bh_enable_ip+0x80/0xf0
[ 1231.197628]  iscsit_close_connection+0x156/0x8f0 [iscsi_target_mod]
[ 1231.198282]  ? __local_bh_enable_ip+0x80/0xf0
[ 1231.198922]  iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod]
[ 1231.199653]  iscsi_target_rx_thread+0xdf/0xf0 [iscsi_target_mod]
[ 1231.200392]  kthread+0x106/0x140
[ 1231.200992]  ? iscsi_target_tx_thread+0x210/0x210 [iscsi_target_mod]
[ 1231.201696]  ? kthread_bind+0x10/0x10
[ 1231.202326]  ret_from_fork+0x3a/0x50
[ 1231.202937] 
Showing all locks held in the system:
[ 1231.204191] 1 lock held by khungtaskd/137:
[ 1231.204781]  #0: ffffffff91289ae0 (rcu_read_lock){....}, at: debug_show_all_locks+0xe/0x1a0
[ 1231.205479] 2 locks held by bash/1640:
[ 1231.206080]  #0: ffff9f538f2b30a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[ 1231.206691]  #1: ffffb2a50cd532f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[ 1231.207398] 2 locks held by bash/1705:
[ 1231.208013]  #0: ffff9f3b81afd0a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[ 1231.208766]  #1: ffffb2a50d3432f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[ 1231.209463] 2 locks held by kworker/u53:5/11156:
[ 1231.210125]  #0: ffff9f3b95b39d48 ((wq_completion)ib-comp-unb-wq){+.+.}, at: process_one_work+0x18c/0x590
[ 1231.210816]  #1: ffffb2a50cd67e50 ((work_completion)(&cq->work)){+.+.}, at: process_one_work+0x18c/0x590
[ 1231.211508] 1 lock held by updatedb/11300:
[ 1231.212291]  #0: ffff9f3a2b3f8cc8 (&type->i_mutex_dir_key#6){++++}, at: lookup_slow+0x27/0x50

[ 1231.213765] =============================================

[ 1354.051832] INFO: task iscsi_np:10868 blocked for more than 368 seconds.
[ 1354.052700]       Not tainted 5.4.0+ #1
[ 1354.053427] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1354.054176] iscsi_np        D    0 10868      2 0x80004004
[ 1354.054925] Call Trace:
[ 1354.055811]  ? __schedule+0x2cd/0x8c0
[ 1354.056544]  schedule+0x40/0xc0
[ 1354.057393]  schedule_timeout+0x1e4/0x310
[ 1354.058140]  ? find_held_lock+0x38/0xa0
[ 1354.058867]  ? wait_for_completion+0x126/0x190
[ 1354.059589]  wait_for_completion+0x12e/0x190
[ 1354.060406]  ? wake_up_q+0x70/0x70
[ 1354.061237]  iscsi_check_for_session_reinstatement+0x1dd/0x270 [iscsi_target_mod]
[ 1354.061977]  iscsi_target_do_login+0xe8/0x5d0 [iscsi_target_mod]
[ 1354.062712]  iscsi_target_start_negotiation+0x51/0xa0 [iscsi_target_mod]
[ 1354.063424]  iscsi_target_login_thread+0x93d/0x1100 [iscsi_target_mod]
[ 1354.064244]  kthread+0x106/0x140
[ 1354.065071]  ? iscsi_target_login_sess_out+0x200/0x200 [iscsi_target_mod]
[ 1354.065786]  ? kthread_bind+0x10/0x10
[ 1354.066481]  ret_from_fork+0x3a/0x50
[ 1354.067184] INFO: task iscsi_trx:11133 blocked for more than 368 seconds.
[ 1354.068010]       Not tainted 5.4.0+ #1
[ 1354.068834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1354.069558] iscsi_trx       D    0 11133      2 0x80004004
[ 1354.070267] Call Trace:
[ 1354.070956]  ? __schedule+0x2cd/0x8c0
[ 1354.071621]  schedule+0x40/0xc0
[ 1354.072375]  schedule_timeout+0x1e4/0x310
[ 1354.073130]  ? find_held_lock+0x38/0xa0
[ 1354.073802]  ? wait_for_completion+0x126/0x190
[ 1354.074463]  wait_for_completion+0x12e/0x190
[ 1354.075115]  ? wake_up_q+0x70/0x70
[ 1354.075892]  __ib_drain_sq+0x196/0x1d0 [ib_core]
[ 1354.076545]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[ 1354.077288]  ? wait_for_completion+0x49/0x190
[ 1354.077951]  ib_drain_qp+0xe/0x30 [ib_core]
[ 1354.078568]  isert_wait_conn+0x5e/0x330 [ib_isert]
[ 1354.079195]  ? __local_bh_enable_ip+0x80/0xf0
[ 1354.079948]  iscsit_close_connection+0x156/0x8f0 [iscsi_target_mod]
[ 1354.080555]  ? __local_bh_enable_ip+0x80/0xf0
[ 1354.081280]  iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod]
[ 1354.081922]  iscsi_target_rx_thread+0xdf/0xf0 [iscsi_target_mod]
[ 1354.082544]  kthread+0x106/0x140
[ 1354.083162]  ? iscsi_target_tx_thread+0x210/0x210 [iscsi_target_mod]
[ 1354.083907]  ? kthread_bind+0x10/0x10
[ 1354.084526]  ret_from_fork+0x3a/0x50
[ 1354.085248] 
Showing all locks held in the system:
[ 1354.086393] 1 lock held by khungtaskd/137:
[ 1354.086995]  #0: ffffffff91289ae0 (rcu_read_lock){....}, at: debug_show_all_locks+0xe/0x1a0
[ 1354.087609] 2 locks held by bash/1640:
[ 1354.088287]  #0: ffff9f538f2b30a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[ 1354.089034]  #1: ffffb2a50cd532f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[ 1354.089689] 2 locks held by bash/1705:
[ 1354.090302]  #0: ffff9f3b81afd0a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[ 1354.090950]  #1: ffffb2a50d3432f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[ 1354.091606] 2 locks held by kworker/u53:5/11156:
[ 1354.092345]  #0: ffff9f3b95b39d48 ((wq_completion)ib-comp-unb-wq){+.+.}, at: process_one_work+0x18c/0x590
[ 1354.093148]  #1: ffffb2a50cd67e50 ((work_completion)(&cq->work)){+.+.}, at: process_one_work+0x18c/0x590

[ 1354.094523] =============================================









###################################### instance 2 ############################################################
[166230.450405] iSCSI Login timeout on Network Portal 10.0.2.2:3260


[166380.978409] INFO: task iscsi_np:11196 blocked for more than 122 seconds.
[166380.979855]       Not tainted 5.4.0 #21
[166380.980927] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[166380.982365] iscsi_np        D    0 11196      2 0x80004084
[166380.983525] Call Trace:
[166380.984770]  ? __schedule+0x39b/0x970
[166380.986038]  schedule+0x40/0xc0
[166380.987049]  schedule_timeout+0x1e4/0x310
[166380.988299]  ? find_held_lock+0x38/0xa0
[166380.989411]  ? sched_clock+0x5/0x10
[166380.990435]  ? sched_clock_cpu+0xc/0xa0
[166380.991564]  wait_for_completion+0x12e/0x190
[166380.992543]  ? wake_up_q+0x70/0x70
[166380.993704]  iscsi_check_for_session_reinstatement+0x1dd/0x270 [iscsi_target_mod]
[166380.994650]  iscsi_target_do_login+0xe8/0x5d0 [iscsi_target_mod]
[166380.995779]  iscsi_target_start_negotiation+0x51/0xa0 [iscsi_target_mod]
[166380.996729]  iscsi_target_login_thread+0x93d/0x1100 [iscsi_target_mod]
[166380.997883]  kthread+0x106/0x140
[166380.998824]  ? iscsi_target_login_sess_out+0x200/0x200 [iscsi_target_mod]
[166380.999819]  ? kthread_bind+0x10/0x10
[166381.000708]  ret_from_fork+0x3a/0x50
[166381.001782] INFO: task iscsi_ttx:11567 blocked for more than 122 seconds.
[166381.002715]       Not tainted 5.4.0 #21
[166381.003729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[166381.004798] iscsi_ttx       D    0 11567      2 0x80004084
[166381.005800] Call Trace:
[166381.006902]  ? __schedule+0x39b/0x970
[166381.007747]  schedule+0x40/0xc0
[166381.008826]  schedule_timeout+0x1e4/0x310
[166381.009666]  ? find_held_lock+0x38/0xa0
[166381.010741]  ? sched_clock+0x5/0x10
[166381.011542]  ? sched_clock_cpu+0xc/0xa0
[166381.012536]  wait_for_completion+0x12e/0x190
[166381.013364]  ? wake_up_q+0x70/0x70
[166381.014225]  __ib_drain_sq+0x155/0x180 [ib_core]
[166381.015029]  ? __lock_acquire+0x283/0x10f0
[166381.015891]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[166381.016740]  ? wait_for_completion+0x49/0x190
[166381.017648]  ib_drain_qp+0xe/0x20 [ib_core]
[166381.018446]  isert_wait_conn+0x5e/0x330 [ib_isert]
[166381.019174]  ? __local_bh_enable_ip+0x80/0xf0
[166381.020077]  iscsit_close_connection+0x156/0x8f0 [iscsi_target_mod]
[166381.020903]  ? sched_clock_cpu+0xc/0xa0
[166381.021924]  ? __local_bh_enable_ip+0x80/0xf0
[166381.022723]  iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod]
[166381.023760]  iscsi_target_tx_thread+0x170/0x210 [iscsi_target_mod]
[166381.024536]  ? remove_wait_queue+0x60/0x60
[166381.025537]  kthread+0x106/0x140
[166381.026424]  ? iscsit_thread_get_cpumask+0xa0/0xa0 [iscsi_target_mod]
[166381.027417]  ? kthread_bind+0x10/0x10
[166381.028178]  ret_from_fork+0x3a/0x50
[166381.029014] INFO: task iscsi_ttx:11571 blocked for more than 122 seconds.
[166381.029948]       Not tainted 5.4.0 #21
[166381.030835] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[166381.031823] iscsi_ttx       D    0 11571      2 0x80004084
[166381.032828] Call Trace:
[166381.033743]  ? __schedule+0x39b/0x970
[166381.034666]  schedule+0x40/0xc0
[166381.035645]  schedule_timeout+0x1e4/0x310
[166381.036676]  ? find_held_lock+0x38/0xa0
[166381.037585]  ? sched_clock+0x5/0x10
[166381.038502]  ? sched_clock_cpu+0xc/0xa0
[166381.039407]  wait_for_completion+0x12e/0x190
[166381.040255]  ? wake_up_q+0x70/0x70
[166381.041261]  __ib_drain_sq+0x155/0x180 [ib_core]
[166381.042117]  ? __lock_acquire+0x283/0x10f0
[166381.043126]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[166381.044017]  ? wait_for_completion+0x49/0x190
[166381.044961]  ib_drain_qp+0xe/0x20 [ib_core]
[166381.045791]  isert_wait_conn+0x5e/0x330 [ib_isert]
[166381.046716]  ? __local_bh_enable_ip+0x80/0xf0
[166381.047610]  iscsit_close_connection+0x156/0x8f0 [iscsi_target_mod]
[166381.048494]  ? sched_clock_cpu+0xc/0xa0
[166381.049207]  ? __local_bh_enable_ip+0x80/0xf0
[166381.050091]  iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod]
[166381.050885]  iscsi_target_tx_thread+0x170/0x210 [iscsi_target_mod]
[166381.051887]  ? remove_wait_queue+0x60/0x60
[166381.052754]  kthread+0x106/0x140
[166381.053730]  ? iscsit_thread_get_cpumask+0xa0/0xa0 [iscsi_target_mod]
[166381.054666]  ? kthread_bind+0x10/0x10
[166381.055685]  ret_from_fork+0x3a/0x50
[166381.056501]
Showing all locks held in the system:
[166381.058151] 1 lock held by khungtaskd/93:
[166381.058951]  #0: ffffffff9d28a160 (rcu_read_lock){....}, at: debug_show_all_locks+0xe/0x1a0
[166381.059945] 3 locks held by kworker/2:1H/633:
[166381.060810]  #0: ffff892bdade8298 (&rq->lock){-.-.}, at: __schedule+0xea/0x970
[166381.061918]  #1: ffffffff9d28a160 (rcu_read_lock){....}, at: __update_idle_core+0x5/0x200
[166381.062875]  #2: ffff892bc1144098 (&sess->cmdsn_mutex){+.+.}, at: iscsit_sequence_cmd+0x2a/0x190 [iscsi_target_mod]
[166381.063926] 2 locks held by kworker/1:1H/724:
[166381.064790]  #0: ffff892bda7e8298 (&rq->lock){-.-.}, at: __schedule+0xea/0x970
[166381.065915]  #1: ffffffff9d28a160 (rcu_read_lock){....}, at: __update_idle_core+0x5/0x200
[166381.066852] 2 locks held by kworker/4:1H/736:
[166381.067903]  #0: ffff892bc4506d48 ((wq_completion)ib-comp-wq){+.+.}, at: process_one_work+0x18c/0x590
[166381.068827]  #1: ffffa47c00687e50 ((work_completion)(&cq->work)){+.+.}, at: process_one_work+0x18c/0x590
[166381.069968] 2 locks held by kworker/6:1H/754:
[166381.070962]  #0: ffff892bc4506d48 ((wq_completion)ib-comp-wq){+.+.}, at: process_one_work+0x18c/0x590
[166381.072017]  #1: ffffa47c0066fe50 ((work_completion)(&cq->work)){+.+.}, at: process_one_work+0x18c/0x590
[166381.073256] 2 locks held by agetty/1991:
[166381.074257]  #0: ffff892bd09628a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[166381.075445]  #1: ffffa47c00ee32f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[166381.076406] 2 locks held by bash/8001:
[166381.077546]  #0: ffff892bd09620a0 (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x24/0x50
[166381.078682]  #1: ffffa47c004572f0 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xdb/0x940
[166381.079899] 2 locks held by kworker/7:2/8348:
[166381.081088]  #0: ffff892bdcbe8298 (&rq->lock){-.-.}, at: __schedule+0xea/0x970
[166381.082153]  #1: ffffffff9d28a160 (rcu_read_lock){....}, at: process_one_work+0x18c/0x590
[166381.083400] 1 lock held by dmesg/11581:

[166381.085703] =============================================


[-- Attachment #3: dmesg_initiator.txt --]
[-- Type: text/plain, Size: 15143 bytes --]

[59518.768637] iwpm_register_pid: Unable to send a nlmsg (client = 2)
[59519.769002] scsi host6: iSCSI Initiator over iSER
[59523.250297] scsi host6: iSCSI Initiator over iSER
[59523.272850] scsi 6:0:0:0: Direct-Access     LIO-ORG  ram100           4.0  PQ: 0 ANSI: 5
[59523.274224] scsi 6:0:0:0: alua: supports implicit and explicit TPGS
[59523.274319] scsi 6:0:0:0: alua: device naa.600140561f7536635924f219092d7b59 port group 0 rel port 1
[59523.275628] sd 6:0:0:0: Attached scsi generic sg3 type 0
[59523.276990] sd 6:0:0:0: [sdc] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59523.277229] sd 6:0:0:0: [sdc] Write Protect is off
[59523.277242] sd 6:0:0:0: [sdc] Mode Sense: 43 00 00 08
[59523.277738] sd 6:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59523.279158] sd 6:0:0:0: [sdc] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59523.286201] sd 6:0:0:0: alua: transition timeout set to 60 seconds
[59523.286271] sd 6:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59523.294653] sd 6:0:0:0: [sdc] Attached SCSI disk
[59524.299600] scsi host7: iSCSI Initiator over iSER
[59524.322907] scsi 7:0:0:0: Direct-Access     LIO-ORG  ram110           4.0  PQ: 0 ANSI: 5
[59524.323836] scsi 7:0:0:0: alua: supports implicit and explicit TPGS
[59524.323851] scsi 7:0:0:0: alua: device naa.60014050736b720653b43ef891c59afb port group 0 rel port 1
[59524.325090] sd 7:0:0:0: Attached scsi generic sg4 type 0
[59524.325938] sd 7:0:0:0: [sdd] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59524.326143] sd 7:0:0:0: [sdd] Write Protect is off
[59524.326151] sd 7:0:0:0: [sdd] Mode Sense: 43 00 00 08
[59524.326548] sd 7:0:0:0: [sdd] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59524.328176] sd 7:0:0:0: [sdd] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59524.344624] sd 7:0:0:0: alua: transition timeout set to 60 seconds
[59524.344640] sd 7:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59524.351825] sd 7:0:0:0: [sdd] Attached SCSI disk
[59525.355487] scsi host8: iSCSI Initiator over iSER
[59525.375729] scsi 8:0:0:0: Direct-Access     LIO-ORG  ram120           4.0  PQ: 0 ANSI: 5
[59525.376749] scsi 8:0:0:0: alua: supports implicit and explicit TPGS
[59525.376764] scsi 8:0:0:0: alua: device naa.6001405bbca925d2b6143d2be6dbd5b2 port group 0 rel port 1
[59525.377508] sd 8:0:0:0: Attached scsi generic sg5 type 0
[59525.379742] sd 8:0:0:0: [sde] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59525.380178] sd 8:0:0:0: [sde] Write Protect is off
[59525.380191] sd 8:0:0:0: [sde] Mode Sense: 43 00 00 08
[59525.380665] sd 8:0:0:0: [sde] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59525.382187] sd 8:0:0:0: [sde] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59525.392159] sd 8:0:0:0: alua: transition timeout set to 60 seconds
[59525.392171] sd 8:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59525.402816] sd 8:0:0:0: [sde] Attached SCSI disk
[59526.417541] scsi host9: iSCSI Initiator over iSER
[59526.439020] scsi 9:0:0:0: Direct-Access     LIO-ORG  ram130           4.0  PQ: 0 ANSI: 5
[59526.440168] scsi 9:0:0:0: alua: supports implicit and explicit TPGS
[59526.440191] scsi 9:0:0:0: alua: device naa.6001405e3ff21dc19e9402582107192a port group 0 rel port 1
[59526.441123] sd 9:0:0:0: Attached scsi generic sg6 type 0
[59526.442103] sd 9:0:0:0: [sdf] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59526.442268] sd 9:0:0:0: [sdf] Write Protect is off
[59526.442275] sd 9:0:0:0: [sdf] Mode Sense: 43 00 00 08
[59526.442497] sd 9:0:0:0: [sdf] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59526.443902] sd 9:0:0:0: [sdf] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59526.467826] sd 9:0:0:0: alua: transition timeout set to 60 seconds
[59526.467844] sd 9:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59526.475946] sd 9:0:0:0: [sdf] Attached SCSI disk
[59527.484769] scsi host10: iSCSI Initiator over iSER
[59527.505089] scsi 10:0:0:0: Direct-Access     LIO-ORG  ram140           4.0  PQ: 0 ANSI: 5
[59527.506193] scsi 10:0:0:0: alua: supports implicit and explicit TPGS
[59527.506216] scsi 10:0:0:0: alua: device naa.60014059f2a5bca5f124793b925bf787 port group 0 rel port 1
[59527.507254] sd 10:0:0:0: Attached scsi generic sg7 type 0
[59527.508651] sd 10:0:0:0: [sdg] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59527.508951] sd 10:0:0:0: [sdg] Write Protect is off
[59527.508959] sd 10:0:0:0: [sdg] Mode Sense: 43 00 00 08
[59527.509439] sd 10:0:0:0: [sdg] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59527.510993] sd 10:0:0:0: [sdg] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59527.519293] sd 10:0:0:0: alua: transition timeout set to 60 seconds
[59527.519304] sd 10:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59527.530751] sd 10:0:0:0: [sdg] Attached SCSI disk
[59528.567803] scsi host11: iSCSI Initiator over iSER
[59528.589890] scsi 11:0:0:0: Direct-Access     LIO-ORG  ram150           4.0  PQ: 0 ANSI: 5
[59528.590968] scsi 11:0:0:0: alua: supports implicit and explicit TPGS
[59528.590994] scsi 11:0:0:0: alua: device naa.60014059d41e4a6d7264f6082b27cd0f port group 0 rel port 1
[59528.591825] sd 11:0:0:0: Attached scsi generic sg8 type 0
[59528.593304] sd 11:0:0:0: [sdh] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59528.593600] sd 11:0:0:0: [sdh] Write Protect is off
[59528.593613] sd 11:0:0:0: [sdh] Mode Sense: 43 00 00 08
[59528.594260] sd 11:0:0:0: [sdh] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59528.596022] sd 11:0:0:0: [sdh] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59528.620020] sd 11:0:0:0: [sdh] Attached SCSI disk
[59528.623927] sd 11:0:0:0: alua: transition timeout set to 60 seconds
[59528.623941] sd 11:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59529.652880] scsi host12: iSCSI Initiator over iSER
[59529.674840] scsi 12:0:0:0: Direct-Access     LIO-ORG  ram160           4.0  PQ: 0 ANSI: 5
[59529.675898] scsi 12:0:0:0: alua: supports implicit and explicit TPGS
[59529.675914] scsi 12:0:0:0: alua: device naa.6001405e46113e4ede84e77927dee873 port group 0 rel port 1
[59529.676917] sd 12:0:0:0: Attached scsi generic sg9 type 0
[59529.677879] sd 12:0:0:0: [sdi] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59529.678060] sd 12:0:0:0: [sdi] Write Protect is off
[59529.678073] sd 12:0:0:0: [sdi] Mode Sense: 43 00 00 08
[59529.678380] sd 12:0:0:0: [sdi] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59529.679872] sd 12:0:0:0: [sdi] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59529.690378] sd 12:0:0:0: alua: transition timeout set to 60 seconds
[59529.690390] sd 12:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59529.699708] sd 12:0:0:0: [sdi] Attached SCSI disk
[59530.746940] scsi host13: iSCSI Initiator over iSER
[59530.769261] scsi 13:0:0:0: Direct-Access     LIO-ORG  ram170           4.0  PQ: 0 ANSI: 5
[59530.770229] scsi 13:0:0:0: alua: supports implicit and explicit TPGS
[59530.770247] scsi 13:0:0:0: alua: device naa.6001405fb71bdbe73804b149d8dc6495 port group 0 rel port 1
[59530.771224] sd 13:0:0:0: Attached scsi generic sg10 type 0
[59530.772461] sd 13:0:0:0: [sdj] 1046528 512-byte logical blocks: (536 MB/511 MiB)
[59530.772546] sd 13:0:0:0: [sdj] Write Protect is off
[59530.772554] sd 13:0:0:0: [sdj] Mode Sense: 43 00 00 08
[59530.772743] sd 13:0:0:0: [sdj] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[59530.774184] sd 13:0:0:0: [sdj] Optimal transfer size 4294967288 logical blocks > dev_max (65535 logical blocks)
[59530.783430] sd 13:0:0:0: alua: transition timeout set to 60 seconds
[59530.783447] sd 13:0:0:0: alua: port group 00 state A non-preferred supports TOlUSNA
[59530.793068] sd 13:0:0:0: [sdj] Attached SCSI disk
[59550.860954] EXT4-fs (sdc): mounting ext3 file system using the ext4 subsystem
[59550.875188] EXT4-fs (sdc): mounted filesystem with ordered data mode. Opts: (null)
[59550.875216] ext3 filesystem being mounted at /mount/iscsi0 supports timestamps until 2038 (0x7fffffff)
[59550.950274] EXT4-fs (sdd): mounting ext3 file system using the ext4 subsystem
[59550.962063] EXT4-fs (sdd): mounted filesystem with ordered data mode. Opts: (null)
[59550.962083] ext3 filesystem being mounted at /mount/iscsi1 supports timestamps until 2038 (0x7fffffff)
[59550.989372] EXT4-fs (sde): mounting ext3 file system using the ext4 subsystem
[59551.003358] EXT4-fs (sde): mounted filesystem with ordered data mode. Opts: (null)
[59551.003379] ext3 filesystem being mounted at /mount/iscsi2 supports timestamps until 2038 (0x7fffffff)
[59551.031349] EXT4-fs (sdf): mounting ext3 file system using the ext4 subsystem
[59551.047403] EXT4-fs (sdf): mounted filesystem with ordered data mode. Opts: (null)
[59551.047423] ext3 filesystem being mounted at /mount/iscsi3 supports timestamps until 2038 (0x7fffffff)
[59551.074807] EXT4-fs (sdg): mounting ext3 file system using the ext4 subsystem
[59551.090428] EXT4-fs (sdg): mounted filesystem with ordered data mode. Opts: (null)
[59551.090449] ext3 filesystem being mounted at /mount/iscsi4 supports timestamps until 2038 (0x7fffffff)
[59551.118820] EXT4-fs (sdh): mounting ext3 file system using the ext4 subsystem
[59551.135108] EXT4-fs (sdh): mounted filesystem with ordered data mode. Opts: (null)
[59551.135128] ext3 filesystem being mounted at /mount/iscsi5 supports timestamps until 2038 (0x7fffffff)
[59551.162711] EXT4-fs (sdi): mounting ext3 file system using the ext4 subsystem
[59551.175810] EXT4-fs (sdi): mounted filesystem with ordered data mode. Opts: (null)
[59551.175830] ext3 filesystem being mounted at /mount/iscsi6 supports timestamps until 2038 (0x7fffffff)
[59551.201090] EXT4-fs (sdj): mounting ext3 file system using the ext4 subsystem
[59551.216756] EXT4-fs (sdj): mounted filesystem with ordered data mode. Opts: (null)
[59551.216776] ext3 filesystem being mounted at /mount/iscsi7 supports timestamps until 2038 (0x7fffffff)
[59873.320290]  connection3:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4354526811, last ping 4354531840, now 4354536960
[59873.320781]  connection3:0: detected conn error (1022)
[59994.670540]  session3: session recovery timed out after 120 secs
[59994.679237] sd 7:0:0:0: rejecting I/O to offline device
[59994.679339] blk_update_request: I/O error, dev sdd, sector 499184 op 0x1:(WRITE) flags 0x800 phys_seg 9 prio class 0
[59994.679363] sd 7:0:0:0: rejecting I/O to offline device
[59994.679370] blk_update_request: I/O error, dev sdd, sector 499630 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679380] sd 7:0:0:0: rejecting I/O to offline device
[59994.679386] blk_update_request: I/O error, dev sdd, sector 499612 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679395] sd 7:0:0:0: rejecting I/O to offline device
[59994.679402] blk_update_request: I/O error, dev sdd, sector 499516 op 0x1:(WRITE) flags 0x800 phys_seg 21 prio class 0
[59994.679435] sd 7:0:0:0: rejecting I/O to offline device
[59994.679442] blk_update_request: I/O error, dev sdd, sector 499606 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679450] sd 7:0:0:0: rejecting I/O to offline device
[59994.679457] blk_update_request: I/O error, dev sdd, sector 499618 op 0x1:(WRITE) flags 0x800 phys_seg 5 prio class 0
[59994.679469] sd 7:0:0:0: rejecting I/O to offline device
[59994.679475] blk_update_request: I/O error, dev sdd, sector 499608 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679483] sd 7:0:0:0: rejecting I/O to offline device
[59994.679490] blk_update_request: I/O error, dev sdd, sector 499616 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679498] sd 7:0:0:0: rejecting I/O to offline device
[59994.679505] blk_update_request: I/O error, dev sdd, sector 488986 op 0x1:(WRITE) flags 0xc800 phys_seg 2 prio class 0
[59994.679518] sd 7:0:0:0: rejecting I/O to offline device
[59994.679524] blk_update_request: I/O error, dev sdd, sector 499564 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[59994.679533] sd 7:0:0:0: rejecting I/O to offline device
[59994.679549] sd 7:0:0:0: rejecting I/O to offline device
[59994.679558] sd 7:0:0:0: rejecting I/O to offline device
[59994.679568] sd 7:0:0:0: rejecting I/O to offline device
[59994.679590] sd 7:0:0:0: rejecting I/O to offline device
[59994.679610] sd 7:0:0:0: rejecting I/O to offline device
[59994.679634] sd 7:0:0:0: rejecting I/O to offline device
[59994.679653] sd 7:0:0:0: rejecting I/O to offline device
[59994.679669] sd 7:0:0:0: rejecting I/O to offline device
[59994.679678] sd 7:0:0:0: rejecting I/O to offline device
[59994.679687] sd 7:0:0:0: rejecting I/O to offline device
[59994.679703] sd 7:0:0:0: rejecting I/O to offline device
[59994.679712] sd 7:0:0:0: rejecting I/O to offline device
[59994.679721] sd 7:0:0:0: rejecting I/O to offline device
[59994.679737] sd 7:0:0:0: rejecting I/O to offline device
[59994.679758] sd 7:0:0:0: rejecting I/O to offline device
[59994.679767] sd 7:0:0:0: rejecting I/O to offline device
[59994.679776] sd 7:0:0:0: rejecting I/O to offline device
[59994.679785] sd 7:0:0:0: rejecting I/O to offline device
[59994.679794] sd 7:0:0:0: rejecting I/O to offline device
[59994.679803] sd 7:0:0:0: rejecting I/O to offline device
[59994.679811] sd 7:0:0:0: rejecting I/O to offline device
[59994.679822] sd 7:0:0:0: rejecting I/O to offline device
[59994.679847] sd 7:0:0:0: rejecting I/O to offline device
[59994.680110] sd 7:0:0:0: rejecting I/O to offline device
[59994.680120] sd 7:0:0:0: rejecting I/O to offline device
[59994.680318] sd 7:0:0:0: rejecting I/O to offline device
[59994.680331] sd 7:0:0:0: rejecting I/O to offline device
[59994.680340] sd 7:0:0:0: rejecting I/O to offline device
[59994.680396] sd 7:0:0:0: rejecting I/O to offline device
[59994.680743] Aborting journal on device sdd-8.
[59994.680792] sd 7:0:0:0: rejecting I/O to offline device
[59994.680842] sd 7:0:0:0: rejecting I/O to offline device
[59994.680871] Buffer I/O error on dev sdd, logical block 246019, lost sync page write
[59994.680890] sd 7:0:0:0: rejecting I/O to offline device
[59994.680903] Buffer I/O error on dev sdd, logical block 1, lost sync page write
[59994.680932] EXT4-fs (sdd): I/O error while writing superblock
[59994.680939] JBD2: Error -5 detected when updating journal superblock for sdd-8.
[59994.680977] EXT4-fs error (device sdd): ext4_journal_check_start:61: Detected aborted journal
[59994.680985] EXT4-fs (sdd): Remounting filesystem read-only
[59994.681044] sd 7:0:0:0: rejecting I/O to offline device
[59994.681060] Buffer I/O error on dev sdd, logical block 1, lost sync page write
[59994.681090] EXT4-fs (sdd): I/O error while writing superblock
[59994.681122] sd 7:0:0:0: rejecting I/O to offline device

[-- Attachment #4: 8tgt_1lun_each.json --]
[-- Type: application/json, Size: 24880 bytes --]