nvme/tcp: infinite loop, livelock, and OOPS issues on disconnect

[Sagi Grimberg]

> Hello,
> 
> We've seen system hangs and OOPS with nvme/tcp with host-initiated
> disconnects during fault testing. To help debug, I've developed a short repro
> scenario (~5 minutes runtime) that triggers the issue on 5.15.65.

Does this happen on upstream as well?

> To reproduce:
> 
> On the host:
>   - run connect and disconnect to a single subsystem in a loop
> On the target:
>   - inject random transport failures every 1-2 seconds

Is this a single controller in the subsystem? or more?

> There are a few observed results:
> 
> 1. The system either hangs completely (reboot required) or nvme management
> commands hang (i.e., nvme list and nvme connect)

Would it be possible to check with the following applied?
41d07df7de84 ("nvme-tcp: always fail a request when sending it failed")

Perhaps its possible that we don't fail the command, and we are unable
to get to the iterator that cancels all commands becuase
nvme_remove_namespaces() is also blocked?

> 2. If the system stays alive, "nvme nvme1: failed to send request -32" streams
> from the kernel in an infinite loop.

Hmm, this is strange... this stream is when the system is hang and
without forward progress? or if the test continues?

> 
> 3. nvme tracing shows a loop trying to read the same lba:
> 
> kworker/2:1H-6376    [002] .....  4314.468725: nvme_setup_cmd:
>    nvme1: disk=nvme1c1n1, qid=3, cmdid=61519, nsid=1, flags=0x0, meta=0x0
>    cmd=(nvme_cmd_read slba=8, len=7, ctrl=0x0, dsmgmt=0, reftag=0)
> kworker/2:1H-6376    [002] .N...  4314.473568: nvme_complete_rq:
>    nvme1: disk=nvme1c1n1, qid=3, cmdid=61519, res=0x0, retries=0, flags=0x0,
>    status=0x370
> 
> 4. Hung task warnings for kernel worker threads:
> 
> INFO: task kworker/u16:2:6524 blocked for more than 491 seconds.
>        Not tainted 5.15.65-f0.el7.x86_64 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/u16:2   state:D stack:    0 pid: 6524 ppid:     2 flags:0x00004000
> Workqueue: nvme-wq nvme_scan_work [nvme_core]
> 
> Call Trace:
>   <TASK>
>   __schedule+0x390/0x910
>   ? scan_shadow_nodes+0x40/0x40
>   schedule+0x55/0xe0
>   io_schedule+0x16/0x40
>   do_read_cache_page+0x55d/0x850
>   ? __page_cache_alloc+0x90/0x90
>   read_cache_page+0x12/0x20
>   read_part_sector+0x3f/0x110
>   amiga_partition+0x3d/0x3e0
>   ? osf_partition+0x33/0x220
>   ? put_partition+0x90/0x90
>   bdev_disk_changed+0x1fe/0x4d0
>   blkdev_get_whole+0x7b/0x90
>   blkdev_get_by_dev+0xda/0x2d0
>   device_add_disk+0x356/0x3b0
>   nvme_mpath_set_live+0x13c/0x1a0 [nvme_core]
>   ? nvme_parse_ana_log+0xae/0x1a0 [nvme_core]
>   nvme_update_ns_ana_state+0x3a/0x40 [nvme_core]
>   nvme_mpath_add_disk+0x120/0x160 [nvme_core]
>   nvme_alloc_ns+0x594/0xa00 [nvme_core]
>   nvme_validate_or_alloc_ns+0xb9/0x1a0 [nvme_core]
>   ? __nvme_submit_sync_cmd+0x1d2/0x210 [nvme_core]
>   nvme_scan_work+0x281/0x410 [nvme_core]
>   process_one_work+0x1be/0x380
>   worker_thread+0x37/0x3b0
>   ? process_one_work+0x380/0x380
>   kthread+0x12d/0x150
>   ? set_kthread_struct+0x50/0x50
>   ret_from_fork+0x1f/0x30
>   </TASK>
> INFO: task nvme:6725 blocked for more than 491 seconds.
>        Not tainted 5.15.65-f0.el7.x86_64 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:nvme            state:D
>   stack:    0 pid: 6725 ppid:  1761 flags:0x00004000
> Call Trace:
>   <TASK>
>   __schedule+0x390/0x910
>   ? sched_clock+0x9/0x10
>   schedule+0x55/0xe0
>   schedule_timeout+0x24b/0x2e0
>   ? try_to_wake_up+0x358/0x510
>   ? finish_task_switch+0x88/0x2c0
>   wait_for_completion+0xa5/0x110
>   __flush_work+0x144/0x210
>   ? worker_attach_to_pool+0xc0/0xc0
>   flush_work+0x10/0x20
>   nvme_remove_namespaces+0x41/0xf0 [nvme_core]
>   nvme_do_delete_ctrl+0x47/0x66 [nvme_core]
>   nvme_sysfs_delete.cold.96+0x8/0xd [nvme_core]
>   dev_attr_store+0x14/0x30
>   sysfs_kf_write+0x38/0x50
>   kernfs_fop_write_iter+0x146/0x1d0
>   new_sync_write+0x114/0x1b0
>   ? intel_pmu_handle_irq+0xe0/0x420
>   vfs_write+0x18d/0x270
>   ksys_write+0x61/0xe0
>   __x64_sys_write+0x1a/0x20
>   do_syscall_64+0x37/0x90
>   entry_SYSCALL_64_after_hwframe+0x61/0xcb
> RIP: 0033:0x7ff4b79c4ba0
> RSP: 002b:00007fff37cea528 EFLAGS: 00000246
>   ORIG_RAX: 0000000000000001
> RAX: ffffffffffffffda RBX: 00000000006532e0 RCX: 00007ff4b79c4ba0
> RDX: 0000000000000001 RSI: 000000000043b146 RDI: 0000000000000003
> RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000001962fe0
> R10: 00007fff37ce9f60 R11: 0000000000000246 R12: 0000000001963090
> R13: 00007fff37ceab20 R14: 0000000000000037 R15: 00000000006535c0
>   </TASK>
> 
> 5. And, an occasional OOPS (same test, possibly a different issue)

