Re: [syzbot] [block?] [trace?] INFO: task hung in blk_trace_remove (2)

[syzbot <syzbot+2373f6be3e6de4f92562@syzkaller.appspotmail.com>]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
inconsistent lock state in simple_pin_fs

================================
WARNING: inconsistent lock state
6.8.0-rc2-syzkaller-g861c0981648f-dirty #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
kworker/u4:1/12 [HC0[0]:SC1[1]:HE1:SE0] takes:
ffffffff8d38c8d8 (pin_fs_lock){+.?.}-{2:2}, at: spin_lock include/linux/spinlock.h:351 [inline]
ffffffff8d38c8d8 (pin_fs_lock){+.?.}-{2:2}, at: simple_pin_fs+0x26/0x190 fs/libfs.c:978
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire kernel/locking/lockdep.c:5754 [inline]
  lock_acquire+0x1ae/0x520 kernel/locking/lockdep.c:5719
  __raw_spin_lock include/linux/spinlock_api_smp.h:133 [inline]
  _raw_spin_lock+0x2e/0x40 kernel/locking/spinlock.c:154
  spin_lock include/linux/spinlock.h:351 [inline]
  simple_pin_fs+0x26/0x190 fs/libfs.c:978
  securityfs_create_dentry+0x74/0x4c0 security/inode.c:121
  securityfs_create_file security/inode.c:204 [inline]
  securityfs_init+0x9d/0x100 security/inode.c:345
  do_one_initcall+0x11c/0x650 init/main.c:1236
  do_initcall_level init/main.c:1298 [inline]
  do_initcalls init/main.c:1314 [inline]
  do_basic_setup init/main.c:1333 [inline]
  kernel_init_freeable+0x687/0xc10 init/main.c:1551
  kernel_init+0x1c/0x2a0 init/main.c:1441
  ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
  ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
