On Mon, 20 Nov 2023 at 16:24, kernel test robot [off-list ref] wrote:

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@redhat.com/ (local)
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 [off-list ref]
| Closes: https://lore.kernel.org/oe-lkp/202311202323.8c66ae1c-oliver.sang@intel.com (local)



[   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.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)

So this looks like we do rely on disabling BH in the hashdance, not
only for the timer but also for the
  spin_lock(&bhead2->lock);
which needs to be softirq-safe.