There were some fixes related to oops observed sporadically with
connect/disconnect/reset loops. It was fixed in:
0fa0f99fc84e ("nvme: fix a possible use-after-free in controller reset 
during load")

Is it applied on your system?

> 
> BUG: kernel NULL pointer dereference, address: 0000000000000008
> #PF: supervisor read access in kernel mode
> #PF: error_code(0x0000) - not-present page
> PGD 0
> P4D 0
> Oops: 0000 [#1] SMP NOPTI
> CPU: 4 PID: 2131 Comm: kworker/4:2H Not tainted 5.15.65-f0.el7.x86_64 #1
> Hardware name: Supermicro SYS-1019S-WR/X11SSW-F, BIOS 2.1a 03/07/2018
> Workqueue:  0x0
>   (events_highpri)
> RIP: 0010:process_one_work+0x34/0x380
> Code: 57 41 56 41 55 41 54 49 89 fc 53 48 89 f3 48 83 ec 10 48 8b 06
> 4c 8b 7f 48 49 89 c5 45 30 ed a8 04 b8 00 00 00 00 4c 0f 44 e8 <49> 8b
> 45 08 44 8b b0 00 01 00 00 41 83 e6 20 41 f6 47 10 04 75 0f
> RSP: 0018:ffffc90001527e90 EFLAGS: 00010046
> RAX: 0000000000000000 RBX: ffff8881459395d0 RCX: dead000000000122
> RDX: 00000001001d8113 RSI: ffff8881459395d0 RDI: ffff888124d85c00
> RBP: ffffc90001527ec8 R08: ffff888857b2cea8 R09: 0000000000000381
> R10: 00000000000001ce R11: 0000000000000000 R12: ffff888124d85c00
> R13: 0000000000000000 R14: ffff888857b2c120 R15: ffff888857b2c100
> FS:  0000000000000000(0000) GS:ffff888857b00000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000000000008 CR3: 000000000260a006 CR4: 00000000003706e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Call Trace:
>   <TASK>
>   worker_thread+0x37/0x3b0
>   ? process_one_work+0x380/0x380
>   kthread+0x12d/0x150
>   ? set_kthread_struct+0x50/0x50
>   ret_from_fork+0x1f/0x30
>   </TASK>
> 
> If there is some way that I can assist, let me know.
> 
> Thanks,
> -Jonathan
>