search

open-iscsi / tcmu-runner

A daemon that handles the userspace side of the LIO TCM-User backstore.
Apache License 2.0
189 stars 148 forks source link

when tcmu-runner crash, [iscsi_np]/[iscsi_trx] process will stuck in D state #423

Open zhuozh opened 6 years ago

zhuozh commented 6 years ago

Test Environment: LIO: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master branch TCMU: latest code

When doing FIO rw test, If I kill tcmu-runner of the active path, after 6 minutes later, [iscsi_np]/[iscsi_trx] process will stuck in D state, the I_T session doesn't end it's life. Here is the process stack:

[root@sds-2-104 ~]# ps aux | grep iscsi root 11074 0.0 0.0 0 0 ? D 17:50 0:00 [iscsi_np] root 11081 5.1 0.0 0 0 ? D 17:50 0:10 [iscsi_trx] root 13816 0.0 0.0 112660 968 pts/1 S+ 17:54 0:00 grep --color=auto iscsi [root@sds-2-104 ~]# [root@sds-2-104 ~]# [root@sds-2-104 ~]# cat /sys/kernel/config/target/^C [root@sds-2-104 ~]# cat /proc/11074/stack [] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod] [] iscsi_check_for_session_reinstatement+0x213/0x280 [iscsi_target_mod] [] iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod] [] iscsi_target_do_login+0xf9/0x600 [iscsi_target_mod] [] iscsi_target_start_negotiation+0x56/0xc0 [iscsi_target_mod] [] iscsi_target_login_thread+0xb0b/0x1060 [iscsi_target_mod] [] kthread+0xcf/0xe0 [] ret_from_fork_nospec_end+0x0/0x39 [] 0xffffffffffffffff [root@sds-2-104 ~]# [root@sds-2-104 ~]# [root@sds-2-104 ~]# cat /proc/11081/stack [] __transport_wait_for_tasks+0xba/0x1b0 [target_core_mod] [] target_wait_free_cmd+0x56/0x90 [target_core_mod] [] transport_generic_free_cmd+0x115/0x150 [target_core_mod] [] iscsit_free_cmd+0x82/0x140 [iscsi_target_mod] [] iscsit_close_connection+0x4c6/0x8a0 [iscsi_target_mod] [] iscsit_take_action_for_connection_exit+0x8b/0x120 [iscsi_target_mod] [] iscsi_target_rx_thread+0xe3/0xf0 [iscsi_target_mod] [] kthread+0xcf/0xe0 [] ret_from_fork_nospec_end+0x0/0x39 [] 0xffffffffffffffff

Thanks for mike's reset ring patch, if I kill the runner, and let the runner come online within 5 minutes, IO can recovers and continues, it makes restart/upgrade runner possible. I tested the following scripts about 30 minutes, and it passed. while true;do systemctl start tcmu-runner;sleep 10;systemctl stop tcmu-runner;sleep 5;done

But if the runner offline for more than 5 minutes, [iscsi_np]/[iscsi_trx] process will stuck in D state forever. Can we fix this?

mikechristie commented 6 years ago

But if the runner offline for more than 5 minutes, [iscsi_np]/[iscsi_trx] process will stuck in D state forever.

I did not fully understand this comment.

In this test case, is runner just not restarted. You just leave it stopped for more than 5 minutes and just leave it down?

Or are you saying if you restart runner after 5 minutes then even when runner does the reset_ring operation the iscsi threads stay stuck. If this is the case, then it is a bug that we should fix.

For this issue though why is runner down so long? Isn't systemd setup so if runner crashes it is restarted? runner would then do its cleanup/reset_ring which fails outstanding commands so session level recovery can complete.

There is also the target_core_user cmd_timeout configfs setting which fails commands after N seconds. It is currently disabled by default. The problem is:

  1. It is failed with LUN comm failure which for some OSs is a hard failure and so the device could be offlined and the IO failure would be propogated to the application when we just want the IO retried.

  2. If the OS does not treat it as a hard failure, then the initiator layer might try a different path (or it might retry the same path), but because the outstanding commands were failed due to the cmd_timeout firing then the iscsi target layer is going to allow the relogin. The initiator will just fall back or depending on timing and OS continue to use that bad path and we will do the same thing. This will repeat over and over. If runner has not restarted then we want this path to be marked as bad/down until runner is restarted.

