Re: [PATCH v2 2/2] tcp/dcpp: Don't disable bh around timewait_sock initialization
From: kernel test robot
Date: Mon Nov 20 2023 - 10:24:01 EST
Hello,
kernel test robot noticed "WARNING:inconsistent_lock_state" on:
commit: 0258784e371906dfa1419556dcb7905333039f34 ("[PATCH v2 2/2] tcp/dcpp: Don't disable bh around timewait_sock initialization")
url: https://github.com/intel-lab-lkp/linux/commits/Valentin-Schneider/tcp-dcpp-Un-pin-tw_timer/20231116-053100
base: https://git.kernel.org/cgit/linux/kernel/git/davem/net.git 674e318089468ece99aef4796eaef7add57f36b2
patch link: https://lore.kernel.org/all/20231115210509.481514-3-vschneid@xxxxxxxxxx/
patch subject: [PATCH v2 2/2] tcp/dcpp: Don't disable bh around timewait_sock initialization
in testcase: boot
compiler: gcc-12
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202311202323.8c66ae1c-oliver.sang@xxxxxxxxx
[ 53.969777][ C0]
[ 53.970087][ C0] ================================
[ 53.970532][ C0] WARNING: inconsistent lock state
[ 53.970976][ C0] 6.6.0-15915-g0258784e3719 #1 Tainted: G W N
[ 53.971566][ C0] --------------------------------
[ 53.972004][ C0] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[ 53.972562][ C0] kallsyms_test/97 [HC0[0]:SC1[1]:HE1:SE0] takes:
[ 53.973095][ C0] ffffc90000281348 (&tcp_hashinfo.bhash[i].lock){+.?.}-{2:2}, at: inet_twsk_hashdance (include/linux/spinlock.h:351 net/ipv4/inet_timewait_sock.c:132)
[ 53.973952][ C0] {SOFTIRQ-ON-W} state was registered at:
[ 53.974434][ C0] __lock_acquire (kernel/locking/lockdep.c:5090)
[ 53.974857][ C0] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755 kernel/locking/lockdep.c:5718)
[ 53.975264][ C0] _raw_spin_lock (include/linux/spinlock_api_smp.h:134 kernel/locking/spinlock.c:154)
[ 53.975673][ C0] inet_twsk_hashdance (include/linux/spinlock.h:351 net/ipv4/inet_timewait_sock.c:132)
[ 53.976122][ C0] tcp_time_wait (include/net/inet_timewait_sock.h:108 net/ipv4/tcp_minisocks.c:343)
[ 53.976533][ C0] tcp_fin (net/ipv4/tcp_input.c:4508)
[ 53.976911][ C0] tcp_data_queue (net/ipv4/tcp_input.c:5188)
[ 53.977336][ C0] tcp_rcv_state_process (net/ipv4/tcp_input.c:6850)
[ 53.977802][ C0] tcp_v4_do_rcv (net/ipv4/tcp_ipv4.c:1929)
[ 53.978216][ C0] __release_sock (net/core/sock.c:2970)
[ 53.978634][ C0] __tcp_close (net/ipv4/tcp.c:2847)
[ 53.979035][ C0] tcp_close (net/ipv4/tcp.c:2922)
[ 53.979413][ C0] inet_release (net/ipv4/af_inet.c:434)
[ 53.979817][ C0] __sock_release (net/socket.c:660)
[ 53.980229][ C0] sock_close (net/socket.c:1421)
[ 53.980610][ C0] __fput (fs/file_table.c:394)
[ 53.980986][ C0] task_work_run (kernel/task_work.c:182 (discriminator 1))
[ 53.981401][ C0] do_exit (kernel/exit.c:872)
[ 53.981777][ C0] do_group_exit (kernel/exit.c:1002)
[ 53.982183][ C0] __ia32_sys_exit_group (kernel/exit.c:1030)
[ 53.982632][ C0] __do_fast_syscall_32 (arch/x86/entry/common.c:164 arch/x86/entry/common.c:230)
[ 53.983076][ C0] do_fast_syscall_32 (arch/x86/entry/common.c:255)
[ 53.983505][ C0] entry_SYSENTER_compat_after_hwframe (arch/x86/entry/entry_64_compat.S:121)
[ 53.984034][ C0] irq event stamp: 95812558
[ 53.984434][ C0] hardirqs last enabled at (95812558): _raw_spin_unlock_irqrestore (arch/x86/include/asm/irqflags.h:26 arch/x86/include/asm/irqflags.h:67 arch/x86/include/asm/irqflags.h:127 include/linux/spinlock_api_smp.h:151 kernel/locking/spinlock.c:194)
[ 53.985302][ C0] hardirqs last disabled at (95812557): _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:108 kernel/locking/spinlock.c:162)
[ 53.986123][ C0] softirqs last enabled at (95812510): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:400 kernel/softirq.c:582)
[ 53.986900][ C0] softirqs last disabled at (95812513): irq_exit_rcu (kernel/softirq.c:427 kernel/softirq.c:632 kernel/softirq.c:622 kernel/softirq.c:644)
[ 53.987664][ C0]
[ 53.987664][ C0] other info that might help us debug this:
[ 53.988335][ C0] Possible unsafe locking scenario:
[ 53.988335][ C0]
[ 53.988971][ C0] CPU0
[ 53.989291][ C0] ----
[ 53.989611][ C0] lock(&tcp_hashinfo.bhash[i].lock);
[ 53.990076][ C0] <Interrupt>
[ 53.990404][ C0] lock(&tcp_hashinfo.bhash[i].lock);
[ 53.990883][ C0]
[ 53.990883][ C0] *** DEADLOCK ***
[ 53.990883][ C0]
[ 53.991593][ C0] 3 locks held by kallsyms_test/97:
[ 53.992048][ C0] #0: ffffffff87560480 (rcu_read_lock){....}-{1:2}, at: netif_receive_skb_list_internal (include/linux/rcupdate.h:301 include/linux/rcupdate.h:747 net/core/dev.c:5748)
[ 53.992919][ C0] #1: ffffffff87560480 (rcu_read_lock){....}-{1:2}, at: ip_local_deliver_finish+0x1d3/0x410
[ 53.993815][ C0] #2: ffff88816d626cb0 (slock-AF_INET/1){+.-.}-{2:2}, at: tcp_v4_rcv (include/linux/skbuff.h:1609 include/net/tcp.h:2458 net/ipv4/tcp_ipv4.c:2326)
[ 53.994590][ C0]
[ 53.994590][ C0] stack backtrace:
[ 53.995117][ C0] CPU: 0 PID: 97 Comm: kallsyms_test Tainted: G W N 6.6.0-15915-g0258784e3719 #1 f6bfa75c5f93478329dec95cb0ab5dfc3e35c498
[ 53.996184][ C0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 53.997020][ C0] Call Trace:
[ 53.997341][ C0] <IRQ>
[ 53.997631][ C0] dump_stack_lvl (lib/dump_stack.c:107)
[ 53.998033][ C0] mark_lock_irq (kernel/locking/lockdep.c:4216)
[ 53.998447][ C0] ? print_usage_bug+0x680/0x680
[ 53.999002][ C0] ? filter_irq_stacks (kernel/stacktrace.c:114)
[ 53.999514][ C0] ? save_trace (kernel/locking/lockdep.c:586)
[ 53.999909][ C0] ? __lock_release+0xf6/0x400
[ 54.000367][ C0] ? __stack_depot_save (lib/stackdepot.c:441)
[ 54.000823][ C0] ? reacquire_held_locks (kernel/locking/lockdep.c:5404)
[ 54.001285][ C0] mark_lock (kernel/locking/lockdep.c:4677)
[ 54.001675][ C0] ? mark_lock_irq (kernel/locking/lockdep.c:4638)
[ 54.002104][ C0] ? do_raw_spin_unlock (arch/x86/include/asm/atomic.h:23 include/linux/atomic/atomic-arch-fallback.h:457 include/linux/atomic/atomic-instrumented.h:33 include/asm-generic/qspinlock.h:57 kernel/locking/spinlock_debug.c:100 kernel/locking/spinlock_debug.c:140)
[ 54.002546][ C0] mark_usage (kernel/locking/lockdep.c:4566)
[ 54.002930][ C0] __lock_acquire (kernel/locking/lockdep.c:5090)
[ 54.003352][ C0] ? mark_lock (arch/x86/include/asm/bitops.h:227 (discriminator 3) arch/x86/include/asm/bitops.h:239 (discriminator 3) include/asm-generic/bitops/instrumented-non-atomic.h:142 (discriminator 3) kernel/locking/lockdep.c:228 (discriminator 3) kernel/locking/lockdep.c:4655 (discriminator 3))
[ 54.003748][ C0] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755 kernel/locking/lockdep.c:5718)
[ 54.004148][ C0] ? inet_twsk_hashdance (include/linux/spinlock.h:351 net/ipv4/inet_timewait_sock.c:132)
[ 54.004608][ C0] ? lock_sync (kernel/locking/lockdep.c:5721)
[ 54.005007][ C0] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4566)
[ 54.005548][ C0] ? lockdep_init_map_type (kernel/locking/lockdep.c:4891)
[ 54.006012][ C0] _raw_spin_lock (include/linux/spinlock_api_smp.h:134 kernel/locking/spinlock.c:154)
[ 54.006413][ C0] ? inet_twsk_hashdance (include/linux/spinlock.h:351 net/ipv4/inet_timewait_sock.c:132)
[ 54.006868][ C0] inet_twsk_hashdance (include/linux/spinlock.h:351 net/ipv4/inet_timewait_sock.c:132)
[ 54.007313][ C0] ? inet_twsk_alloc (net/ipv4/inet_timewait_sock.c:222)
[ 54.007742][ C0] tcp_time_wait (include/net/inet_timewait_sock.h:108 net/ipv4/tcp_minisocks.c:343)
[ 54.008149][ C0] tcp_rcv_state_process (net/ipv4/tcp_input.c:6790)
[ 54.008621][ C0] ? lock_sync (kernel/locking/lockdep.c:5721)
[ 54.009020][ C0] ? tcp_rcv_synsent_state_process (net/ipv4/tcp_input.c:6605)
[ 54.009547][ C0] ? do_raw_spin_lock (arch/x86/include/asm/atomic.h:115 include/linux/atomic/atomic-arch-fallback.h:2164 include/linux/atomic/atomic-instrumented.h:1296 include/asm-generic/qspinlock.h:111 kernel/locking/spinlock_debug.c:115)
[ 54.009982][ C0] tcp_v4_do_rcv (net/ipv4/tcp_ipv4.c:1929)
[ 54.010389][ C0] tcp_v4_rcv (net/ipv4/tcp_ipv4.c:2329)
[ 54.010795][ C0] ? tcp_v4_early_demux (net/ipv4/tcp_ipv4.c:2162)
[ 54.011246][ C0] ? lock_sync (kernel/locking/lockdep.c:5721)
[ 54.011641][ C0] ? raw_rcv (net/ipv4/raw.c:165)
[ 54.012021][ C0] ? __kmem_cache_free (mm/slub.c:3809 mm/slub.c:3822)
[ 54.012461][ C0] ip_protocol_deliver_rcu (net/ipv4/ip_input.c:205)
[ 54.012927][ C0] ip_local_deliver_finish+0x28b/0x410
[ 54.013467][ C0] ip_sublist_rcv_finish (net/ipv4/ip_input.c:578)
[ 54.013914][ C0] ip_list_rcv_finish+0x316/0x4b0
[ 54.014422][ C0] ? ip_rcv_finish_core+0x13d0/0x13d0
[ 54.014952][ C0] ip_list_rcv (net/ipv4/ip_input.c:645)
[ 54.015351][ C0] ? ip_rcv (net/ipv4/ip_input.c:645)
[ 54.015729][ C0] __netif_receive_skb_list_core (net/core/dev.c:5582)
[ 54.016231][ C0] ? __netif_receive_skb_core+0x2050/0x2050
[ 54.016798][ C0] ? reacquire_held_locks (kernel/locking/lockdep.c:5404)
[ 54.017257][ C0] netif_receive_skb_list_internal (net/core/dev.c:5674 net/core/dev.c:5763)
[ 54.017769][ C0] ? dev_gro_receive (arch/x86/include/asm/bitops.h:227 (discriminator 8) arch/x86/include/asm/bitops.h:239 (discriminator 8) include/asm-generic/bitops/instrumented-non-atomic.h:142 (discriminator 8) net/core/gro.c:533 (discriminator 8))
[ 54.018208][ C0] ? process_backlog (net/core/dev.c:5735)
[ 54.018641][ C0] ? napi_gro_receive (include/trace/events/net.h:288 net/core/gro.c:610)
[ 54.019075][ C0] ? e1000_clean_rx_irq (drivers/net/ethernet/intel/e1000/e1000_main.c:4480)
[ 54.019528][ C0] napi_complete_done (include/linux/list.h:37 include/net/gro.h:440 include/net/gro.h:435 net/core/dev.c:6103)
[ 54.019963][ C0] ? napi_busy_loop (net/core/dev.c:6070)
[ 54.020389][ C0] ? e1000_clean_rx_ring (drivers/net/ethernet/intel/e1000/e1000_main.c:4350)
[ 54.020848][ C0] e1000_clean (drivers/net/ethernet/intel/e1000/e1000_main.c:3811)
[ 54.021235][ C0] ? e1000_clean_tx_irq (drivers/net/ethernet/intel/e1000/e1000_main.c:3796)
[ 54.021693][ C0] __napi_poll+0x99/0x430
[ 54.022154][ C0] net_rx_action (net/core/dev.c:6604 net/core/dev.c:6735)
[ 54.022565][ C0] ? __napi_poll+0x430/0x430
[ 54.023043][ C0] ? asym_cpu_capacity_scan (kernel/sched/clock.c:389)
[ 54.023516][ C0] ? lock_sync (kernel/locking/lockdep.c:5721)
[ 54.023911][ C0] __do_softirq (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 include/trace/events/irq.h:142 kernel/softirq.c:554)
[ 54.024316][ C0] ? __lock_text_end (kernel/softirq.c:511)
[ 54.024729][ C0] irq_exit_rcu (kernel/softirq.c:427 kernel/softirq.c:632 kernel/softirq.c:622 kernel/softirq.c:644)
[ 54.025116][ C0] common_interrupt (arch/x86/kernel/irq.c:247 (discriminator 14))
[ 54.025529][ C0] </IRQ>
[ 54.025823][ C0] <TASK>
[ 54.026117][ C0] asm_common_interrupt (arch/x86/include/asm/idtentry.h:636)
[ 54.026551][ C0] RIP: kallsyms_expand_symbol+0xff/0x2e0
[ 54.027129][ C0] Code: 48 81 c3 e0 0e a3 86 48 89 d8 49 89 d8 48 89 df 48 c1 e8 03 41 83 e0 07 42 0f b6 04 28 44 38 c0 7f 08 84 c0 0f 85 39 01 00 00 <0f> b6 ad e0 0e a3 86 40 84 ed 74 65 85 d2 75 2a 48 83 c3 01 48 89
All code
========
0: 48 81 c3 e0 0e a3 86 add $0xffffffff86a30ee0,%rbx
7: 48 89 d8 mov %rbx,%rax
a: 49 89 d8 mov %rbx,%r8
d: 48 89 df mov %rbx,%rdi
10: 48 c1 e8 03 shr $0x3,%rax
14: 41 83 e0 07 and $0x7,%r8d
18: 42 0f b6 04 28 movzbl (%rax,%r13,1),%eax
1d: 44 38 c0 cmp %r8b,%al
20: 7f 08 jg 0x2a
22: 84 c0 test %al,%al
24: 0f 85 39 01 00 00 jne 0x163
2a:* 0f b6 ad e0 0e a3 86 movzbl -0x795cf120(%rbp),%ebp <-- trapping instruction
31: 40 84 ed test %bpl,%bpl
34: 74 65 je 0x9b
36: 85 d2 test %edx,%edx
38: 75 2a jne 0x64
3a: 48 83 c3 01 add $0x1,%rbx
3e: 48 rex.W
3f: 89 .byte 0x89
Code starting with the faulting instruction
===========================================
0: 0f b6 ad e0 0e a3 86 movzbl -0x795cf120(%rbp),%ebp
7: 40 84 ed test %bpl,%bpl
a: 74 65 je 0x71
c: 85 d2 test %edx,%edx
e: 75 2a jne 0x3a
10: 48 83 c3 01 add $0x1,%rbx
14: 48 rex.W
15: 89 .byte 0x89
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231120/202311202323.8c66ae1c-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki