[bug report][bisected] blktests nvme/tcp failed on the latest linux-block/for-next
Yi Zhang
yi.zhang at redhat.com
Wed Oct 18 22:28:12 PDT 2023
Hi Hannes
Bisect shows it was introduced from this commit:
commit 675b453e024154dd547921c6e6d5b58747ba7e0e
Author: Hannes Reinecke <hare at suse.de>
Date: Thu Aug 24 16:39:23 2023 +0200
nvmet-tcp: enable TLS handshake upcall
On Wed, Oct 18, 2023 at 10:49 PM Keith Busch <kbusch at kernel.org> wrote:
>
> [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
> >
> >
>
--
Best Regards,
Yi Zhang
More information about the Linux-nvme
mailing list