Revisting iscsi target hung issue with tcmu glusterfs backstore

解决问题的思路反思和教训

2019 年 0710 生成此报告，20200525 再次审视。
不光需要理解代码，也应该有假设探索的能力，才能快速准确的定位解决 bug。反思自己以下的解决过程，在代码理解和 bug 的复现的基础上结合一定的假设，也许就可以更快的分析解决这个问题了。

• 问题复现上，由于缺乏当时生产环境的具体信息，确实只能自我摸索。但其实已经极限接近问题的本质了，但最后却浅尝辄止了
• 在代码理解上，精读分析了代码。却没有跳出具体细节。从直观或者宏观角度做一个假设，进而换个角度理解或者给 bug 复现探索提供新的思路

问题

三台机器，243，244，245 IO 的时候有些 target 的 iscsi 会话断开，target hung。

gluster-block 创建一个 glfs backstore，基于此 backstore 创建一个 lun，期间默认会创建 tpg 和 portal，这里 HA=1。然后通过 targetcli 在此 tgp 和 portal 下创建其他 lun。默认 gluster-block 在一个 tpg 下只会创建一个 lun，这里我们利用了 targetcli 的方式，创建其他 lun。
如此，在组成 gluster volume 的这三台机器，每个都这么执行如上操作。 本质上生成了三个 target 即三个 iqn。
每个 target 对应一个机器，每个 target 一个 tpg，这个 tpg 下面有多个 lun。
i 端（另外机器）连上三个 target，轮流读写这些 lun。

现象

• 244/245 机器当前的 target 与某个 i 端的连接处于 close-wait 状态，而 243 机器所有的 i-t 连接都是正常 est 状态。

• 244 机器 np 线程 接收队列满了。245 未观察。

[root@xdfs2 ~]# ss -n4lt 'sport = :iscsi-target'
State       Recv-Q Send-Q               Local Address:Port         Peer Address:Port
LISTEN      257    256                  192.168.227.244:3260

• 244/245 机器 np/trx/ttx 线程 fd count
  ls /proc/*/fd|wc -l
  数据获取错误，忽略
• iscsiadm -m discovery
  在 244 机器上执行 iscsiadm -m discovery -t st -p 192.168.227.245/244 -d8 连接超时，243 正常。
  iscsiadm -m discovery -t st -p 192.168.227.243 输出三个 target iqn，688d0c0a，ada71018（这个是 block 创建的）, 8132c0d0
• iscsiadm -m session
  在 243 机器上 iscsiadm -m session，no active session，说明此机器没有发起过或者没有 logging session。
  在 244 上执行 iscsiadm -m session -P 3
  三个 session，conn state 和 session state 都是 logged in 状态。
  一个是连到 245 target 7a734 的 session。sid =1
  一个是连到 244 即本机的 target d6726 的 session。sid=2 （block 创建的）
  一个是连到 244 即本机的 target 0d7c4b 的 session。sid =3
  243 ： block 创建的是 ada71018-8d55-4106-9787-17f7df92c643
  244: block 创建的是 d672686d-dda6-4c31-ace6-4db75e9e12d3
• D 状态，只有 243 机器没有 D 状态，244/245 偶尔有 glusterfs/glusterfsd D 状态，但是正常的。
  244/245 有以下 hang，
  244 机器

  scsit [iscsi_ttx]                 18041 D

  iscsit [iscsi_np]                 21181 D

[root@xdfs2 ~]# cat /proc/21181/stack

[<ffffffffc07c5c48>] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod]

[<ffffffffc07b67d3>] iscsi_check_for_session_reinstatement+0x213/0x280 [iscsi_target_mod]

[<ffffffffc07b95d5>] iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod]

[<ffffffffc07b96d9>] iscsi_target_do_login+0xf9/0x640 [iscsi_target_mod]

[<ffffffffc07ba836>] iscsi_target_start_negotiation+0x56/0xc0 [iscsi_target_mod]

[<ffffffffc07b824e>] __iscsi_target_login_thread+0x89e/0x1000 [iscsi_target_mod]

[<ffffffffc07b89d8>] iscsi_target_login_thread+0x28/0x60 [iscsi_target_mod]

[<ffffffffb62c1c31>] kthread+0xd1/0xe0

[<ffffffffb6974c37>] ret_from_fork_nospec_end+0x0/0x39

[<ffffffffffffffff>] 0xffffffffffffffff

[root@xdfs2 ~]# cat /proc/18041/stack

[<ffffffffc07be837>] iscsit_check_session_usage_count+0x87/0x90 [iscsi_target_mod]

[<ffffffffc07c6665>] iscsit_close_session+0x165/0x230 [iscsi_target_mod]

[<ffffffffc07cc522>] lio_tpg_close_session+0x12/0x20 [iscsi_target_mod]

[<ffffffffc0811c8c>] target_release_session+0x2c/0x30

[target_core_mod]

[<ffffffffc0813cec>] target_put_session+0x2c/0x30 [target_core_mod]

[<ffffffffc07c67fe>] iscsit_logout_post_handler+0xce/0x260 [iscsi_target_mod]

[<ffffffffc07c6a66>] iscsit_response_queue+0xd6/0x730 [iscsi_target_mod]

[<ffffffffc07c56df>] iscsi_target_tx_thread+0x1bf/0x240 [iscsi_target_mod]

[<ffffffffb62c1c31>] kthread+0xd1/0xe0

[<ffffffffb6974c37>] ret_from_fork_nospec_end+0x0/0x39

[<ffffffffffffffff>] 0xffffffffffffffff

245 机器

  iscsit [iscsi_np]                  25620 D

[root@xdfs3 ~]# cat /proc/25620/stack

[<ffffffffc0851c48>] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod]

[<ffffffffc08427d3>] iscsi_check_for_session_reinstatement+0x213/0x280 [iscsi_target_mod]

[<ffffffffc08455d5>] iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod]

[<ffffffffc08456d9>] iscsi_target_do_login+0xf9/0x640 [iscsi_target_mod]

[<ffffffffc0846836>] iscsi_target_start_negotiation+0x56/0xc0 [iscsi_target_mod]

[<ffffffffc084424e>] __iscsi_target_login_thread+0x89e/0x1000 [iscsi_target_mod]

[<ffffffffc08449d8>] iscsi_target_login_thread+0x28/0x60 [iscsi_target_mod]

[<ffffffff962c1c31>] kthread+0xd1/0xe0

[<ffffffff96974c37>] ret_from_fork_nospec_end+0x0/0x39

[<ffffffffffffffff>] 0xffffffffffffffff

• 进程状态

  gluster-blockd--- active(running)

  gluster-block-target--- active(exited)

  target ---- inactive(dead) 应该 active(running) ？需要关注

  tcmu-runner —active-running

• kernel trigger blocked thread to print call trace

  与 cat /proc/*/stack 结果一致。