zhuozh commented 6 years ago

In this test case, is runner just not restarted. You just leave it stopped for more than 5 minutes and just leave it down? Or are you saying if you restart runner after 5 minutes then even when runner does the reset_ring operation the iscsi threads stay stuck. If this is the case, then it is a bug that we should fix.

Hi, mike. In my test, I stopped runner manually to test the reliability, and 5 minutes later, iscsi threads stuck in D state.

Isn't systemd setup so if runner crashes it is restarted?

'Restart=xx' is not set in tcmu-runner.service for now. Maybe we should add it.

we are using Linux as Target/Initiator OS, and set cmd_timeout atttribute to 30 minutes as default, the problem is that if runner does not come back within 5 minutes, the failing path can not recover even if runner is started again after 5 minutes later, the iscsi_np thread stuck in D state and the session is not clearly closed, which prevents initiator relogin.

mikechristie commented 6 years ago

runner is started again after 5 minutes later, the iscsi_np thread stuck in D state and the session is not clearly closed, which prevents initiator relogin.

If it is still stuck after restarting runner, you might be hitting a kernel bug.

What kernel are you using on the iscsi target side? Is it the RHEL/Centos 7.5 kernel by any chance?

zhuozh commented 6 years ago

What kernel are you using on the iscsi target side? Is it the RHEL/Centos 7.5 kernel by any chance?

Both RHEL 7.5 kernel(3.10.0-862.3.2) and Linus' master branch can reproduce this bug.

mikechristie commented 6 years ago

Is this easy for you to hit? I tried it here several times and am not able to hit it.

What type of initiator is this with?

With Linus's master branch can you run your test with target_core_user debugging on. Run:

echo "module target_core_user +p" > /sys/kernel/debug/dynamic_debug/control

then do your test and post the kernel log here.

zhuozh commented 6 years ago

It is 100% reproducible at my side. The initiator version is iscsi-initiator-utils-6.2.0.874-4.el7.x86_64 Here is the log:

[Mon Jun 4 17:50:27 2018] allocated cmd 34 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 22 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 28 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 33 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 34 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 22 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] allocated cmd 28 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:27 2018] close [Mon Jun 4 17:50:30 2018] close [Mon Jun 4 17:50:30 2018] allocated cmd 1 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 2 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 3 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 4 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 5 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 6 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 7 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 8 for dev rbd.block0 tmo 0 [Mon Jun 4 17:50:30 2018] allocated cmd 9 for dev rbd.block0 tmo 0 [Mon Jun 4 17:52:03 2018] ABORT_TASK: Found referenced iSCSI task_tag: 43 [Mon Jun 4 17:52:35 2018] iSCSI Login timeout on Network Portal 10.128.2.104:3260 [Mon Jun 4 17:54:41 2018] INFO: task iscsi_np:11971 blocked for more than 120 seconds. [Mon Jun 4 17:54:41 2018] Not tainted 4.17.0-rc7+ #11 [Mon Jun 4 17:54:41 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Mon Jun 4 17:54:41 2018] iscsi_np D 0 11971 2 0x80000084 [Mon Jun 4 17:54:41 2018] Call Trace: [Mon Jun 4 17:54:41 2018] ? schedule+0x28a/0x850 [Mon Jun 4 17:54:41 2018] schedule+0x32/0x80 [Mon Jun 4 17:54:41 2018] schedule_timeout+0x1d5/0x2f0 [Mon Jun 4 17:54:41 2018] wait_for_completion+0x123/0x190 [Mon Jun 4 17:54:41 2018] ? wake_up_q+0x70/0x70 [Mon Jun 4 17:54:41 2018] iscsit_cause_connection_reinstatement+0x95/0xe0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsit_stop_session+0x115/0x1b0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsi_check_for_session_reinstatement+0x1de/0x270 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsi_target_do_login+0xe8/0x5d0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsi_target_start_negotiation+0x51/0xa0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsi_target_login_thread+0x874/0xfc0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] ? schedule+0x260/0x850 [Mon Jun 4 17:54:41 2018] iscsi_target_login_thread+0x20/0x50 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] kthread+0xf5/0x130 [Mon Jun 4 17:54:41 2018] ? __iscsi_target_login_thread+0xfc0/0xfc0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] ? kthread_bind+0x10/0x10 [Mon Jun 4 17:54:41 2018] ret_from_fork+0x35/0x40 [Mon Jun 4 17:54:41 2018] INFO: task kworker/u64:1:13593 blocked for more than 120 seconds. [Mon Jun 4 17:54:41 2018] Not tainted 4.17.0-rc7+ #11 [Mon Jun 4 17:54:41 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Mon Jun 4 17:54:41 2018] kworker/u64:1 D 0 13593 2 0x80000080 [Mon Jun 4 17:54:41 2018] Workqueue: tmr-user target_tmr_work [target_core_mod] [Mon Jun 4 17:54:41 2018] Call Trace: [Mon Jun 4 17:54:41 2018] ? schedule+0x28a/0x850 [Mon Jun 4 17:54:41 2018] ? kvasprintf+0x7b/0xd0 [Mon Jun 4 17:54:41 2018] schedule+0x32/0x80 [Mon Jun 4 17:54:41 2018] schedule_timeout+0x15d/0x2f0 [Mon Jun 4 17:54:41 2018] ? __next_timer_interrupt+0xd0/0xd0 [Mon Jun 4 17:54:41 2018] wait_for_completion_timeout+0x12f/0x1a0 [Mon Jun 4 17:54:41 2018] ? wake_up_q+0x70/0x70 [Mon Jun 4 17:54:41 2018] transport_wait_for_tasks+0xd8/0x140 [target_core_mod] [Mon Jun 4 17:54:41 2018] transport_wait_for_tasks+0x55/0x90 [target_core_mod] [Mon Jun 4 17:54:41 2018] core_tmr_abort_task+0xed/0x170 [target_core_mod] [Mon Jun 4 17:54:41 2018] target_tmr_work+0x111/0x120 [target_core_mod] [Mon Jun 4 17:54:41 2018] process_one_work+0x152/0x350 [Mon Jun 4 17:54:41 2018] worker_thread+0x47/0x3e0 [Mon Jun 4 17:54:41 2018] kthread+0xf5/0x130 [Mon Jun 4 17:54:41 2018] ? max_active_store+0x80/0x80 [Mon Jun 4 17:54:41 2018] ? kthread_bind+0x10/0x10 [Mon Jun 4 17:54:41 2018] ret_from_fork+0x35/0x40 [Mon Jun 4 17:54:41 2018] INFO: task iscsi_trx:13771 blocked for more than 120 seconds. [Mon Jun 4 17:54:41 2018] Not tainted 4.17.0-rc7+ #11 [Mon Jun 4 17:54:41 2018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Mon Jun 4 17:54:41 2018] iscsi_trx D 0 13771 2 0x80000084 [Mon Jun 4 17:54:41 2018] Call Trace: [Mon Jun 4 17:54:41 2018] ? schedule+0x28a/0x850 [Mon Jun 4 17:54:41 2018] schedule+0x32/0x80 [Mon Jun 4 17:54:41 2018] schedule_timeout+0x1d5/0x2f0 [Mon Jun 4 17:54:41 2018] ? schedule+0x32/0x80 [Mon Jun 4 17:54:41 2018] ? schedule_timeout+0x1d5/0x2f0 [Mon Jun 4 17:54:41 2018] ? __next_timer_interrupt+0xd0/0xd0 [Mon Jun 4 17:54:41 2018] wait_for_completion+0x123/0x190 [Mon Jun 4 17:54:41 2018] ? wake_up_q+0x70/0x70 [Mon Jun 4 17:54:41 2018] transport_generic_free_cmd+0x6b/0x140 [target_core_mod] [Mon Jun 4 17:54:41 2018] iscsit_free_cmd+0x3e/0x90 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsit_close_connection+0x577/0x8e0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsit_take_action_for_connection_exit+0x7e/0x100 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] iscsi_target_rx_thread+0xdc/0xf0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] kthread+0xf5/0x130 [Mon Jun 4 17:54:41 2018] ? iscsi_target_tx_thread+0x1f0/0x1f0 [iscsi_target_mod] [Mon Jun 4 17:54:41 2018] ? kthread_bind+0x10/0x10 [Mon Jun 4 17:54:41 2018] ret_from_fork+0x35/0x40

