fix bug of iscsid hung

Hi list,

I encountered a bug of iscsid hung when testing iscsi login/logout in unstable network.

Same as this one reported by Wangqiang@Huawei
https://lore.kernel.org/lkml/508A4C72ED914648BB0F1814399310DBBB2997-0LhPdUyVHB9548jd+VSckwK1hpo4iccwjNknBlVQO8k@public.gmane.org/

Use tc tool to simulate network packet loss.

---------- test script start -------------
tc qdisc add dev eth0 root netem loss 60

# 2 target, each with 10 LUNs

n=1
while [ 1 ]
do

     echo "$(date) ==== test loop $n ===="
     iscsiadm -m node -T iqn.2016-06.io.spdk:disk1 --login
     sleep 5
     iscsiadm -m node -T iqn.2016-06.io.spdk:disk1 --logout&
     iscsiadm -m node -T iqn.2016-06.io.spdk:disk2 --login&
     sleep 10
     iscsiadm -m node -u
     n=$(($n + 1))
     echo "$(date) ==== continue to test loop ===="

done
---------- test script end -------------

iscsid hung as below,

[  369.909988] INFO: task iscsid:1254 blocked for more than 122 seconds.
[  369.912532]       Tainted: G            E     5.1.0-rc3+ #12
[  369.914750] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  369.917396] iscsid          D    0  1254      1 0x00000080
[  369.917399] Call Trace:
[  369.920958]  schedule+0x32/0x70
[  369.922716]  schedule_timeout+0x1d8/0x300
[  369.926129]  wait_for_completion+0x123/0x190
[  369.929365]  __flush_work.isra.34+0x124/0x1b0  ===> flush_work(&session->unbind_work);
[  369.932746]  iscsi_remove_session+0xf0/0x1d0 [scsi_transport_iscsi]
[  369.934718]  iscsi_session_teardown+0x37/0xf0 [libiscsi]
[  369.936417]  iscsi_sw_tcp_session_destroy+0x42/0x60 [iscsi_tcp]
[  369.938312]  iscsi_if_recv_msg+0x69b/0x1510 [scsi_transport_iscsi]
[  369.946502]  iscsi_if_rx+0xa5/0x1e0 [scsi_transport_iscsi]
[  369.948193]  netlink_unicast+0x17f/0x230
[  369.949734]  netlink_sendmsg+0x2d2/0x3d0
[  369.951277]  sock_sendmsg+0x36/0x50
[  369.952691]  ___sys_sendmsg+0x280/0x2a0
[  369.981533]  __sys_sendmsg+0x58/0xa0
[  369.982444]  do_syscall_64+0x5b/0x180
[  369.983369]  entry_SYSCALL_64_after_hwframe+0x44/0xa9

__flush_work() tried to flush session->unbind_work. kworker thread that handles unbind_work blocked as below,

[  615.742259] INFO: task kworker/u4:11:1321 blocked for more than 368 seconds.
[  615.743615]       Tainted: G            E     5.1.0-rc3+ #12
[  615.744780] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  615.746274] kworker/u4:11   D    0  1321      2 0x80000080
[  615.746281] Workqueue: scsi_wq_2 __iscsi_unbind_session [scsi_transport_iscsi]
[  615.746282] Call Trace:
[  615.749131]  schedule+0x32/0x70
[  615.750065]  async_synchronize_cookie_domain+0x8b/0x140
[  615.752349]  sd_remove+0x8f/0x140 [sd_mod]
[  615.753411]  device_release_driver_internal+0xeb/0x1c0
[  615.754605]  bus_remove_device+0xe5/0x160
[  615.755702]  device_del+0x15a/0x340
[  615.759495]  __scsi_remove_device+0x9c/0x160
[  615.760673]  scsi_remove_device+0x21/0x30
[  615.761824]  scsi_remove_target+0x172/0x1c0
[  615.763001]  __iscsi_unbind_session+0xd0/0x1a0 [scsi_transport_iscsi]
[  615.764477]  process_one_work+0x171/0x380
[  615.765646]  worker_thread+0x49/0x3f0
[  615.766774]  kthread+0xf8/0x130
[  615.769974]  ret_from_fork+0x35/0x40

async_synchronize_cookie_domain() blocked until all entries in "scsi_sd_probe_domain" finished. But some entries never finished because kworker thread that executes sd_probe_async() blocked as below,

