Bug 209763

Summary: timeout observed with blktests nvme/tcp nvme/012
Product: IO/Storage Reporter: yizhan
Component: NVMeAssignee: IO/NVME Virtual Default Assignee (io_nvme)
Status: NEW ---    
Severity: normal    
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 5.9.0 Subsystem:
Regression: No Bisected commit-id:

Description yizhan 2020-10-20 07:28:05 UTC 
The WARNING[1] was fixed by ming's patch[2], but the timeout issue still exists, so file this issue to track it.

[1]
refcount_t: underflow; use-after-free
https://marc.info/?l=linux-block&m=160215221708632&w=2

[2]
https://marc.info/?l=linux-block&m=160285851624680&w=2


Reproduce steps:
cd /root/blktests;
nvme_trtype=tcp ./check nvme/012

ENV:
# lscpu 
Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   48 bits physical, 48 bits virtual
CPU(s):                          12
On-line CPU(s) list:             0-11
Thread(s) per core:              1
Core(s) per socket:              6
Socket(s):                       2
NUMA node(s):                    2
Vendor ID:                       AuthenticAMD
CPU family:                      16
Model:                           8
Model name:                      Six-Core AMD Opteron(tm) Processor 2427
Stepping:                        0
CPU MHz:                         800.000
CPU max MHz:                     2200.0000
CPU min MHz:                     800.0000
BogoMIPS:                        4399.80
Virtualization:                  AMD-V
L1d cache:                       768 KiB
L1i cache:                       768 KiB
L2 cache:                        6 MiB
L3 cache:                        12 MiB
NUMA node0 CPU(s):               0,2,4,6,8,10
NUMA node1 CPU(s):               1,3,5,7,9,11
Vulnerability Itlb multihit:     Not affected
Vulnerability L1tf:              Not affected
Vulnerability Mds:               Not affected
Vulnerability Meltdown:          Not affected
Vulnerability Spec store bypass: Not affected
Vulnerability Spectre v1:        Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2:        Mitigation; Full AMD retpoline, STIBP disabled, RSB filling
Vulnerability Srbds:             Not affected
Vulnerability Tsx async abort:   Not affected
Flags:                           fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm 3dnowext 3dnow constant_tsc rep_good nopl non
                                 stop_tsc cpuid extd_apicid pni monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt hw_pstate vmmcall npt lbrv svm_lock nrip_s
                                 ave pausefilter
# free
              total        used        free      shared  buff/cache   available
Mem:        4028996      182088     3367340         972      479568     3569996
Swap:       4156412           0     4156412