mikechristie commented 6 years ago

When did you restart runner?

Did runner fail to restart? We did not see this message:

    pr_debug("mb last %u head %u tail %u\n", udev->cmdr_last_cleaned,
             mb->cmd_tail, mb->cmd_head);

get logged from target_core_user's tcmu_reset_ring function when runner writes to the reset_ring configfs file during restart.

zhuozh commented 6 years ago

Hi, mike, I did not restart runner, I just stop it. (systemctl stop tcmu-runner)

mikechristie commented 6 years ago

Hi, mike, I did not restart runner, I just stop it.

I think we are misunderstanding each other. What is the bug we are debugging?

Is the bug where runner restarts and the systems stays hung? You wrote this:

runner is started again after 5 minutes later, the iscsi_np thread stuck in D state and the session is not clearly closed, which prevents initiator relogin.

a couple days ago, so I thought we were trying to fix a bug where when runner restarts the iscsi threads are still stuck. Is that is the case then you should send me the logs for with target_core_user debugging enabled for when IO was started, runner was killed and then restarted so we can make sure target_core_user is failing all the outstanding IO so the iscsi session recovery can proceed. The iscsi threads are waiting on the outstanding commands to complete this operation and then allow new iscsi logins.

If you are just saying there is a bug where you kill runner and never restarted it and then the iscsi threads get and stay stuck, then that is expected behavior when cmd_timeout is 0. If it is greater than zero then that is bug and after the cmd timeout has fired the iscsi threads are still stuck then that is a bug too. You should send the logs with target_core_user debugging enabled for when IO was started, runner is killed and the cmd timer fires so we can make sure that is cleaning up all the outstanding IO so the iscsi session recovery can proceed.

zhuozh commented 6 years ago

runner is started again after 5 minutes later, the iscsi_np thread stuck in D state and the session is not clearly closed, which prevents initiator relogin. Sorry, :-) I might misleading you here, since I am using ceph-iscsi-config, so the cmd_timeout is 0, I stop the runner manually, iscsi_np thread will stuck in D state after 5 minutes later. I tried start runner manually, iscsi_np thread can't recover from D state.

that is expected behavior when cmd_timeout is 0. So we don't care it even if it cause an unrecoverable failure?

By following your guide, I set cmd_timeout to 30, cmd remaining in the ring and the newly coming cmd will time out. session recover after runner come online. Since cmd_timeout is so important, can we give user some guide in the manual, or expose an interface in ceph-iscsi-config to give user a chance to decide it's value when creating LUNs.

Here is the log in case someone else is interest in this topic.