[  492.909482] INFO: task kworker/u4:0:7 blocked for more than 122 seconds.
[  492.912321]       Tainted: G            E     5.1.0-rc3+ #6
[  492.913519] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  492.915037] kworker/u4:0    D    0     7      2 0x80000000
[  492.915046] Workqueue: events_unbound async_run_entry_fn
[  492.915047] Call Trace:
[  492.916813]  schedule+0x32/0x70
[  492.917740]  io_schedule+0x12/0x40
[  492.918659]  do_read_cache_page+0x43b/0x740
[  492.921877]  read_dev_sector+0x28/0xa0
[  492.922859]  read_lba+0xfe/0x1b0
[  492.924904]  find_valid_gpt+0xfa/0x720
[  492.927048]  efi_partition+0x89/0x430
[  492.931934]  check_partition+0x110/0x200
[  492.932960]  rescan_partitions+0xbb/0x360
[  492.934000]  __blkdev_get+0x372/0x4b0
[  492.934987]  blkdev_get+0x1a7/0x300
[  492.937892]  __device_add_disk+0x45f/0x4c0
[  492.938942]  sd_probe_async+0x13f/0x240 [sd_mod]
[  492.940065]  async_run_entry_fn+0x39/0x160
[  492.941126]  process_one_work+0x171/0x380
[  492.942181]  worker_thread+0x49/0x3f0
[  492.943169]  kthread+0xf8/0x130
[  492.946140]  ret_from_fork+0x35/0x40

The iscsi command sent by do_read_cache_page() timedout in my test, but it's never completed/aborted because session->state is ISCSI_STATE_FAILED and iscsi_eh_cmd_timed_out() keep returning BLK_EH_RESET_TIMER.

1947 enum blk_eh_timer_return iscsi_eh_cmd_timed_out(struct scsi_cmnd *sc) 1948 {
......
......
1972 if (session->state != ISCSI_STATE_LOGGED_IN) {
1973 /*

1974                  * During shutdown, if session is prematurely disconnected,
1975                  * recovery won't happen and there will be hung cmds. Not
1976                  * handling cmds would trigger EH, also bad in this case.
1977                  * Instead, handle cmd, allow completion to happen and let
1978                  * upper layer to deal with the result.
1979                  */
1980                 if (unlikely(system_state != SYSTEM_RUNNING)) {
1981                         sc->result = DID_NO_CONNECT << 16;
1982                         ISCSI_DBG_EH(session, "sc on shutdown, handled\n");
1983                         rc = BLK_EH_DONE;
1984                         goto done;
1985                 }
1986                 /*
1987                  * We are probably in the middle of iscsi recovery so let
1988                  * that complete and handle the error.
1989                  */

1990 rc = BLK_EH_RESET_TIMER;
1991 goto done;
1992 }

I ported Wangqiang's patch to latest 5.1-rc kernel and it fixed this bug. Please help review it.

Thanks,
Ming

You received this message because you are subscribed to the Google Groups "open-iscsi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to open-iscsi+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
To post to this group, send email to open-iscsi-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
Visit this group at https://groups.google.com/group/open-iscsi.
For more options, visit https://groups.google.com/d/optout.

From: "wangqiang (AY)" <[email protected]>

sd_remove() waits for the completion of async threads executing sd_probe_async of disks on unrelated host adapters, rather than just the the async thread associated with the scsi_disk being removed.

This patch makes sd_remove() just wait for the the async thread associated with the scsi_disk being removed. And makes the operation of iscsid after received ISCSI_KEVENT_CONN_ERROR be asynchronous by put the __iscsi_destroy_session() in work queue.

---
 drivers/scsi/scsi_transport_iscsi.c | 14 +++++++++++++-
 drivers/scsi/sd.c                   |  5 +++--
 drivers/scsi/sd.h                   |  3 +++
 include/scsi/scsi_transport_iscsi.h |  1 +
 4 files changed, 20 insertions(+), 3 deletions(-)

index 0a82e93566dc..7e5782eb527b 100644
@@ -2005,6 +2005,16 @@ void iscsi_block_session(struct iscsi_cls_session *session)
 }
 EXPORT_SYMBOL_GPL(iscsi_block_session);
 
