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/508a4c72ed914648bb0f1814399310dbbb2...@dggemm506-mbx.china.huawei.com/ 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