irq event stamp: 4567394
hardirqs last  enabled at (4567394): [<ffffffff8a91ffae>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:151 [inline]
hardirqs last  enabled at (4567394): [<ffffffff8a91ffae>] _raw_spin_unlock_irqrestore+0x4e/0x70 kernel/locking/spinlock.c:194
hardirqs last disabled at (4567393): [<ffffffff8a91fd5e>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (4567393): [<ffffffff8a91fd5e>] _raw_spin_lock_irqsave+0x4e/0x50 kernel/locking/spinlock.c:162
softirqs last  enabled at (4567282): [<ffffffff89e2f8fc>] spin_unlock_bh include/linux/spinlock.h:396 [inline]
softirqs last  enabled at (4567282): [<ffffffff89e2f8fc>] cfg80211_inform_single_bss_frame_data+0x96c/0x12c0 net/wireless/scan.c:3039
softirqs last disabled at (4567283): [<ffffffff814ff74a>] do_softirq kernel/softirq.c:454 [inline]
softirqs last disabled at (4567283): [<ffffffff814ff74a>] do_softirq+0xaa/0xe0 kernel/softirq.c:441

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(pin_fs_lock);
  <Interrupt>
    lock(pin_fs_lock);

 *** DEADLOCK ***

4 locks held by kworker/u4:1/12:
 #0: ffff888013089938 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x789/0x15d0 kernel/workqueue.c:2608
 #1: ffffc90000117d80 ((work_completion)(&rdev->wiphy_work)){+.+.}-{0:0}, at: process_one_work+0x7eb/0x15d0 kernel/workqueue.c:2609
 #2: ffff88809d6f0768 (&rdev->wiphy.mtx){+.+.}-{3:3}, at: wiphy_lock include/net/cfg80211.h:5928 [inline]
 #2: ffff88809d6f0768 (&rdev->wiphy.mtx){+.+.}-{3:3}, at: cfg80211_wiphy_work+0x2b/0x330 net/wireless/core.c:424
 #3: ffffffff8d1acac0 (rcu_callback){....}-{0:0}, at: rcu_lock_acquire include/linux/rcupdate.h:298 [inline]
 #3: ffffffff8d1acac0 (rcu_callback){....}-{0:0}, at: rcu_do_batch kernel/rcu/tree.c:2184 [inline]
 #3: ffffffff8d1acac0 (rcu_callback){....}-{0:0}, at: rcu_core+0x7bd/0x1680 kernel/rcu/tree.c:2465

stack backtrace:
CPU: 0 PID: 12 Comm: kworker/u4:1 Not tainted 6.8.0-rc2-syzkaller-g861c0981648f-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
Workqueue: events_unbound cfg80211_wiphy_work
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0xd9/0x1b0 lib/dump_stack.c:106
 print_usage_bug kernel/locking/lockdep.c:3971 [inline]
 valid_state kernel/locking/lockdep.c:4013 [inline]
 mark_lock_irq kernel/locking/lockdep.c:4216 [inline]
 mark_lock+0x91a/0xc50 kernel/locking/lockdep.c:4678
 mark_usage kernel/locking/lockdep.c:4567 [inline]
 __lock_acquire+0x13f6/0x3b30 kernel/locking/lockdep.c:5091
 lock_acquire kernel/locking/lockdep.c:5754 [inline]
 lock_acquire+0x1ae/0x520 kernel/locking/lockdep.c:5719
 __raw_spin_lock include/linux/spinlock_api_smp.h:133 [inline]
 _raw_spin_lock+0x2e/0x40 kernel/locking/spinlock.c:154
 spin_lock include/linux/spinlock.h:351 [inline]
 simple_pin_fs+0x26/0x190 fs/libfs.c:978
 debugfs_remove+0x4e/0x80 fs/debugfs/inode.c:811
 blk_trace_free_rcu kernel/trace/blktrace.c:343 [inline]
 blk_trace_rcu_free+0x57/0x150 kernel/trace/blktrace.c:403
 rcu_do_batch kernel/rcu/tree.c:2190 [inline]
 rcu_core+0x819/0x1680 kernel/rcu/tree.c:2465
 __do_softirq+0x21a/0x8de kernel/softirq.c:553
 do_softirq kernel/softirq.c:454 [inline]
 do_softirq+0xaa/0xe0 kernel/softirq.c:441
 </IRQ>
 <TASK>
 __local_bh_enable_ip+0xfc/0x120 kernel/softirq.c:381
 spin_unlock_bh include/linux/spinlock.h:396 [inline]
 cfg80211_inform_single_bss_frame_data+0x96c/0x12c0 net/wireless/scan.c:3039
 cfg80211_inform_bss_frame_data+0x14c/0x350 net/wireless/scan.c:3068
 ieee80211_bss_info_update+0x311/0xab0 net/mac80211/scan.c:226
 ieee80211_rx_bss_info net/mac80211/ibss.c:1098 [inline]
 ieee80211_rx_mgmt_probe_beacon net/mac80211/ibss.c:1577 [inline]
 ieee80211_ibss_rx_queued_mgmt+0x1973/0x30e0 net/mac80211/ibss.c:1604
 ieee80211_iface_process_skb net/mac80211/iface.c:1589 [inline]
 ieee80211_iface_work+0xa67/0xda0 net/mac80211/iface.c:1643
 cfg80211_wiphy_work+0x24e/0x330 net/wireless/core.c:437
 process_one_work+0x886/0x15d0 kernel/workqueue.c:2633
 process_scheduled_works kernel/workqueue.c:2706 [inline]
 worker_thread+0x8b9/0x1290 kernel/workqueue.c:2787
 kthread+0x2c6/0x3a0 kernel/kthread.c:388
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
 </TASK>
BUG: sleeping function called from invalid context at kernel/locking/rwsem.c:1578
in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 12, name: kworker/u4:1
preempt_count: 101, expected: 0
RCU nest depth: 0, expected: 0
INFO: lockdep is turned off.
Preemption disabled at:
[<0000000000000000>] 0x0
CPU: 0 PID: 12 Comm: kworker/u4:1 Not tainted 6.8.0-rc2-syzkaller-g861c0981648f-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 11/17/2023
Workqueue: events_unbound cfg80211_wiphy_work
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x125/0x1b0 lib/dump_stack.c:106
 __might_resched+0x3c3/0x5e0 kernel/sched/core.c:10176
 down_write+0x19/0x50 kernel/locking/rwsem.c:1578
 inode_lock include/linux/fs.h:802 [inline]
 simple_recursive_removal+0x171/0x850 fs/libfs.c:528
 debugfs_remove+0x5d/0x80 fs/debugfs/inode.c:812
 blk_trace_free_rcu kernel/trace/blktrace.c:343 [inline]
 blk_trace_rcu_free+0x57/0x150 kernel/trace/blktrace.c:403
 rcu_do_batch kernel/rcu/tree.c:2190 [inline]
 rcu_core+0x819/0x1680 kernel/rcu/tree.c:2465
 __do_softirq+0x21a/0x8de kernel/softirq.c:553
 do_softirq kernel/softirq.c:454 [inline]
 do_softirq+0xaa/0xe0 kernel/softirq.c:441
 </IRQ>
 <TASK>
 __local_bh_enable_ip+0xfc/0x120 kernel/softirq.c:381
 spin_unlock_bh include/linux/spinlock.h:396 [inline]
 cfg80211_inform_single_bss_frame_data+0x96c/0x12c0 net/wireless/scan.c:3039
 cfg80211_inform_bss_frame_data+0x14c/0x350 net/wireless/scan.c:3068
 ieee80211_bss_info_update+0x311/0xab0 net/mac80211/scan.c:226
 ieee80211_rx_bss_info net/mac80211/ibss.c:1098 [inline]
 ieee80211_rx_mgmt_probe_beacon net/mac80211/ibss.c:1577 [inline]
 ieee80211_ibss_rx_queued_mgmt+0x1973/0x30e0 net/mac80211/ibss.c:1604
 ieee80211_iface_process_skb net/mac80211/iface.c:1589 [inline]
 ieee80211_iface_work+0xa67/0xda0 net/mac80211/iface.c:1643
 cfg80211_wiphy_work+0x24e/0x330 net/wireless/core.c:437
 process_one_work+0x886/0x15d0 kernel/workqueue.c:2633
 process_scheduled_works kernel/workqueue.c:2706 [inline]
 worker_thread+0x8b9/0x1290 kernel/workqueue.c:2787
 kthread+0x2c6/0x3a0 kernel/kthread.c:388
 ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
 </TASK>
BUG: scheduling while atomic: kworker/u4:1/12/0x00000102
INFO: lockdep is turned off.
Modules linked in:
Preemption disabled at:
[<0000000000000000>] 0x0


Tested on:

commit:         861c0981 Merge tag 'jfs-6.8-rc3' of github.com:kleikam..
git tree:       https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=13751c2fe80000
kernel config:  https://syzkaller.appspot.com/x/.config?x=b168fa511db3ca08
dashboard link: https://syzkaller.appspot.com/bug?extid=2373f6be3e6de4f92562
compiler:       gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch:          https://syzkaller.appspot.com/x/patch.diff?x=15288adfe80000