Re: [bug report] blktests nvme/tcp failed on the latest linux-block/for-next

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



[CC'ing Hannes]

On Wed, Oct 18, 2023 at 10:06:54PM +0800, Yi Zhang wrote:
> Hello
> I found most of the blktests nvme/tcp failed[2] on the latest
> linux-block/for-next[1], please help check it, I will try to bisect
> it, thanks.
> 
> [1]
> https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git/log/?h=for-next
> e3db512c4ab6 (HEAD -> for-next, origin/for-next) Merge branch
> 'for-6.7/block' into for-next
> 
> [2]
> # nvme_trtype=tcp ./check nvme/003
> nvme/003 (test if we're sending keep-alives to a discovery controller) [failed]
>     runtime  13.731s  ...  12.676s
>     something found in dmesg:
>     [ 5149.710328] run blktests nvme/003 at 2023-10-18 09:58:24
>     [ 5149.819809] loop0: detected capacity change from 0 to 2097152
>     [ 5149.846524] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
>     [ 5149.880347] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
>     [ 5149.934226] nvmet: creating discovery controller 1 for
> subsystem nqn.2014-08.org.nvmexpress.discovery for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
>     [ 5149.954001] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery", addr 127.0.0.1:4420
>     [ 5161.391083] nvme nvme0: Removing ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery"
>     [ 5161.400970] ------------[ cut here ]------------
>     [ 5161.405594] ODEBUG: assert_init not available (active state 0)
> object: 0000000004184194 object type: timer_list hint: 0x0
>     [ 5161.416566] WARNING: CPU: 6 PID: 55 at lib/debugobjects.c:514
> debug_print_object+0x199/0x2c0
>     ...
>     (See '/root/blktests/results/nodev/nvme/003.dmesg' for the entire message)
> 
> # cat /root/blktests/results/nodev/nvme/003.dmesg
> [ 5149.710328] run blktests nvme/003 at 2023-10-18 09:58:24
> [ 5149.819809] loop0: detected capacity change from 0 to 2097152
> [ 5149.846524] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
> [ 5149.880347] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
> [ 5149.934226] nvmet: creating discovery controller 1 for subsystem
> nqn.2014-08.org.nvmexpress.discovery for NQN
> nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349.
> [ 5149.954001] nvme nvme0: new ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery", addr 127.0.0.1:4420
> [ 5161.391083] nvme nvme0: Removing ctrl: NQN
> "nqn.2014-08.org.nvmexpress.discovery"
> [ 5161.400970] ------------[ cut here ]------------
> [ 5161.405594] ODEBUG: assert_init not available (active state 0)
> object: 0000000004184194 object type: timer_list hint: 0x0
> [ 5161.416566] WARNING: CPU: 6 PID: 55 at lib/debugobjects.c:514
> debug_print_object+0x199/0x2c0
> [ 5161.425003] Modules linked in: loop nvmet_tcp nvmet nvme_common
> nvme_tcp nvme_fabrics nvme_core rpcsec_gss_krb5 auth_rpcgss nfsv4
> dns_resolver nfs lockd grace fscache netfs rfkill sunrpc vfat fat
> dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
> intel_uncore_frequency_common isst_if_common skx_edac
> x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm mgag200
> irqbypass rapl iTCO_wdt iTCO_vendor_support i2c_algo_bit mei_me
> ipmi_ssif intel_cstate drm_shmem_helper dell_smbios dcdbas
> intel_uncore dell_wmi_descriptor wmi_bmof drm_kms_helper pcspkr
> acpi_ipmi mei i2c_i801 lpc_ich intel_pch_thermal i2c_smbus ipmi_si
> ipmi_devintf ipmi_msghandler dax_pmem acpi_power_meter drm fuse xfs
> libcrc32c nd_pmem nd_btt sd_mod t10_pi sg crct10dif_pclmul
> crc32_pclmul crc32c_intel ahci libahci ghash_clmulni_intel tg3 libata
> megaraid_sas wmi nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod
> [last unloaded: loop]
> [ 5161.506243] CPU: 6 PID: 55 Comm: kworker/6:0 Tainted: G        W
>       6.6.0-rc3+ #3
> [ 5161.514244] Hardware name: Dell Inc. PowerEdge R640/06NR82, BIOS
> 2.17.1 11/15/2022
> [ 5161.521808] Workqueue: nvmet-wq nvmet_tcp_release_queue_work [nvmet_tcp]
> [ 5161.528516] RIP: 0010:debug_print_object+0x199/0x2c0
> [ 5161.533481] Code: 8d 3c dd 80 8a 17 9d 48 89 fa 48 c1 ea 03 80 3c
> 02 00 75 54 41 55 48 8b 14 dd 80 8a 17 9d 48 c7 c7 a0 7b 17 9d e8 c7
> 82 fd fe <0f> 0b 58 83 05 c9 a8 33 03 01 48 83 c4 20 5b 5d 41 5c 41 5d
> 41 5e
> [ 5161.552227] RSP: 0018:ffffc900009af998 EFLAGS: 00010096
> [ 5161.557454] RAX: 0000000000000000 RBX: 0000000000000005 RCX: 0000000000000000
> [ 5161.564586] RDX: 0000000000000002 RSI: 0000000000000004 RDI: 0000000000000001
> [ 5161.571719] RBP: 0000000000000002 R08: 0000000000000001 R09: ffffed11c697dfa9
> [ 5161.578850] R10: ffff888e34befd4b R11: 0000000000000001 R12: ffffffff9cf2d4e0
> [ 5161.585984] R13: 0000000000000000 R14: ffffc900009afa58 R15: ffffffff9cf2d4e0
> [ 5161.593116] FS:  0000000000000000(0000) GS:ffff888e34a00000(0000)
> knlGS:0000000000000000
> [ 5161.601202] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 5161.606947] CR2: 00005638a5d9ffea CR3: 00000003bb24e003 CR4: 00000000007706e0
> [ 5161.614080] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 5161.621211] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 5161.628343] PKRU: 55555554
> [ 5161.631056] Call Trace:
> [ 5161.633511]  <TASK>
> [ 5161.635616]  ? __warn+0xc9/0x350
> [ 5161.638848]  ? debug_print_object+0x199/0x2c0
> [ 5161.643209]  ? report_bug+0x326/0x3c0
> [ 5161.646875]  ? handle_bug+0x3c/0x70
> [ 5161.650364]  ? exc_invalid_op+0x14/0x50
> [ 5161.654206]  ? asm_exc_invalid_op+0x16/0x20
> [ 5161.658394]  ? debug_print_object+0x199/0x2c0
> [ 5161.662750]  ? debug_print_object+0x199/0x2c0
> [ 5161.667108]  ? do_raw_spin_unlock+0x55/0x1f0
> [ 5161.671383]  debug_object_assert_init+0x27d/0x3c0
> [ 5161.676089]  ? __pfx_debug_object_assert_init+0x10/0x10
> [ 5161.681313]  ? lock_acquire+0x4db/0x5e0
> [ 5161.685152]  ? __pfx_try_to_wake_up+0x10/0x10
> [ 5161.689510]  ? do_raw_spin_trylock+0xb5/0x180
> [ 5161.693872]  ? __timer_delete+0x70/0x170
> [ 5161.697797]  __timer_delete+0x70/0x170
> [ 5161.701550]  ? __pfx___timer_delete+0x10/0x10
> [ 5161.705907]  ? __mutex_lock+0x741/0x14b0
> [ 5161.709833]  ? try_to_grab_pending+0x70/0x80
> [ 5161.714105]  ? rcu_is_watching+0x11/0xb0
> [ 5161.718032]  try_to_grab_pending+0x46/0x80
> [ 5161.722132]  __cancel_work_timer+0xa0/0x460
> [ 5161.726318]  ? mutex_lock_io_nested+0x1273/0x1310
> [ 5161.731024]  ? __pfx___cancel_work_timer+0x10/0x10
> [ 5161.735816]  ? do_raw_write_trylock+0xb5/0x190
> [ 5161.740260]  ? __pfx_do_raw_write_trylock+0x10/0x10
> [ 5161.745141]  ? rcu_is_watching+0x11/0xb0
> [ 5161.749066]  ? trace_irq_enable.constprop.0+0x13d/0x180
> [ 5161.754292]  ? __pfx_sk_stream_write_space+0x10/0x10
> [ 5161.759258]  nvmet_tcp_release_queue_work+0x2db/0x1350 [nvmet_tcp]
> [ 5161.765438]  ? rcu_is_watching+0x11/0xb0
> [ 5161.769362]  ? process_one_work+0x6b5/0x13f0
> [ 5161.773637]  process_one_work+0x7c1/0x13f0
> [ 5161.777737]  ? __pfx___lock_release+0x10/0x10
> [ 5161.782093]  ? __pfx_process_one_work+0x10/0x10
> [ 5161.786630]  ? assign_work+0x16c/0x240
> [ 5161.790378]  ? rcu_is_watching+0x11/0xb0
> [ 5161.794306]  worker_thread+0x721/0xfd0
> [ 5161.798060]  ? __pfx_worker_thread+0x10/0x10
> [ 5161.802332]  kthread+0x2f8/0x3e0
> [ 5161.805562]  ? _raw_spin_unlock_irq+0x24/0x50
> [ 5161.809921]  ? __pfx_kthread+0x10/0x10
> [ 5161.813674]  ret_from_fork+0x2d/0x70
> [ 5161.817254]  ? __pfx_kthread+0x10/0x10
> [ 5161.821007]  ret_from_fork_asm+0x1b/0x30
> [ 5161.824937]  </TASK>
> [ 5161.827125] irq event stamp: 40414
> [ 5161.830530] hardirqs last  enabled at (40413): [<ffffffff9caa5aa4>]
> _raw_spin_unlock_irq+0x24/0x50
> [ 5161.839482] hardirqs last disabled at (40414): [<ffffffff9ca8bc48>]
> __schedule+0xa68/0x1d80
> [ 5161.847829] softirqs last  enabled at (35660): [<ffffffff9caa8a3b>]
> __do_softirq+0x5db/0x8f6
> [ 5161.856261] softirqs last disabled at (35653): [<ffffffff9a64c4dc>]
> __irq_exit_rcu+0xbc/0x210
> [ 5161.864780] ---[ end trace 0000000000000000 ]---
> [ 5161.869451] ------------[ cut here ]------------
> [ 5161.874112] WARNING: CPU: 6 PID: 55 at kernel/workqueue.c:3400
> __flush_work+0x165/0x180
> [ 5161.882154] Modules linked in: loop nvmet_tcp nvmet nvme_common
> nvme_tcp nvme_fabrics nvme_core rpcsec_gss_krb5 auth_rpcgss nfsv4
> dns_resolver nfs lockd grace fscache netfs rfkill sunrpc vfat fat
> dm_multipath intel_rapl_msr intel_rapl_common intel_uncore_frequency
> intel_uncore_frequency_common isst_if_common skx_edac
> x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm mgag200
> irqbypass rapl iTCO_wdt iTCO_vendor_support i2c_algo_bit mei_me
> ipmi_ssif intel_cstate drm_shmem_helper dell_smbios dcdbas
> intel_uncore dell_wmi_descriptor wmi_bmof drm_kms_helper pcspkr
> acpi_ipmi mei i2c_i801 lpc_ich intel_pch_thermal i2c_smbus ipmi_si
> ipmi_devintf ipmi_msghandler dax_pmem acpi_power_meter drm fuse xfs
> libcrc32c nd_pmem nd_btt sd_mod t10_pi sg crct10dif_pclmul
> crc32_pclmul crc32c_intel ahci libahci ghash_clmulni_intel tg3 libata
> megaraid_sas wmi nfit libnvdimm dm_mirror dm_region_hash dm_log dm_mod
> [last unloaded: loop]
> [ 5161.963439] CPU: 6 PID: 55 Comm: kworker/6:0 Tainted: G        W
>       6.6.0-rc3+ #3
> [ 5161.971480] Hardware name: Dell Inc. PowerEdge R640/06NR82, BIOS
> 2.17.1 11/15/2022
> [ 5161.979087] Workqueue: nvmet-wq nvmet_tcp_release_queue_work [nvmet_tcp]
> [ 5161.985831] RIP: 0010:__flush_work+0x165/0x180
> [ 5161.990322] Code: cc cc 48 8d 7c 24 78 88 44 24 07 e8 25 b3 3e 02
> 48 c7 c6 80 70 ec 9c 4c 89 e7 e8 b6 8e fb 00 0f b6 44 24 07 eb 93 0f
> 0b eb 8f <0f> 0b 31 c0 eb 89 e8 20 0e 88 00 e9 2c ff ff ff e8 76 99 3c
> 02 66
> [ 5162.009102] RSP: 0018:ffffc900009afa38 EFLAGS: 00010246
> [ 5162.014330] RAX: 1ffff1107469886b RBX: 1ffff92000135f48 RCX: dffffc0000000000
> [ 5162.021463] RDX: ffffc900009afa40 RSI: 0000000000000001 RDI: ffff8883a34c4358
> [ 5162.028596] RBP: ffff8883a34c4340 R08: 0000000000000000 R09: fffffbfff3d319c4
> [ 5162.035727] R10: ffffffff9e98ce27 R11: 0000000000000001 R12: ffff8883a34c4340
> [ 5162.042860] R13: 1ffff92000135f77 R14: 0000000000000001 R15: ffff88810208bec0
> [ 5162.049994] FS:  0000000000000000(0000) GS:ffff888e34a00000(0000)
> knlGS:0000000000000000
> [ 5162.058079] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 5162.063823] CR2: 00005638a5d9ffea CR3: 000000104da6e001 CR4: 00000000007706e0
> [ 5162.070956] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 5162.078088] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 5162.085222] PKRU: 55555554
> [ 5162.087934] Call Trace:
> [ 5162.090387]  <TASK>
> [ 5162.092493]  ? __warn+0xc9/0x350
> [ 5162.095727]  ? __flush_work+0x165/0x180
> [ 5162.099573]  ? report_bug+0x326/0x3c0
> [ 5162.103251]  ? handle_bug+0x3c/0x70
> [ 5162.106748]  ? exc_invalid_op+0x14/0x50
> [ 5162.110587]  ? asm_exc_invalid_op+0x16/0x20
> [ 5162.114778]  ? __flush_work+0x165/0x180
> [ 5162.118622]  ? lock_acquire+0x4db/0x5e0
> [ 5162.122469]  ? __pfx___flush_work+0x10/0x10
> [ 5162.126658]  ? __pfx_try_to_wake_up+0x10/0x10
> [ 5162.131025]  ? irqentry_enter+0x28/0x70
> [ 5162.134872]  ? rcu_is_watching+0x11/0xb0
> [ 5162.138805]  ? trace_irq_enable.constprop.0+0x13d/0x180
> [ 5162.144034]  ? asm_sysvec_apic_timer_interrupt+0x16/0x20
> [ 5162.149355]  __cancel_work_timer+0x31a/0x460
> [ 5162.153633]  ? mutex_lock_io_nested+0x1273/0x1310
> [ 5162.158343]  ? __pfx___cancel_work_timer+0x10/0x10
> [ 5162.163141]  ? do_raw_write_trylock+0xb5/0x190
> [ 5162.167596]  ? __pfx_do_raw_write_trylock+0x10/0x10
> [ 5162.172475]  ? rcu_is_watching+0x11/0xb0
> [ 5162.176411]  ? trace_irq_enable.constprop.0+0x13d/0x180
> [ 5162.181646]  ? __pfx_sk_stream_write_space+0x10/0x10
> [ 5162.186618]  nvmet_tcp_release_queue_work+0x2db/0x1350 [nvmet_tcp]
> [ 5162.192807]  ? rcu_is_watching+0x11/0xb0
> [ 5162.196741]  ? process_one_work+0x6b5/0x13f0
> [ 5162.201024]  process_one_work+0x7c1/0x13f0
> [ 5162.205132]  ? __pfx___lock_release+0x10/0x10
> [ 5162.209497]  ? __pfx_process_one_work+0x10/0x10
> [ 5162.214033]  ? assign_work+0x16c/0x240
> [ 5162.217791]  ? rcu_is_watching+0x11/0xb0
> [ 5162.221720]  worker_thread+0x721/0xfd0
> [ 5162.225482]  ? __pfx_worker_thread+0x10/0x10
> [ 5162.229761]  kthread+0x2f8/0x3e0
> [ 5162.233000]  ? _raw_spin_unlock_irq+0x24/0x50
> [ 5162.237360]  ? __pfx_kthread+0x10/0x10
> [ 5162.241122]  ret_from_fork+0x2d/0x70
> [ 5162.244709]  ? __pfx_kthread+0x10/0x10
> [ 5162.248461]  ret_from_fork_asm+0x1b/0x30
> [ 5162.252392]  </TASK>
> [ 5162.254587] irq event stamp: 40414
> [ 5162.257994] hardirqs last  enabled at (40413): [<ffffffff9caa5aa4>]
> _raw_spin_unlock_irq+0x24/0x50
> [ 5162.266955] hardirqs last disabled at (40414): [<ffffffff9ca8bc48>]
> __schedule+0xa68/0x1d80
> [ 5162.275300] softirqs last  enabled at (35660): [<ffffffff9caa8a3b>]
> __do_softirq+0x5db/0x8f6
> [ 5162.283732] softirqs last disabled at (35653): [<ffffffff9a64c4dc>]
> __irq_exit_rcu+0xbc/0x210
> [ 5162.292255] ---[ end trace 0000000000000000 ]---
> 
> -- 
> Best Regards,
>   Yi Zhang
> 
> 



[Index of Archives]     [Linux RAID]     [Linux SCSI]     [Linux ATA RAID]     [IDE]     [Linux Wireless]     [Linux Kernel]     [ATH6KL]     [Linux Bluetooth]     [Linux Netdev]     [Kernel Newbies]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Device Mapper]

  Powered by Linux