dmesg:
[32808.189629] run blktests nvme/012 at 2020-10-19 06:57:14
[32808.282069] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[32808.301481] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
[32808.317042] nvmet: creating controller 1 for subsystem blktests-subsystem-1 for NQN nqn.2014-08.org.nvmexpress:uuid:28ec29d001764c9dba1badd56054949b.
[32808.331467] nvme nvme0: creating 12 I/O queues.
[32808.339810] nvme nvme0: mapped 12/0/0 default/read/poll queues.
[32808.351438] nvme nvme0: new ctrl: NQN "blktests-subsystem-1", addr 127.0.0.1:4420
[32810.288546] XFS (nvme0n1): Mounting V5 Filesystem
[32810.302727] XFS (nvme0n1): Ending clean mount
[32810.308744] xfs filesystem being mounted at /mnt/blktests supports timestamps until 2038 (0x7fffffff)
[32870.677814] nvme nvme0: queue 1: timeout request 0x61 type 4
[32870.683500] nvme nvme0: starting error recovery
[32870.688092] nvme nvme0: queue 4: timeout request 0x31 type 4
[32870.688657] block nvme0n1: no usable path - requeuing I/O
[32870.694366] nvme nvme0: Reconnecting in 10 seconds...
[32870.699182] block nvme0n1: no usable path - requeuing I/O
[32870.699187] block nvme0n1: no usable path - requeuing I/O
[32870.699193] block nvme0n1: no usable path - requeuing I/O
[32870.720401] block nvme0n1: no usable path - requeuing I/O
[32870.725810] block nvme0n1: no usable path - requeuing I/O
[32870.731215] block nvme0n1: no usable path - requeuing I/O
[32870.736627] block nvme0n1: no usable path - requeuing I/O
[32870.742024] block nvme0n1: no usable path - requeuing I/O
[32870.747431] block nvme0n1: no usable path - requeuing I/O
[32896.277358] nvmet: ctrl 2 keep-alive timer (15 seconds) expired!
[32896.283380] nvmet: ctrl 2 fatal error occurred!
[32900.885454] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[32900.891465] nvmet: ctrl 1 fatal error occurred!
[32924.104385] nvmet: creating controller 2 for subsystem blktests-subsystem-1 for NQN nqn.2014-08.org.nvmexpress:uuid:28ec29d001764c9dba1badd56054949b.
[32942.358330] nvme nvme0: queue 0: timeout request 0x0 type 4
[32942.363969] nvme nvme0: Connect command failed, error wo/DNR bit: 881
[32942.370408] nvme nvme0: failed to connect queue: 0 ret=881
[32942.375910] nvme nvme0: Failed reconnect attempt 1
[32942.380688] nvme nvme0: Reconnecting in 10 seconds...
[32952.599223] nvmet: creating controller 1 for subsystem blktests-subsystem-1 for NQN nqn.2014-08.org.nvmexpress:uuid:28ec29d001764c9dba1badd56054949b.
[32952.613274] nvme_ns_head_submit_bio: 6 callbacks suppressed
[32952.613282] block nvme0n1: no usable path - requeuing I/O
[32952.624276] block nvme0n1: no usable path - requeuing I/O
[32952.629679] block nvme0n1: no usable path - requeuing I/O
[32952.635078] block nvme0n1: no usable path - requeuing I/O
[32952.640484] block nvme0n1: no usable path - requeuing I/O
[32952.645890] block nvme0n1: no usable path - requeuing I/O
[32952.651300] block nvme0n1: no usable path - requeuing I/O
[32952.656701] block nvme0n1: no usable path - requeuing I/O
[32952.662107] block nvme0n1: no usable path - requeuing I/O
[32952.667522] block nvme0n1: no usable path - requeuing I/O
[32952.673156] nvme nvme0: creating 12 I/O queues.
[32952.791830] nvme nvme0: mapped 12/0/0 default/read/poll queues.
[32952.800343] nvme nvme0: Successfully reconnected (2 attempt)
[33006.871736] nvme nvme0: queue 11: timeout request 0x22 type 4
[33006.877487] nvme nvme0: starting error recovery
[33006.882487] nvme_ns_head_submit_bio: 14 callbacks suppressed
[33006.882494] block nvme0n1: no usable path - requeuing I/O
[33006.884161] nvme nvme0: Reconnecting in 10 seconds...
[33006.888192] block nvme0n1: no usable path - requeuing I/O
[33006.904052] block nvme0n1: no usable path - requeuing I/O
[33006.909472] block nvme0n1: no usable path - requeuing I/O
[33006.914902] block nvme0n1: no usable path - requeuing I/O
[33006.920325] block nvme0n1: no usable path - requeuing I/O
[33006.925739] block nvme0n1: no usable path - requeuing I/O
[33006.931149] block nvme0n1: no usable path - requeuing I/O
[33006.936567] block nvme0n1: no usable path - requeuing I/O
[33006.941981] block nvme0n1: no usable path - requeuing I/O
[33032.472272] nvmet: ctrl 2 keep-alive timer (15 seconds) expired!
[33032.478284] nvmet: ctrl 2 fatal error occurred!
[33035.032289] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[33035.038438] nvmet: ctrl 1 fatal error occurred!
[33055.669945] nvmet: creating controller 2 for subsystem blktests-subsystem-1 for NQN nqn.2014-08.org.nvmexpress:uuid:28ec29d001764c9dba1badd56054949b.
[33077.529217] nvme nvme0: queue 0: timeout request 0x1 type 4
[33077.534871] nvme nvme0: Connect command failed, error wo/DNR bit: 881
[33077.541363] nvme nvme0: failed to connect queue: 0 ret=881
[33077.546869] nvme nvme0: Failed reconnect attempt 1
[33077.551654] nvme nvme0: Reconnecting in 10 seconds...
[33087.770043] nvmet: creating controller 1 for subsystem blktests-subsystem-1 for NQN nqn.2014-08.org.nvmexpress:uuid:28ec29d001764c9dba1badd56054949b.
[33087.784153] nvme_ns_head_submit_bio: 1 callbacks suppressed
[33087.784160] block nvme0n1: no usable path - requeuing I/O
[33087.795145] block nvme0n1: no usable path - requeuing I/O
[33087.800540] block nvme0n1: no usable path - requeuing I/O
[33087.805938] block nvme0n1: no usable path - requeuing I/O
[33087.811355] block nvme0n1: no usable path - requeuing I/O
[33087.816745] block nvme0n1: no usable path - requeuing I/O
[33087.822139] block nvme0n1: no usable path - requeuing I/O
[33087.827521] block nvme0n1: no usable path - requeuing I/O
[33087.832915] block nvme0n1: no usable path - requeuing I/O
[33087.838310] block nvme0n1: no usable path - requeuing I/O
[33087.843885] nvme nvme0: creating 12 I/O queues.
[33087.912280] nvme nvme0: mapped 12/0/0 default/read/poll queues.
[33087.914247] XFS (nvme0n1): Unmounting Filesystem
[33087.923037] nvme nvme0: Successfully reconnected (2 attempt)
[33088.069626] nvme nvme0: Removing ctrl: NQN "blktests-subsystem-1"