[Wed Jun 6 13:45:37 2018] allocated cmd 5 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 22 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 47 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 61 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 62 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 10 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 47 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 10 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] allocated cmd 47 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:37 2018] close [Wed Jun 6 13:45:38 2018] close [Wed Jun 6 13:45:38 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 2 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 3 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 4 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 5 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 6 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 7 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 8 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 9 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 10 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 11 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 12 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 13 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 14 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 15 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 16 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 17 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 18 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 19 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 20 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 21 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 22 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 23 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 24 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 25 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 26 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 27 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 28 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 29 for dev rbd.block0 tmo 30 [Wed Jun 6 13:45:38 2018] allocated cmd 30 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:46:08 2018] Timing out cmd 1 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 2 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 3 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 4 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 5 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 6 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 7 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 8 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 9 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 10 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 11 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 12 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 13 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 14 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 15 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 16 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 17 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 18 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 19 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 20 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 21 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 22 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 23 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 24 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 25 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 26 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 27 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 28 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 29 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] Timing out cmd 30 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:08 2018] allocated cmd 31 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 32 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 33 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 34 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 35 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 36 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 37 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 38 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 39 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 40 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 41 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 42 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 43 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 44 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 45 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 46 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 47 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 48 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 49 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 50 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 51 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 52 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 53 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 54 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 55 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 56 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 57 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 58 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 59 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 60 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 61 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 62 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 63 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 64 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:08 2018] allocated cmd 65 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:40 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:46:40 2018] Timing out cmd 31 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 32 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 33 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 34 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 35 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 36 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 37 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 38 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 39 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 40 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 41 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 42 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 43 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 44 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 45 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 46 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 47 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 48 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 49 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 50 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 51 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 52 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 53 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 54 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 55 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 56 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 57 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 58 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 59 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 60 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 61 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 62 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 63 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 64 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] Timing out cmd 65 on dev rbd.block0 that is inflight. [Wed Jun 6 13:46:40 2018] allocated cmd 66 for dev rbd.block0 tmo 30 [Wed Jun 6 13:46:45 2018] allocated cmd 67 for dev rbd.block0 tmo 30 [Wed Jun 6 13:47:16 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:47:16 2018] Timing out cmd 66 on dev rbd.block0 that is inflight. [Wed Jun 6 13:47:16 2018] Timing out cmd 67 on dev rbd.block0 that is inflight. [Wed Jun 6 13:47:16 2018] allocated cmd 68 for dev rbd.block0 tmo 30 [Wed Jun 6 13:47:22 2018] allocated cmd 69 for dev rbd.block0 tmo 30 [Wed Jun 6 13:47:53 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:47:53 2018] Timing out cmd 68 on dev rbd.block0 that is inflight. [Wed Jun 6 13:47:53 2018] Timing out cmd 69 on dev rbd.block0 that is inflight. [Wed Jun 6 13:47:53 2018] allocated cmd 70 for dev rbd.block0 tmo 30 [Wed Jun 6 13:47:59 2018] allocated cmd 71 for dev rbd.block0 tmo 30 [Wed Jun 6 13:48:30 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:48:30 2018] Timing out cmd 70 on dev rbd.block0 that is inflight. [Wed Jun 6 13:48:30 2018] Timing out cmd 71 on dev rbd.block0 that is inflight. [Wed Jun 6 13:48:30 2018] allocated cmd 72 for dev rbd.block0 tmo 30 [Wed Jun 6 13:48:35 2018] allocated cmd 73 for dev rbd.block0 tmo 30 [Wed Jun 6 13:49:07 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:49:07 2018] Timing out cmd 72 on dev rbd.block0 that is inflight. [Wed Jun 6 13:49:07 2018] Timing out cmd 73 on dev rbd.block0 that is inflight. [Wed Jun 6 13:49:07 2018] allocated cmd 74 for dev rbd.block0 tmo 30 [Wed Jun 6 13:49:12 2018] allocated cmd 75 for dev rbd.block0 tmo 30 [Wed Jun 6 13:49:43 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:49:43 2018] Timing out cmd 74 on dev rbd.block0 that is inflight. [Wed Jun 6 13:49:43 2018] Timing out cmd 75 on dev rbd.block0 that is inflight. [Wed Jun 6 13:49:44 2018] allocated cmd 76 for dev rbd.block0 tmo 30 [Wed Jun 6 13:49:49 2018] allocated cmd 77 for dev rbd.block0 tmo 30 [Wed Jun 6 13:50:20 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:50:20 2018] Timing out cmd 76 on dev rbd.block0 that is inflight. [Wed Jun 6 13:50:20 2018] Timing out cmd 77 on dev rbd.block0 that is inflight. [Wed Jun 6 13:50:20 2018] allocated cmd 78 for dev rbd.block0 tmo 30 [Wed Jun 6 13:50:26 2018] allocated cmd 79 for dev rbd.block0 tmo 30 [Wed Jun 6 13:50:58 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:50:58 2018] Timing out cmd 78 on dev rbd.block0 that is inflight. [Wed Jun 6 13:50:58 2018] Timing out cmd 79 on dev rbd.block0 that is inflight. [Wed Jun 6 13:50:58 2018] allocated cmd 80 for dev rbd.block0 tmo 30 [Wed Jun 6 13:51:03 2018] allocated cmd 81 for dev rbd.block0 tmo 30 [Wed Jun 6 13:51:35 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:51:35 2018] Timing out cmd 80 on dev rbd.block0 that is inflight. [Wed Jun 6 13:51:35 2018] Timing out cmd 81 on dev rbd.block0 that is inflight. [Wed Jun 6 13:51:36 2018] allocated cmd 82 for dev rbd.block0 tmo 30 [Wed Jun 6 13:51:40 2018] allocated cmd 83 for dev rbd.block0 tmo 30 [Wed Jun 6 13:52:11 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:52:11 2018] Timing out cmd 82 on dev rbd.block0 that is inflight. [Wed Jun 6 13:52:11 2018] Timing out cmd 83 on dev rbd.block0 that is inflight. [Wed Jun 6 13:52:11 2018] allocated cmd 84 for dev rbd.block0 tmo 30 [Wed Jun 6 13:52:17 2018] allocated cmd 85 for dev rbd.block0 tmo 30 [Wed Jun 6 13:52:48 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:52:48 2018] Timing out cmd 84 on dev rbd.block0 that is inflight. [Wed Jun 6 13:52:48 2018] Timing out cmd 85 on dev rbd.block0 that is inflight. [Wed Jun 6 13:52:48 2018] allocated cmd 86 for dev rbd.block0 tmo 30 [Wed Jun 6 13:52:53 2018] allocated cmd 87 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:25 2018] rbd.block0 cmd timeout has expired [Wed Jun 6 13:53:25 2018] Timing out cmd 86 on dev rbd.block0 that is inflight. [Wed Jun 6 13:53:25 2018] Timing out cmd 87 on dev rbd.block0 that is inflight. [Wed Jun 6 13:53:25 2018] allocated cmd 88 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:30 2018] allocated cmd 89 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] tcmu daemon: command reply support 1. [Wed Jun 6 13:53:48 2018] removing cmd 1 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 2 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 3 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 4 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 5 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 6 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 7 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 8 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 9 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 10 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 11 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 12 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 13 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 14 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 15 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 16 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 17 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 18 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 19 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 20 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 21 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 22 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 23 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 24 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 25 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 26 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 27 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 28 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 29 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 30 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 31 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 32 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 33 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 34 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 35 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 36 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 37 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 38 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 39 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 40 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 41 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 42 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 43 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 44 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 45 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 46 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 47 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 48 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 49 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 50 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 51 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 52 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 53 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 54 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 55 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 56 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 57 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 58 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 59 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 60 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 61 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 62 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 63 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 64 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 65 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 66 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 67 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 68 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 69 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 70 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 71 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 72 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 73 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 74 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 75 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 76 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 77 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 78 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 79 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 80 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 81 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 82 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 83 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 84 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 85 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 86 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 87 on dev rbd.block0 from ring (is expired 1) [Wed Jun 6 13:53:48 2018] removing cmd 88 on dev rbd.block0 from ring (is expired 0) [Wed Jun 6 13:53:48 2018] removing cmd 89 on dev rbd.block0 from ring (is expired 0) [Wed Jun 6 13:53:48 2018] mb last 3288464 head 3288464 tail 3299688 [Wed Jun 6 13:53:48 2018] open [Wed Jun 6 13:53:48 2018] mb last 0 head 0 tail 0 [Wed Jun 6 13:53:48 2018] open [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 2 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 2 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 3 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 4 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 1 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 2 for dev rbd.block0 tmo 30 [Wed Jun 6 13:53:48 2018] allocated cmd 3 for dev rbd.block0 tmo 30

mikechristie commented 6 years ago

Why is it so important for you to have these commands failed though? What problem are you trying to solve? Is it just because you do not want to see the hung task messages? It is coded this way for a reason. It is not always safe to fail the command in the kernel while it is still running in user space.

With cmd_timeout=0 the session recovery will complete and lio will allow relogins when runner restarts. Why is it such a big deal that we have the waiting tasks while this is not done?