Re: netconsole deadlock with virtnet

[Leon Romanovsky <leon@kernel.org>]

On Tue, Nov 17, 2020 at 09:33:25AM -0500, Steven Rostedt wrote:
> On Tue, 17 Nov 2020 12:23:41 +0200
> Leon Romanovsky <leon@kernel.org> wrote:
>
> > Hi,
> >
> > Approximately two weeks ago, our regression team started to experience those
> > netconsole splats. The tested code is Linus's master (-rc4) + netdev net-next
> > + netdev net-rc.
> >
> > Such splats are random and we can't bisect because there is no stable reproducer.
> >
> > Any idea, what is the root cause?
> >
> > [   21.141117] netpoll: netconsole: local port 6666
> > [   21.141947] netpoll: netconsole: local IPv4 address 10.236.251.7
> > [   21.143138] netpoll: netconsole: interface 'eth1'
> > [   21.143988] netpoll: netconsole: remote port 62517
> > [   21.145127] netpoll: netconsole: remote IPv4 address 10.236.251.1
> > [   21.146206] netpoll: netconsole: remote ethernet address 68:05:ca:aa:99:49
> > [   21.149464] =====================================================
> > [   21.149466] WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
> > [   21.149467] 5.10.0-rc4_for_upstream_min_debug_2020_11_16_13_03 #1 Not tainted
> > [   21.149468] -----------------------------------------------------
> > [   21.149469] modprobe/596 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
> > [   21.149471] ffff000194b4e298 (_xmit_ETHER#2){+.-.}-{2:2}, at: virtnet_poll_tx+0x84/0x120
> > [   21.149478] and this task is already holding:
> > [   21.149478] ffff8000093d4018 (target_list_lock){....}-{2:2}, at: write_msg+0x6c/0x120 [netconsole]
> > [   21.149483] which would create a new lock dependency:
> > [   21.149484]  (target_list_lock){....}-{2:2} -> (_xmit_ETHER#2){+.-.}-{2:2}
> > [   21.149491] but this new dependency connects a HARDIRQ-irq-safe lock:
> > [   21.149492]  (console_owner){-.-.}-{0:0}
> > [   21.149496] ... which became HARDIRQ-irq-safe at:
> > [   21.149496]   __lock_acquire+0xa78/0x1a94
> > [   21.149498]   lock_acquire.part.0+0x170/0x360
> > [   21.149498]   lock_acquire+0x68/0x8c
> > [   21.149500]   console_unlock+0x1e8/0x6a4
> > [   21.149500]   vprintk_emit+0x1c4/0x3c4
> > [   21.149501]   vprintk_default+0x40/0x4c
> > [   21.149502]   vprintk_func+0x10c/0x220
> > [   21.149503]   printk+0x68/0x90
> > [   21.149504]   crng_fast_load+0x1bc/0x1c0
> > [   21.149505]   add_interrupt_randomness+0x280/0x290
> > [   21.149506]   handle_irq_event+0x80/0x120
> > [   21.149507]   handle_fasteoi_irq+0xac/0x200
> > [   21.149508]   __handle_domain_irq+0x84/0xf0
> > [   21.149509]   gic_handle_irq+0xd4/0x320
> > [   21.149510]   el1_irq+0xd0/0x180
> > [   21.149511]   arch_cpu_idle+0x24/0x44
> > [   21.149512]   default_idle_call+0x48/0xa0
> > [   21.149513]   do_idle+0x260/0x300
> > [   21.149514]   cpu_startup_entry+0x30/0x6c
> > [   21.149515]   rest_init+0x1b4/0x288
> > [   21.149515]   arch_call_rest_init+0x18/0x24
> > [   21.149516]   start_kernel+0x5cc/0x608
> > [   21.149518] to a HARDIRQ-irq-unsafe lock:
> > [   21.149519]  (_xmit_ETHER#2){+.-.}-{2:2}
> > [   21.149523] ... which became HARDIRQ-irq-unsafe at:
> > [   21.149524] ...  __lock_acquire+0x8bc/0x1a94
> > [   21.149525]   lock_acquire.part.0+0x170/0x360
> > [   21.149526]   lock_acquire+0x68/0x8c
> > [   21.149527]   _raw_spin_trylock+0x80/0xd0
> > [   21.149527]   virtnet_poll+0xac/0x360
> > [   21.149528]   net_rx_action+0x1b0/0x4e0
> > [   21.149529]   __do_softirq+0x1f4/0x638
> > [   21.149530]   do_softirq+0xb8/0xcc
> > [   21.149531]   __local_bh_enable_ip+0x18c/0x200
> > [   21.149532]   virtnet_napi_enable+0xc0/0xd4
> > [   21.149533]   virtnet_open+0x98/0x1c0
> > [   21.149534]   __dev_open+0x12c/0x200
> > [   21.149535]   __dev_change_flags+0x1a0/0x220
> > [   21.149536]   dev_change_flags+0x2c/0x70
> > [   21.149536]   do_setlink+0x214/0xe20
> > [   21.149537]   __rtnl_newlink+0x514/0x820
> > [   21.149538]   rtnl_newlink+0x58/0x84
> > [   21.149539]   rtnetlink_rcv_msg+0x184/0x4b4
> > [   21.149540]   netlink_rcv_skb+0x60/0x124
> > [   21.149541]   rtnetlink_rcv+0x20/0x30
> > [   21.149542]   netlink_unicast+0x1b4/0x270
> > [   21.149543]   netlink_sendmsg+0x1f0/0x400
> > [   21.149544]   sock_sendmsg+0x5c/0x70
> > [   21.149545]   ____sys_sendmsg+0x24c/0x280
> > [   21.149545]   ___sys_sendmsg+0x88/0xd0
> > [   21.149546]   __sys_sendmsg+0x70/0xd0
> > [   21.149547]   __arm64_sys_sendmsg+0x2c/0x40
> > [   21.149548]   el0_svc_common.constprop.0+0x84/0x200
> > [   21.149549]   do_el0_svc+0x2c/0x90
> > [   21.149550]   el0_svc+0x18/0x50
> > [   21.149551]   el0_sync_handler+0xe0/0x350
> > [   21.149552]   el0_sync+0x158/0x180
> > [   21.149553] other info that might help us debug this:
> > [   21.149555] Chain exists of:
> > [   21.149556]   console_owner --> target_list_lock --> _xmit_ETHER#2
>
> So somewhere we have target_list_lock taken while holding the console_owner
> lock (which can happen in interrupt). And what this is saying,
> target_list_lock is held somewhere where _xmit_ETHER#2 is taken (which I'm
> guessing from the back traces is the xmit_lock taken in virtnet_poll_tx().
>
> Thus, you can have a deadlock with three CPUs (I need to update the lockdep
> output to make it proper one of these days).
>
> 	CPU0			CPU1			CPU2
> 	----			----			----
>     lock(xmit_ETHER#2)
>
> 			    local_irq_disable()
> 			    lock(target_list_lock)
> 			    lock(xmit_ETHER#2)
> 			    [blocked]
>
> 						    local_irq_disable()
> 						    lock(console_owner)
> 						    lock(target_list_lock)
> 						    [blocked]
>     <interrupt>
>     lock(console_owner)
>     [blocked]
>
>  *** DEADLOCK! ***
>
>
> > [   21.149563]  Possible interrupt unsafe locking scenario:
> > [   21.149564]        CPU0                    CPU1
> > [   21.149565]        ----                    ----
> > [   21.149566]   lock(_xmit_ETHER#2);
> > [   21.149569]                                local_irq_disable();
> > [   21.149570]                                lock(console_owner);
> > [   21.149572]                                lock(target_list_lock);
> > [   21.149575]   <Interrupt>
> > [   21.149576]     lock(console_owner);
> > [   21.149579]  *** DEADLOCK ***
> > [   21.149580] 3 locks held by modprobe/596:
> > [   21.149581]  #0: ffff800011a1efe0 (console_lock){+.+.}-{0:0}, at: register_console+0x144/0x2f4
> > [   21.149586]  #1: ffff800011a1f108 (console_owner){-.-.}-{0:0}, at: console_unlock+0x17c/0x6a4
> > [   21.149590]  #2: ffff8000093d4018 (target_list_lock){....}-{2:2}, at: write_msg+0x6c/0x120 [netconsole]
> > [   21.149596] the dependencies between HARDIRQ-irq-safe lock and the holding lock:
> > [   21.149596]  -> (console_owner){-.-.}-{0:0} ops: 1191 {
> > [   21.149601]     IN-HARDIRQ-W at:
> > [   21.149602]                          __lock_acquire+0xa78/0x1a94
> > [   21.149603]                          lock_acquire.part.0+0x170/0x360
> > [   21.149604]                          lock_acquire+0x68/0x8c
> > [   21.149605]                          console_unlock+0x1e8/0x6a4
> > [   21.149606]                          vprintk_emit+0x1c4/0x3c4
> > [   21.149607]                          vprintk_default+0x40/0x4c
> > [   21.149608]                          vprintk_func+0x10c/0x220
> > [   21.149610]                          printk+0x68/0x90
> > [   21.149611]                          crng_fast_load+0x1bc/0x1c0
> > [   21.149612]                          add_interrupt_randomness+0x280/0x290
> > [   21.149613]                          handle_irq_event+0x80/0x120
> > [   21.149614]                          handle_fasteoi_irq+0xac/0x200
> > [   21.149615]                          __handle_domain_irq+0x84/0xf0
> > [   21.149616]                          gic_handle_irq+0xd4/0x320
> > [   21.149617]                          el1_irq+0xd0/0x180
> > [   21.149618]                          arch_cpu_idle+0x24/0x44
> > [   21.149619]                          default_idle_call+0x48/0xa0
> > [   21.149620]                          do_idle+0x260/0x300
> > [   21.149621]                          cpu_startup_entry+0x30/0x6c
> > [   21.149622]                          rest_init+0x1b4/0x288
> > [   21.149624]                          arch_call_rest_init+0x18/0x24
> > [   21.149625]                          start_kernel+0x5cc/0x608
> > [   21.149625]     IN-SOFTIRQ-W at:
> > [   21.149627]                          __lock_acquire+0x894/0x1a94
> > [   21.149628]                          lock_acquire.part.0+0x170/0x360
> > [   21.149629]                          lock_acquire+0x68/0x8c
> > [   21.149630]                          console_unlock+0x1e8/0x6a4
> > [   21.149631]                          vprintk_emit+0x1c4/0x3c4
> > [   21.149632]                          vprintk_default+0x40/0x4c
> > [   21.149633]                          vprintk_func+0x10c/0x220
> > [   21.149634]                          printk+0x68/0x90
> > [   21.149635]                          hrtimer_interrupt+0x290/0x294
> > [   21.149636]                          arch_timer_handler_virt+0x3c/0x50
> > [   21.149637]                          handle_percpu_devid_irq+0x94/0x164
> > [   21.149673]                          __handle_domain_irq+0x84/0xf0
> > [   21.149674]                          gic_handle_irq+0xd4/0x320
> > [   21.149675]                          el1_irq+0xd0/0x180
> > [   21.149676]                          __do_softirq+0x108/0x638
> > [   21.149677]                          __irq_exit_rcu+0x17c/0x1b0
> > [   21.149678]                          irq_exit+0x18/0x44
> > [   21.149679]                          __handle_domain_irq+0x88/0xf0
> > [   21.149680]                          gic_handle_irq+0xd4/0x320
> > [   21.149681]                          el1_irq+0xd0/0x180
> > [   21.149682]                          smp_call_function_many_cond+0x3cc/0x3f0
> > [   21.149683]                          kick_all_cpus_sync+0x4c/0x80
> > [   21.149684]                          load_module+0x1eec/0x2734
> > [   21.149685]                          __do_sys_finit_module+0xbc/0x12c
> > [   21.149686]                          __arm64_sys_finit_module+0x28/0x34
> > [   21.149687]                          el0_svc_common.constprop.0+0x84/0x200
> > [   21.149688]                          do_el0_svc+0x2c/0x90
> > [   21.149689]                          el0_svc+0x18/0x50
> > [   21.149690]                          el0_sync_handler+0xe0/0x350
> > [   21.149691]                          el0_sync+0x158/0x180
> > [   21.149692]     INITIAL USE at:
> > [   21.149694]                         __lock_acquire+0x2e0/0x1a94
> > [   21.149695]                         lock_acquire.part.0+0x170/0x360
> > [   21.149696]                         lock_acquire+0x68/0x8c
> > [   21.149697]                         console_unlock+0x1e8/0x6a4
> > [   21.149698]                         vprintk_emit+0x1c4/0x3c4
> > [   21.149699]                         vprintk_default+0x40/0x4c
> > [   21.149700]                         vprintk_func+0x10c/0x220
> > [   21.149701]                         printk+0x68/0x90
> > [   21.149702]                         start_kernel+0x8c/0x608
> > [   21.149703]   }
> > [   21.149704]   ... key      at: [<ffff800011a1f108>] console_owner_dep_map+0x0/0x28
> > [   21.149705]   ... acquired at:
> > [   21.149706]    lock_acquire.part.0+0x170/0x360
> > [   21.149707]    lock_acquire+0x68/0x8c
> > [   21.149708]    _raw_spin_lock_irqsave+0x88/0x15c
> > [   21.149709]    write_msg+0x6c/0x120 [netconsole]
> > [   21.149710]    console_unlock+0x3ec/0x6a4
> > [   21.149711]    register_console+0x17c/0x2f4
> > [   21.149712]    init_netconsole+0x20c/0x1000 [netconsole]
> > [   21.149713]    do_one_initcall+0x8c/0x480
> > [   21.149714]    do_init_module+0x60/0x270
> > [   21.149715]    load_module+0x21f8/0x2734
> > [   21.149716]    __do_sys_finit_module+0xbc/0x12c
> > [   21.149717]    __arm64_sys_finit_module+0x28/0x34
> > [   21.149718]    el0_svc_common.constprop.0+0x84/0x200
> > [   21.149719]    do_el0_svc+0x2c/0x90
> > [   21.149720]    el0_svc+0x18/0x50
> > [   21.149722]    el0_sync_handler+0xe0/0x350
> > [   21.149723]    el0_sync+0x158/0x180
> > [   21.149724] -> (target_list_lock){....}-{2:2} ops: 4 {
> > [   21.149729]    INITIAL USE at:
> > [   21.149730]                       __lock_acquire+0x2e0/0x1a94
> > [   21.149731]                       lock_acquire.part.0+0x170/0x360
> > [   21.149732]                       lock_acquire+0x68/0x8c
> > [   21.149734]                       _raw_spin_lock_irqsave+0x88/0x15c
> > [   21.149735]                       init_netconsole+0x148/0x1000 [netconsole]
> > [   21.149736]                       do_one_initcall+0x8c/0x480
> > [   21.149737]                       do_init_module+0x60/0x270
> > [   21.149738]                       load_module+0x21f8/0x2734
> > [   21.149739]                       __do_sys_finit_module+0xbc/0x12c
> > [   21.149740]                       __arm64_sys_finit_module+0x28/0x34
> > [   21.149741]                       el0_svc_common.constprop.0+0x84/0x200
> > [   21.149742]                       do_el0_svc+0x2c/0x90
> > [   21.149743]                       el0_svc+0x18/0x50
> > [   21.149744]                       el0_sync_handler+0xe0/0x350
> > [   21.149745]                       el0_sync+0x158/0x180
> > [   21.149746]  }
> > [   21.149747]  ... key      at: [<ffff8000093d4018>] target_list_lock+0x18/0xfffffffffffff000 [netconsole]
> > [   21.149748]  ..
> > [   21.149750] Lost 190 message(s)!
>
> It really sucks that we lose 190 messages that would help to decipher this
> more. :-p
>
> Because I'm not sure where the xmit_lock is taken while holding the
> target_list_lock. But the above does show that printk() calls write_msg()
> while holding the console_lock, and write_msg() takes the target_list_lock.
>
> Thus, the fix would ether require disabling interrupts every time the
> xmit_lock is taken, or to get it from being taken while holding the
> target_list_lock.

I can add any debug code to our night runs that you think may help.

Thanks

>
> -- Steve
_______________________________________________
Virtualization mailing list
Virtualization@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/virtualization