分析

1. 接收队列满

   试图设置更高的值，发现系统默认 net.core.somaxconn = 128，而且内核 target 代码设置 SCSIT_TCP_BACKLOG = 256 应该是合理的。一个疑问：somaxconn 是最大值，SCSIT_TCP_BACKLOG 怎么会超过呢？倾向于认为接收队列满是因为 hung 导致的。

2. 根据 call trace 搜寻一些 commit, 未果

模拟复现

根据 244 机器，一个正常 login 过程，一个属于 logout 过程。分析 calltrace，两个 calltrace 独立，互相不影响（？）。我们试图模拟出 login- perform reinstatement，本质就是 i 端登录失败后自己 relogin，内部机制，不是我们手动 relogin。

1. 排除 tcmu，利用 target backstore type pscsi，使用 scsi_debug 模拟的盘进行测试：
   在一定读写次数 (scsi_debug 参数 every_nth = 30) 后，/dev/sda 会忽略读写（scsi_debug 参数 opts = 0x4 表示忽略此 cmd，不返回），即永久超时。I 端大约在一定时间（由 device timeout 时间决定）后触发自己的超时机制，再次检查确认命令超时后会发送 abort （abort 前面那个超时的 cmd）给 target。由于 I 端设置 abort 的超时时间是 5s，但是后端即 target 的 /dev/sda 设备执行 abort 的时间设置为 120s-650s 之间（比如 scsi_debug 参数 abort_sleep = 120），导致 I 端 abort 失败。I 端进而发送 reset lun，然后 reset target ，并试图 reset session，等待 relogin，期间会进行 session recovery 。失败的话，会 offline device。

   在 i 端设置

   1. echo 5 > /sys/block/sda/device/timeout 默认 30s，i 端读写的时候一般要大约超时 180s 后才可能触发超时，然后重复确认，进而 abort/reset 等，时间比较长。为了复现尽可能快，设置为 5s。

   2. node.session.timeo.replacement_timeout = 5 , 默认 120s

   3. node.conn[0].timeo.login_timeout = 30，默认 15s

   4. node.conn[0].timeo.noop_out_timeout and 未改变
      node.conn[0].timeo.noop_out_interval = 5 未改变

   5. node.session.err_timeo.abort_timeout = 5 默认 15s

   2-4 项是 i 端的 /etc/iscsi/iscsid.conf 配置，replacement_timeout 是 recovery session 的 timeout 时间。

   abort_timeout 表示 abort 命令的超时时间。noop_out_timeout 表示发送 ping 到 target 端的超时时间，间隔 noop_out_interval 5s 再次发送。

   复现情况：

   复现出与原来烽火 bug 相同的 np 线程 hung。但是在大约一定时间后，np 又恢复正常。 具体与后端实际 hung 的时间有关，对于我们这个测试，就是与 abort_sleep 有关。
   也试图改变测试条件，但最终也没有复现出一直 hung 的情况。
   在 np 卡住的时候，命令行 I 端登录 target，没有立即完成，这时持续 ctrl+c 。持续多次登录 +ctrlC，直至 target 的 3260 端口 listen sock 的 accept 队列变满，同时所有 I-T 连接处于 closewait 状态。
   从这点来看，基本能复现出 accept 队列满。说明是 np 卡住或者某种原因来不及关闭已经建立的 sock，出现 closewait。但线上问题是只出现一个 closewait 状态，且 listen sock 的 accept 队列也满了。

