On Mon, 20 Nov 2023 at 16:24, kernel test robot <oliver.sang@xxxxxxxxx> 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@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.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.
