[ 29.453913][ T290] br1: port 1(veth1) entered blocking state [ 29.455295][ T290] br1: port 1(veth1) entered disabled state [ 29.455996][ T290] veth1: entered allmulticast mode [ 29.465067][ T290] veth1: entered promiscuous mode [ 29.589986][ T216] br1: port 1(veth1) entered blocking state [ 29.590371][ T216] br1: port 1(veth1) entered forwarding state [ 29.696030][ T293] br1: port 2(veth2) entered blocking state [ 29.696360][ T293] br1: port 2(veth2) entered disabled state [ 29.696599][ T293] veth2: entered allmulticast mode [ 29.698410][ T293] veth2: entered promiscuous mode [ 29.804766][ T62] br1: port 2(veth2) entered blocking state [ 29.805147][ T62] br1: port 2(veth2) entered forwarding state [ 39.312155][ T326] GACT probability NOT on [ 44.845061][ C1] [ 44.845197][ C1] ======================================================== [ 44.845494][ C1] WARNING: possible irq lock inversion dependency detected [ 44.845782][ C1] 6.9.0-rc1-virtme #1 Not tainted [ 44.845978][ C1] -------------------------------------------------------- [ 44.846279][ C1] ksoftirqd/1/23 just changed the state of lock: [ 44.846533][ C1] ffff888007c3ac38 (&br->lock){+.-.}-{2:2}, at: br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.847064][ C1] but this lock took another, SOFTIRQ-unsafe lock in the past: [ 44.847356][ C1] (&p->alloc_lock){+.+.}-{2:2} [ 44.847363][ C1] [ 44.847363][ C1] [ 44.847363][ C1] and interrupts could create inverse lock ordering between them. [ 44.847363][ C1] [ 44.848072][ C1] [ 44.848072][ C1] other info that might help us debug this: [ 44.848363][ C1] Chain exists of: [ 44.848363][ C1] &br->lock --> lweventlist_lock --> &p->alloc_lock [ 44.848363][ C1] [ 44.848815][ C1] Possible interrupt unsafe locking scenario: [ 44.848815][ C1] [ 44.849112][ C1] CPU0 CPU1 [ 44.849325][ C1] ---- ---- [ 44.849530][ C1] lock(&p->alloc_lock); [ 44.849687][ C1] local_irq_disable(); [ 44.849940][ C1] lock(&br->lock); [ 44.850197][ C1] lock(lweventlist_lock); [ 44.850456][ C1] [ 44.850612][ C1] lock(&br->lock); [ 44.850777][ C1] [ 44.850777][ C1] *** DEADLOCK *** [ 44.850777][ C1] [ 44.851065][ C1] 1 lock held by ksoftirqd/1/23: [ 44.851265][ C1] #0: ffffc900001afc20 ((&p->forward_delay_timer)){+.-.}-{0:0}, at: call_timer_fn+0xe8/0x230 [ 44.851679][ C1] [ 44.851679][ C1] the shortest dependencies between 2nd lock and 1st lock: [ 44.852025][ C1] -> (&p->alloc_lock){+.+.}-{2:2} { [ 44.852247][ C1] HARDIRQ-ON-W at: [ 44.852407][ C1] __lock_acquire+0x797/0x1570 [ 44.852671][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.852940][ C1] _raw_spin_lock+0x30/0x40 [ 44.853190][ C1] set_mems_allowed+0x1d/0x210 [ 44.853455][ C1] kernel_init_freeable+0x72/0x310 [ 44.853705][ C1] kernel_init+0x20/0x200 [ 44.853958][ C1] ret_from_fork+0x31/0x70 [ 44.854207][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.854450][ C1] SOFTIRQ-ON-W at: [ 44.854604][ C1] __lock_acquire+0x797/0x1570 [ 44.854860][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.855104][ C1] _raw_spin_lock+0x30/0x40 [ 44.855355][ C1] set_mems_allowed+0x1d/0x210 [ 44.855604][ C1] kernel_init_freeable+0x72/0x310 [ 44.855853][ C1] kernel_init+0x20/0x200 [ 44.856097][ C1] ret_from_fork+0x31/0x70 [ 44.856345][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.856602][ C1] INITIAL USE at: [ 44.856755][ C1] __lock_acquire+0x797/0x1570 [ 44.857013][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.857257][ C1] _raw_spin_lock+0x30/0x40 [ 44.857515][ C1] set_mems_allowed+0x1d/0x210 [ 44.857767][ C1] kernel_init_freeable+0x72/0x310 [ 44.858022][ C1] kernel_init+0x20/0x200 [ 44.858268][ C1] ret_from_fork+0x31/0x70 [ 44.858516][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.858766][ C1] } [ 44.858838][ C1] ... key at: [] __key.387+0x0/0x40 [ 44.859136][ C1] ... acquired at: [ 44.859291][ C1] __lock_acquire+0xaf0/0x1570 [ 44.859461][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.859656][ C1] _raw_spin_lock+0x30/0x40 [ 44.859848][ C1] __get_task_comm+0x27/0x70 [ 44.860042][ C1] ref_tracker_alloc+0x2ee/0x490 [ 44.860241][ C1] linkwatch_fire_event+0x196/0x200 [ 44.860421][ C1] veth_newlink+0x367/0x830 [veth] [ 44.860758][ C1] rtnl_newlink_create+0x341/0x850 [ 44.861072][ C1] __rtnl_newlink+0xac9/0xd80 [ 44.861272][ C1] rtnl_newlink+0x63/0xa0 [ 44.861468][ C1] rtnetlink_rcv_msg+0x2fb/0xbf0 [ 44.861671][ C1] netlink_rcv_skb+0x130/0x360 [ 44.861998][ C1] netlink_unicast+0x449/0x710 [ 44.862201][ C1] netlink_sendmsg+0x723/0xbe0 [ 44.862408][ C1] ____sys_sendmsg+0x7b2/0xa10 [ 44.862616][ C1] ___sys_sendmsg+0xee/0x170 [ 44.862952][ C1] __sys_sendmsg+0xcd/0x170 [ 44.863281][ C1] do_syscall_64+0xc6/0x1e0 [ 44.863482][ C1] entry_SYSCALL_64_after_hwframe+0x6d/0x75 [ 44.863728][ C1] [ 44.863834][ C1] -> (lweventlist_lock){....}-{2:2} { [ 44.864042][ C1] INITIAL USE at: [ 44.864191][ C1] __lock_acquire+0x797/0x1570 [ 44.864441][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.864693][ C1] _raw_spin_lock_irqsave+0x3f/0x60 [ 44.864949][ C1] linkwatch_sync_dev+0x29/0x1f0 [ 44.865320][ C1] rtnl_getlink+0x4c9/0x970 [ 44.865704][ C1] rtnetlink_rcv_msg+0x2fb/0xbf0 [ 44.865953][ C1] netlink_rcv_skb+0x130/0x360 [ 44.866332][ C1] netlink_unicast+0x449/0x710 [ 44.866587][ C1] netlink_sendmsg+0x723/0xbe0 [ 44.866845][ C1] __sys_sendto+0x37d/0x410 [ 44.867246][ C1] __x64_sys_sendto+0xe0/0x1c0 [ 44.867491][ C1] do_syscall_64+0xc6/0x1e0 [ 44.867740][ C1] entry_SYSCALL_64_after_hwframe+0x6d/0x75 [ 44.868039][ C1] } [ 44.868138][ C1] ... key at: [] lweventlist_lock+0x18/0x60 [ 44.868440][ C1] ... acquired at: [ 44.868594][ C1] __lock_acquire+0xaf0/0x1570 [ 44.868793][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.868990][ C1] _raw_spin_lock_irqsave+0x3f/0x60 [ 44.869186][ C1] linkwatch_fire_event+0x74/0x200 [ 44.869389][ C1] br_stp_change_bridge_id+0x25f/0x360 [bridge] [ 44.869963][ C1] br_set_mac_address+0x1f3/0x260 [bridge] [ 44.870278][ C1] dev_set_mac_address+0x28a/0x410 [ 44.870604][ C1] dev_set_mac_address_user+0x31/0x50 [ 44.870800][ C1] do_setlink+0x17b4/0x21e0 [ 44.871001][ C1] rtnl_setlink+0x1f7/0x310 [ 44.871201][ C1] rtnetlink_rcv_msg+0x2fb/0xbf0 [ 44.871526][ C1] netlink_rcv_skb+0x130/0x360 [ 44.871720][ C1] netlink_unicast+0x449/0x710 [ 44.872033][ C1] netlink_sendmsg+0x723/0xbe0 [ 44.872235][ C1] __sys_sendto+0x37d/0x410 [ 44.872439][ C1] __x64_sys_sendto+0xe0/0x1c0 [ 44.872641][ C1] do_syscall_64+0xc6/0x1e0 [ 44.872974][ C1] entry_SYSCALL_64_after_hwframe+0x6d/0x75 [ 44.873210][ C1] [ 44.873308][ C1] -> (&br->lock){+.-.}-{2:2} { [ 44.873506][ C1] HARDIRQ-ON-W at: [ 44.873650][ C1] __lock_acquire+0x797/0x1570 [ 44.873897][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.874139][ C1] _raw_spin_lock_bh+0x38/0x50 [ 44.874379][ C1] recalculate_group_addr+0x55/0x130 [bridge] [ 44.874857][ C1] br_vlan_filter_toggle+0x77/0x130 [bridge] [ 44.875212][ C1] br_changelink+0x36c/0x1360 [bridge] [ 44.875541][ C1] br_dev_newlink+0xa5/0x100 [bridge] [ 44.876000][ C1] rtnl_newlink_create+0x341/0x850 [ 44.876241][ C1] __rtnl_newlink+0xac9/0xd80 [ 44.876479][ C1] rtnl_newlink+0x63/0xa0 [ 44.876719][ C1] rtnetlink_rcv_msg+0x2fb/0xbf0 [ 44.877094][ C1] netlink_rcv_skb+0x130/0x360 [ 44.877333][ C1] netlink_unicast+0x449/0x710 [ 44.877589][ C1] netlink_sendmsg+0x723/0xbe0 [ 44.877829][ C1] ____sys_sendmsg+0x7b2/0xa10 [ 44.878072][ C1] ___sys_sendmsg+0xee/0x170 [ 44.878313][ C1] __sys_sendmsg+0xcd/0x170 [ 44.878559][ C1] do_syscall_64+0xc6/0x1e0 [ 44.878924][ C1] entry_SYSCALL_64_after_hwframe+0x6d/0x75 [ 44.879357][ C1] IN-SOFTIRQ-W at: [ 44.879513][ C1] __lock_acquire+0x797/0x1570 [ 44.879776][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.880155][ C1] _raw_spin_lock+0x30/0x40 [ 44.880393][ C1] br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.880892][ C1] call_timer_fn+0x13b/0x230 [ 44.881139][ C1] __run_timers+0x545/0x810 [ 44.881504][ C1] run_timer_softirq+0xe8/0x1b0 [ 44.881753][ C1] __do_softirq+0x1f8/0x5df [ 44.882081][ C1] run_ksoftirqd+0x2e/0x60 [ 44.882322][ C1] smpboot_thread_fn+0x306/0x840 [ 44.882538][ C1] kthread+0x28a/0x350 [ 44.882875][ C1] ret_from_fork+0x31/0x70 [ 44.883131][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.883393][ C1] INITIAL USE at: [ 44.883510][ C1] __lock_acquire+0x797/0x1570 [ 44.883893][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.884085][ C1] _raw_spin_lock_bh+0x38/0x50 [ 44.884322][ C1] recalculate_group_addr+0x55/0x130 [bridge] [ 44.884839][ C1] br_vlan_filter_toggle+0x77/0x130 [bridge] [ 44.885209][ C1] br_changelink+0x36c/0x1360 [bridge] [ 44.885528][ C1] br_dev_newlink+0xa5/0x100 [bridge] [ 44.885983][ C1] rtnl_newlink_create+0x341/0x850 [ 44.886240][ C1] __rtnl_newlink+0xac9/0xd80 [ 44.886474][ C1] rtnl_newlink+0x63/0xa0 [ 44.886854][ C1] rtnetlink_rcv_msg+0x2fb/0xbf0 [ 44.887103][ C1] netlink_rcv_skb+0x130/0x360 [ 44.887353][ C1] netlink_unicast+0x449/0x710 [ 44.887603][ C1] netlink_sendmsg+0x723/0xbe0 [ 44.887986][ C1] ____sys_sendmsg+0x7b2/0xa10 [ 44.888235][ C1] ___sys_sendmsg+0xee/0x170 [ 44.888489][ C1] __sys_sendmsg+0xcd/0x170 [ 44.888746][ C1] do_syscall_64+0xc6/0x1e0 [ 44.889128][ C1] entry_SYSCALL_64_after_hwframe+0x6d/0x75 [ 44.889429][ C1] } [ 44.889531][ C1] ... key at: [] __key.6+0x0/0xfffffffffffe5ac0 [bridge] [ 44.889927][ C1] ... acquired at: [ 44.890075][ C1] mark_lock+0x28d/0x3e0 [ 44.890266][ C1] mark_usage+0xd9/0x2a0 [ 44.890464][ C1] __lock_acquire+0x797/0x1570 [ 44.890673][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.890878][ C1] _raw_spin_lock+0x30/0x40 [ 44.891071][ C1] br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.891392][ C1] call_timer_fn+0x13b/0x230 [ 44.891596][ C1] __run_timers+0x545/0x810 [ 44.891925][ C1] run_timer_softirq+0xe8/0x1b0 [ 44.892130][ C1] __do_softirq+0x1f8/0x5df [ 44.892322][ C1] run_ksoftirqd+0x2e/0x60 [ 44.892525][ C1] smpboot_thread_fn+0x306/0x840 [ 44.892853][ C1] kthread+0x28a/0x350 [ 44.893014][ C1] ret_from_fork+0x31/0x70 [ 44.893205][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.893409][ C1] [ 44.893509][ C1] [ 44.893509][ C1] stack backtrace: [ 44.893885][ C1] CPU: 1 PID: 23 Comm: ksoftirqd/1 Not tainted 6.9.0-rc1-virtme #1 [ 44.894184][ C1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014 [ 44.894752][ C1] Call Trace: [ 44.894903][ C1] [ 44.895012][ C1] dump_stack_lvl+0x82/0xd0 [ 44.895230][ C1] print_irq_inversion_bug.part.0+0x3d9/0x570 [ 44.895477][ C1] ? kernel_text_address+0x17/0xe0 [ 44.895815][ C1] ? __pfx_print_irq_inversion_bug.part.0+0x10/0x10 [ 44.896059][ C1] ? __pfx_usage_skip+0x10/0x10 [ 44.896260][ C1] ? __pfx_usage_match+0x10/0x10 [ 44.896594][ C1] ? arch_stack_walk+0x8c/0xf0 [ 44.896944][ C1] mark_lock_irq+0x4cd/0xa10 [ 44.897142][ C1] ? ret_from_fork_asm+0x1a/0x30 [ 44.897340][ C1] ? __pfx_mark_lock_irq+0x10/0x10 [ 44.897538][ C1] ? __pfx_stack_trace_save+0x10/0x10 [ 44.897867][ C1] ? __pfx_lockdep_lock+0x10/0x10 [ 44.898065][ C1] ? save_trace+0x8f/0x5b0 [ 44.898269][ C1] mark_lock+0x28d/0x3e0 [ 44.898427][ C1] mark_usage+0xd9/0x2a0 [ 44.898706][ C1] __lock_acquire+0x797/0x1570 [ 44.898904][ C1] ? __lock_acquire+0xaf0/0x1570 [ 44.899113][ C1] ? __pfx_br_forward_delay_timer_expired+0x10/0x10 [bridge] [ 44.899609][ C1] lock_acquire.part.0+0xeb/0x330 [ 44.899813][ C1] ? br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.900133][ C1] ? __pfx_lock_acquire.part.0+0x10/0x10 [ 44.900335][ C1] ? trace_lock_acquire+0x135/0x1c0 [ 44.900657][ C1] ? br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.901107][ C1] ? lock_acquire+0x32/0xc0 [ 44.901308][ C1] ? br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.901639][ C1] _raw_spin_lock+0x30/0x40 [ 44.901842][ C1] ? br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.902396][ C1] br_forward_delay_timer_expired+0x48/0x440 [bridge] [ 44.902717][ C1] ? __pfx_br_forward_delay_timer_expired+0x10/0x10 [bridge] [ 44.903220][ C1] call_timer_fn+0x13b/0x230 [ 44.903415][ C1] ? call_timer_fn+0xe8/0x230 [ 44.903610][ C1] ? call_timer_fn+0xe8/0x230 [ 44.903814][ C1] ? __pfx_call_timer_fn+0x10/0x10 [ 44.904007][ C1] ? mark_lock+0x38/0x3e0 [ 44.904162][ C1] __run_timers+0x545/0x810 [ 44.904358][ C1] ? __pfx_br_forward_delay_timer_expired+0x10/0x10 [bridge] [ 44.904720][ C1] ? __pfx___run_timers+0x10/0x10 [ 44.904916][ C1] ? do_raw_spin_lock+0x131/0x270 [ 44.905109][ C1] ? __pfx_do_raw_spin_lock+0x10/0x10 [ 44.905421][ C1] ? lock_acquire+0x32/0xc0 [ 44.905620][ C1] ? run_timer_softirq+0xe0/0x1b0 [ 44.905808][ C1] run_timer_softirq+0xe8/0x1b0 [ 44.906000][ C1] __do_softirq+0x1f8/0x5df [ 44.906324][ C1] ? __pfx_run_ksoftirqd+0x10/0x10 [ 44.906538][ C1] run_ksoftirqd+0x2e/0x60 [ 44.906741][ C1] smpboot_thread_fn+0x306/0x840 [ 44.906943][ C1] ? __pfx_smpboot_thread_fn+0x10/0x10 [ 44.907256][ C1] ? __pfx_smpboot_thread_fn+0x10/0x10 [ 44.907465][ C1] kthread+0x28a/0x350 [ 44.907615][ C1] ? __pfx_kthread+0x10/0x10 [ 44.907810][ C1] ret_from_fork+0x31/0x70 [ 44.908131][ C1] ? __pfx_kthread+0x10/0x10 [ 44.908331][ C1] ret_from_fork_asm+0x1a/0x30 [ 44.908533][ C1] [ 49.381601][ T447] br1: port 2(veth2) entered disabled state [ 49.493976][ T449] veth2: left allmulticast mode [ 49.494268][ T449] veth2: left promiscuous mode [ 49.494521][ T449] br1: port 2(veth2) entered disabled state [ 49.599433][ T450] br1: port 1(veth1) entered disabled state [ 49.699042][ T451] veth1: left allmulticast mode [ 49.699234][ T451] veth1: left promiscuous mode [ 49.699487][ T451] br1: port 1(veth1) entered disabled state