2. 单 brick glusterfs I -T 环境：
   手动配置的 target，不是通过 gluster-block 配置。具体差别有

   • /sys/kernel/config/target/core/user_1/dust2lun/attrib/cmd_time_out gluster-block 130s 配置，手动默认配置是 30s。

   • /sys/kernel/config/target/core/user_1/dust2lun/attrib/max_data_area_mb gluster-block 配置 64MB，而手动默认配置是 1024MB，期间也进行了 1MB 的测试。

   • a 编译内核模块 dm_dust 模拟一些坏扇区进行测试。参数手动默认。没有出现 hung 的情况，只是 i 端 io 时有 input/output ERROR. 放弃测试。（可以试试持续 loop io 时，即使出现错误情况下也持续 io，类似于下面的测试）。
   • b 创建 lvm 或者 dm 设备作为 brick，I 端登录后在 brick 机器执行 dmsetup suspend dmdevice ，暂停 brick io
     • 手动默认参数情况下，即 cmd_time_out=30，max_data_area_mb=1024MB 下
       I 端持续 io 情况下，t 端没有发现任何 D 状态出现。
       初步认为是 tcmu 的 cmd_time_out 超时机制导致 target 给 i 端返回错误，规避了 target 的 backstore hung 的情况。对于非 tcmu 的 target，由于没有类似的超时机制，一切的超时处理都由 i 端实现。
     • 手动默认参数情况下，即 cmd_time_out=30，max_data_area_mb=1MB, 测试在 ringbuffer 满的情况下即极端或者异常情况
       发现在 libaio，direct=0 的情况下，很快 target 的 tcmu 的 ringbuffer 用满了，进而好多 cmd 排队。只是影响性能，并没有出现 io 错误等，也没有 hung 的情况（在当时的测试环境下）
       在 libaio，direct=1 下，估计后端存储性能不强，没有出现 ringbuffer 用满了的情况，也没有 hung 出现。
     • cmd_time_out=120，max_data_area_mb=1MB, node.session.timeo.replacement_timeout = 10
       为了让在 tcmu 情况下也出现 hung 的情况，分析了 target/i 端的 pscsi/tcmu 下的 debug log 和代码，试图设置 target 端的 set attribute login_timeout=10（目的是触发 target login timeout），以前设置的值是 15s，发现设置没有成功。然后设置 tcmu cmd_time_out=120/130（这个时间长了也会触发 target login timeout，与 pscsi 情况就有可能相同）。同时设置 node.session.timeo.replacement_timeout = 10，增加了原来 5s 的设置，延长 target 时间来恢复。
       在 libaio，direct=1 下，每隔 1s watch 进程状态，发现出现了 np 和 trx 的 D 状态。而且持续时间很长。但是可能是 cmd_time_out 设置的时间的问题，基本都是在一定时间比如小于 120s 后就又恢复为 S 状态，然后就又 D 状态一段时间。所以 dmesg 里并不会出现 np 等的 hung call trace，只是有当时 suspend brick 出现的 glusterfs io thread 线程的 call trace。

初步结论