+static void __iscsi_destroy_session(struct work_struct *work)
+{
+	struct iscsi_cls_session *session =
+		container_of(work, struct iscsi_cls_session,
+                                    destroy_work);
+	struct iscsi_transport *transport = session->transport;
+
+	transport->destroy_session(session);
+}
+
 static void __iscsi_unbind_session(struct work_struct *work)
 {
 	struct iscsi_cls_session *session =

@@ -2061,6 +2071,7 @@ iscsi_alloc_session(struct Scsi_Host *shost, struct iscsi_transport *transport,
 	INIT_WORK(&session->block_work, __iscsi_block_session);
 	INIT_WORK(&session->unbind_work, __iscsi_unbind_session);
 	INIT_WORK(&session->scan_work, iscsi_scan_session);
+	INIT_WORK(&session->destroy_work, __iscsi_destroy_session);
 	spin_lock_init(&session->lock);
 
 	/* this is released in the dev's release function */

@@ -3536,7 +3547,8 @@ iscsi_if_recv_msg(struct sk_buff *skb, struct nlmsghdr *nlh, uint32_t *group)
 	case ISCSI_UEVENT_DESTROY_SESSION:
 		session = iscsi_session_lookup(ev->u.d_session.sid);
 		if (session)
-			transport->destroy_session(session);
+			scsi_queue_work(iscsi_session_to_shost(session),
+					&session->destroy_work);
 		else
 			err = -EINVAL;
 		break;

index 2b2bc4b49d78..378f57142183 100644
@@ -3436,7 +3436,8 @@ static int sd_probe(struct device *dev)
 	dev_set_drvdata(dev, sdkp);
 
 	get_device(&sdkp->dev);	/* prevent release before async_schedule */
-	async_schedule_domain(sd_probe_async, sdkp, &scsi_sd_probe_domain);
+	INIT_LIST_HEAD(&sdkp->sd_probe_domain.pending);
+	async_schedule_domain(sd_probe_async, sdkp, &sdkp->sd_probe_domain);
 
 	return 0;
 

@@ -3472,7 +3473,7 @@ static int sd_remove(struct device *dev)
 	scsi_autopm_get_device(sdkp->device);
 
 	async_synchronize_full_domain(&scsi_sd_pm_domain);
-	async_synchronize_full_domain(&scsi_sd_probe_domain);
+	async_synchronize_full_domain(&sdkp->sd_probe_domain);
 	device_del(&sdkp->dev);
 	del_gendisk(sdkp->disk);
 	sd_shutdown(dev);

index 5796ace76225..f46a87ebd759 100644
@@ -2,6 +2,8 @@
 #ifndef _SCSI_DISK_H
 #define _SCSI_DISK_H
 
+#include <linux/async.h>
+
 /*
  * More than enough for everybody ;)  The huge number of majors
  * is a leftover from 16bit dev_t days, we don't really need that

@@ -73,6 +75,7 @@ struct scsi_disk {
 	struct device	dev;
 	struct gendisk	*disk;
 	struct opal_dev *opal_dev;
+	struct async_domain sd_probe_domain;
 #ifdef CONFIG_BLK_DEV_ZONED
 	u32		nr_zones;
 	u32		zone_blocks;

index b266d2a3bcb1..7830e1596ef3 100644
@@ -238,6 +238,7 @@ struct iscsi_cls_session {
 	struct work_struct unblock_work;
 	struct work_struct scan_work;
 	struct work_struct unbind_work;
+	struct work_struct destroy_work;
 
 	/* recovery fields */
 	int recovery_tmo;

2.14.4.52.g320db32

-- 
You received this message because you are subscribed to the Google Groups "open-iscsi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to open-iscsi+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
To post to this group, send email to open-iscsi-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
Visit this group at https://groups.google.com/group/open-iscsi.
For more options, visit https://groups.google.com/d/optout.

Hi, Bart

It seems that the commit 21e6ba3 in branch 5.2/scsi-queue has
addressed the deadlock issue we encountered.

We will backport that patch to our kernel version and verify it
with our test cases.

Thanks

Best regards

You received this message because you are subscribed to the Google Groups "open-iscsi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to open-iscsi+unsubscribe-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
To post to this group, send email to open-iscsi-/JYPxA39Uh5TLH3MbocFF+G/[email protected]
Visit this group at https://groups.google.com/group/open-iscsi.
For more options, visit https://groups.google.com/d/optout.