1. 后端 hung，一般也会导致 np hung，但是目前只是复现出几乎 hung 的情况，并没有完全复现出。因为 cmd_time_out 存在，不会一直不返回的。
2. 假如后端 hung，还需要去修复 glusterfs 自身的问题。即然具有了 1 的 cmd_time_out 的功能，2 也不会是原因。
3. 至于 target 自身，包括 tcmu 的问题导致的 hung，也没有复现出，但有可能需要以下 bug 修复。可以采纳或者以验证的方式采用。
   Revist:
   对于 3，应该发散思维或者多找不同观点的同事或者朋友来沟通，也许才能最终找到本质问题。 虽然代码已经彻底分析了，但却不明了问题的解决方向在哪。事后看来，才感叹原来好像很明显啊。
   其实 1 和 2 已经表明问题的本质在 3. 其实从 stacktrace 角度和代码角度是很有可能作出是多个线程 (logout 线程、login 线程）等待一个资源，最后 hang 的问题。也试图在这方面进行多方面的尝试，具体可见下文。最终复现的方式是在在 logout 的同时，disable tpg 即 iscsit_free_session，其实与那个 login 线程里做的具体事情一样，最终都调用 iscsi_check_for_session_reinstatement。但由于对问题本质的不深刻把握，导致复现一直限于 logout/login 线程，不能直接的复现出来。

可能的 bug 修复

1. lost wakeup
   target 本身就 hung
   • https://www.spinics.net/lists/target-devel/msg16362.html
   • https://www.spinics.net/lists/target-devel/msg16463.html
     作者说

   Disclaimer: I do not understand why this problem did not show up before tcp prequeue removal.

我们内核并没有删除 tcp prequeue，所以应该不会触发这个 bug。
不过可以试试 sysctl tcp_low_latency=1 （不走 tcp prequeue 路径）验证是否 workaround hung 问题。
2. cmd 丢失超时问题
scsi: tcmu: avoid cmd/qfull timers updated whenever a new cmd comes
此 patch 解决了 tcmu 内核模块丢失某些 cmd 的超时 timer，有可能让某些 cmd 永远不返回，np hung。

一些概念和需要注意的

1. max_data_area_mb per lun
   tcmu 本身默认设置 1024MB，但 gluster-block 设置为 64MB。
   一个 scsi cmd 的控制部分基本是固定的，可变的是每个 scsi cmd 的数据 buffer。1G data area 基本上 8M cmd area。
   target 总的大小默认是 2GB。
   对于高 iops，低吞吐量的 IO，可以采用 64MB 的 gluter-block 的设置，但对于高吞吐量的 IO，应该设置大些。
   否则应该会有好多问题出现。

2. tcmu cmd_time_out 设置

   • a cmd_time_out=0, 以前 gluster block 默认设置
     Setting cmd_time_out to 0 means that the iscsi_trx will wait infinite until the cmds fired to tcmu-runner return back. Just in case if tcmu-runner is killed/terminated, the iscsi_trx will hung in D state infinitely。link
     即使设置 cmd_time_out >0, 如果某些 cmd 丢失超时设置，也会导致 D 状态。
   • b cmd_time_out > 0
     内核 tcmu cmd 超时机制，正常情况下即使 glusterfs hung，也不会导致 np 完全 hung 住
     alua HA 下 cmd_time_out 必须满足，cmd_time_out > GLUSTER ping timeout 42/5s（我们的设置） && cmd_time_out > replacement_timeout。
     • alua ha> 1 时，cmd_time_out 必须大于 replacement_timeout，以便 alua 路径正常恢复。 gluster-block 配置 cmd_time_out= 130s，replacement_timeout=120s。也必须大于 glusterfs ping timeout 42/（5s 是我们的 glusterfs 的设置）。
       在 brick hung 或者 tcmurunner hung/killed 时，target 会阻塞 130s（这时会有 D 状态也会有 dmesg blocekd 120s call trace 打印）。然后试图恢复。
       如下是 cmd_time_out 与 replacement_timeout 的关系的解释
       
     • alua ha=1 时，分析 i 端 iscsi 内核代码，cmd_time_out 与 replacement_timeout 应该没有任何关系。
       烽火线上配置是 cmd_time_out= 130s，replacement_timeout = 120s （假设客户用的标准 I 端程序），配置与 HA >1 时的相同。
       在设置 cmd_time_out=30s，replacement_timeout=5s 下，np 不 hung，也能登录成功。具体流程如下 tcmu session reinstatement target 端的流程
       1. 45:38 recv abort_task
       2. 45:43 rx=0
       3. 45:45 take action for connect exit
          cleanup_wait status ,close nection 0 on sid 1816
          transportgeneric free cmd detect cmd_t_aborted for its
       4. 5:45 recv login， sid1816 acitive,perf session reinstatement.
       5. 45:58 cmu_cmd_timedout:1287: dust2lun cmd timeout has expired

            target_core_user:tcmu_check_expired_cmd:1267: Timing out cmd 38 on dev dust2lun that is inflight.
            _transport_wait_for_tasks:3026: wait_for_tasks: Stopped wait_for_completion(&cmd- >t_transport_stop_comp) for ITT: 0x80000009
            ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 2147483657 1's
            lio_release_cmd
            iscsit_close_connection
            iscsit_close_session
            完成 session resinstatement
            Sending Login Response （成功）

如上流程第 4 步之后大约 13s 后，cmd_time_out 超时定时器失效，释放 cmd，释放原来的资源引用，session reinstatement 成功，登录成功。
对于 pscsi 测试情况，第四步 15s 后（即触发 target login timeout handler）导致 target 关闭自己的 socket，失败 session resinstatement，登录失败。
如果设置 cmd_time_out=130s，replacement_timeout=5s/10s 时，np hung 。如模拟复现部分 ---- 单 brick glusterfs I -T 环境项的最后一个复现条件。（可以测试 replacement_timeout=120s 下，类似烽火环境）

3. iscsi 登录过程理解，特别是 target 端的处理逻辑，可以参考这个 maillist 和对于的 RFC（具体的实现可能比 RFC 里的介绍的少）

   • https://www.spinics.net/lists/target-devel/msg14971.html
   • https://www.spinics.net/lists/target-devel/msg15401.html
   • https://www.spinics.net/lists/target-devel/msg15400.html

Todo:

1. 设置 i 端 logintimout 再小点可否复现？ 而不是 target 端 login timeout, 试试？

2. HA=1 时，到底是什么影响？cmd_time_out 应该小于 还是大于 replacement_timeout？

3. 生产复现时打开 i 端，target 端调试

target:

echo -n 'module iscsi_target_mod =pflmt; module target_core_mod  =pflmt; module target_core_user  =pflmt; module uio  =pflmt' > /sys/kernel/debug/dynamic_debug/control

i:

echo -n 'module libiscsi =pflmt; module libiscsi_tcp =pflmt; module scsi_transport_iscsi =pflmt; module iscsi_tcp =pflmt' > /sys/kernel/debug/dynamic_debug/control

echo 1 > /sys/module/iscsi_tcp/parameters/debug_iscsi_tcp
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_conn
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_eh
echo 1 > /sys/module/libiscsi/parameters/debug_libiscsi_session
echo 1 > /sys/module/scsi_transport_iscsi/parameters/debug_conn
echo 1 > /sys/module/scsi_transport_iscsi/parameters/debug_session
echo 1 > /sys/module/libiscsi_tcp/parameters/debug_libiscsi_tcp

4. 生产 / 复现时要 stop gluster-blockd 和 gluster-block-target，防止干扰。或者开启，以便确认是否干扰导致的 hung。

5. I 端用标准客户端时有个 bug，在 io 的时候 logout 然后 login，会导致发现的设备异常，要恢复正常的话，目前只能重启机器。正在定位。并提交 bug https://bugzilla.redhat.com/show_bug.cgi?id=1726051

6. 生产 / 复现时需要关注 target service 状态 ，验证 glusterfs 是否真正正常（reboot gluster volume 等）。采用 cat lun image 文件好像不能完全确定是否有问题。 还有上次 statedump 竟然没有文件输出。

7. 严格按照烽火环境参数配置测试。

8. target kernel warning _iscsit_free_cmd+0x26e/0x290 需要 定位

Revist: 名为 todo，其实是没有继续这个问题的定位，而是放弃了。

20200525 的 revisit

好奇现在是否社区已经解决了，从现在翻看回 201907 月份的 maillist。找到问题的解决方案了。
scsi: target: fix hang when multiple threads try to destroy the same iscsi session
LIO hanging in iscsit_free_session and iscsit_stop_session
其实也是与原来 stacktrace 和代码分析一致，只是没能从这个角度去有意的变通，去设计测试例。当然如果是一直是 target-devel/iscsi 的维护者，应该会有充分的经验能判断出问题所在。
这个问题看社区估计从 2018 年就有出现这个问题，但最终解决还是在 20200312.