syzbot


INFO: task hung in cfg80211_event_work (2)

Status: upstream: reported C repro on 2023/07/12 12:52
Subsystems: wireless
[Documentation on labels]
Reported-by: syzbot+85f0eb24e10cec9b8a10@syzkaller.appspotmail.com
First crash: 281d, last: 35d
Cause bisection: introduced by (bisect log) :
commit d15121be7485655129101f3960ae6add40204463
Author: Paolo Abeni <pabeni@redhat.com>
Date: Mon May 8 06:17:44 2023 +0000

  Revert "softirq: Let ksoftirqd do its job"

Crash: BUG: workqueue lockup (log)
Repro: C syz .config
  
Discussions (1)
Title Replies (including bot) Last reply
[syzbot] [wireless?] INFO: task hung in cfg80211_event_work (2) 1 (3) 2023/09/16 22:46
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in cfg80211_event_work wireless C unreliable error 4 1184d 1217d 0/26 closed as invalid on 2022/02/08 10:49
linux-4.19 INFO: task hung in cfg80211_event_work 1 449d 449d 0/1 upstream: reported on 2023/01/21 03:03
Last patch testing requests (5)
Created Duration User Patch Repo Result
2023/11/01 02:04 31m retest repro linux-next OK log
2023/11/01 02:04 33m retest repro linux-next OK log
2023/09/13 03:03 17m retest repro upstream report log
2023/08/22 23:39 25m retest repro linux-next report log
2023/08/22 23:39 26m retest repro linux-next report log
Fix bisection attempts (5)
Created Duration User Patch Repo Result
2024/03/10 12:32 1h42m bisect fix upstream job log (0) log
2024/01/20 03:02 4h02m bisect fix upstream job log (0) log
2023/12/19 16:34 1h45m bisect fix upstream job log (0) log
2023/11/18 22:20 2h30m bisect fix upstream job log (0) log
2023/10/15 09:03 2h43m bisect fix upstream job log (0) log
Cause bisection attempts (3)
Created Duration User Patch Repo Result
2023/09/16 16:01 6h43m bisect upstream job log (1) log
2023/08/17 16:41 59m bisect linux-next error job log (0)
marked invalid by nogikh@google.com
2023/07/09 02:56 12h17m bisect linux-next error job log (0)
marked invalid by nogikh@google.com

Sample crash report:
INFO: task kworker/u4:6:1257 blocked for more than 143 seconds.
      Not tainted 6.5.0-syzkaller-00453-g727dbda16b83 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u4:6    state:D
 stack:20560 pid:1257  ppid:2      flags:0x00004000
Workqueue: cfg80211 cfg80211_event_work

Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5380 [inline]
 __schedule+0x1873/0x48f0 kernel/sched/core.c:6709
 schedule+0xc3/0x180 kernel/sched/core.c:6785
 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6844
 __mutex_lock_common+0xe33/0x2530 kernel/locking/mutex.c:679
 __mutex_lock kernel/locking/mutex.c:747 [inline]
 mutex_lock_nested+0x1b/0x20 kernel/locking/mutex.c:799
 wiphy_lock include/net/cfg80211.h:5776 [inline]
 cfg80211_event_work+0x27/0x40 net/wireless/core.c:332
 process_one_work+0x92c/0x12c0 kernel/workqueue.c:2600
 worker_thread+0xa63/0x1210 kernel/workqueue.c:2751
 kthread+0x2b8/0x350 kernel/kthread.c:389
 ret_from_fork+0x2e/0x60 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>

Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
 #0: 
ffffffff8d3295f0
 (
rcu_tasks.tasks_gp_mutex
){+.+.}-{3:3}
, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:522
1 lock held by rcu_tasks_trace/14:
 #0: ffffffff8d3299b0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:522
1 lock held by khungtaskd/28:
 #0: 
ffffffff8d329420
 (
rcu_read_lock
){....}-{1:2}
, at: rcu_lock_acquire+0x0/0x30
5 locks held by kworker/u4:3/47:
 #0: ffff8880b993bf98 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x2a/0x140 kernel/sched/core.c:558
 #1: ffff8880b99287c8 (&per_cpu_ptr(group->pcpu, cpu)->seq){-.-.}-{0:0}, at: psi_task_switch+0x441/0x770 kernel/sched/psi.c:999
 #2: ffff8880b99295d8 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x120/0x260 kernel/time/timer.c:999
 #3: ffffffff92230ce8 (&obj_hash[i].lock){-.-.}-{2:2}, at: debug_object_activate+0x163/0x530 lib/debugobjects.c:717
 #4: ffffffff8d1da8e8 (text_mutex){+.+.}-{3:3}, at: arch_jump_label_transform_apply+0x12/0x30 arch/x86/kernel/jump_label.c:145
3 locks held by kworker/u4:6/1257:
 #0: ffff8881412a4138 ((wq_completion)cfg80211){+.+.}-{0:0}, at: process_one_work+0x7e3/0x12c0 kernel/workqueue.c:2572
 #1: ffffc900063efd00 ((work_completion)(&rdev->event_work)){+.+.}-{0:0}, at: process_one_work+0x82b/0x12c0 kernel/workqueue.c:2574
 #2: ffff888077028768 (&rdev->wiphy.mtx){+.+.}-{3:3}, at: wiphy_lock include/net/cfg80211.h:5776 [inline]
 #2: ffff888077028768 (&rdev->wiphy.mtx){+.+.}-{3:3}, at: cfg80211_event_work+0x27/0x40 net/wireless/core.c:332
2 locks held by getty/4772:
 #0: ffff88814bee8098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x25/0x70 drivers/tty/tty_ldisc.c:243
 #1: ffffc900015902f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6b1/0x1dc0 drivers/tty/n_tty.c:2187
8 locks held by kworker/1:2/5064:

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.5.0-syzkaller-00453-g727dbda16b83 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0x1e7/0x2d0 lib/dump_stack.c:106
 nmi_cpu_backtrace+0x498/0x4d0 lib/nmi_backtrace.c:113
 nmi_trigger_cpumask_backtrace+0x187/0x300 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:160 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
 watchdog+0xec2/0xf00 kernel/hung_task.c:379
 kthread+0x2b8/0x350 kernel/kthread.c:389
 ret_from_fork+0x2e/0x60 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 5064 Comm: kworker/1:2 Not tainted 6.5.0-syzkaller-00453-g727dbda16b83 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
Workqueue: events cfg80211_wiphy_work
RIP: 0010:do_raw_spin_unlock+0x7/0x8b0 kernel/locking/spinlock_debug.c:138
Code: 07 80 c1 03 38 c1 0f 8c 2c ff ff ff e8 02 17 78 00 e9 22 ff ff ff e8 08 cb 50 09 0f 1f 84 00 00 00 00 00 66 0f 1f 00 55 41 57 <41> 56 41 55 41 54 53 48 83 ec 28 49 89 ff 48 bb 00 00 00 00 00 fc
RSP: 0018:ffffc900001e0be8 EFLAGS: 00000046
RAX: 08d41d684f2cea00 RBX: ffffffff921c98c0 RCX: ffffc900001e0b03
RDX: 0000000000000005 RSI: ffffffff8b0aaae0 RDI: ffffffff921c98c0
RBP: ffffc900001e0c90 R08: ffffffff8e987aef R09: 1ffffffff1d30f5d
R10: dffffc0000000000 R11: fffffbfff1d30f5e R12: dffffc0000000000
R13: 1ffff9200003c180 R14: ffffc900001e0c20 R15: 0000000000000046
FS:  0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000055555718dca8 CR3: 0000000020260000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <IRQ>
 __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:150 [inline]
 _raw_spin_unlock_irqrestore+0x81/0x140 kernel/locking/spinlock.c:194
 debug_timer_deactivate kernel/time/timer.c:787 [inline]
 debug_deactivate kernel/time/timer.c:831 [inline]
 detach_timer+0x24/0x2f0 kernel/time/timer.c:878
 expire_timers kernel/time/timer.c:1734 [inline]
 __run_timers+0x5d4/0x860 kernel/time/timer.c:2022
 __do_softirq+0x2ab/0x908 kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu+0xf1/0x1b0 kernel/softirq.c:632
 irq_exit_rcu+0x9/0x20 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x95/0xb0 arch/x86/kernel/apic/apic.c:1109
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:645
RIP: 0010:console_trylock_spinning+0x3b8/0x460
Code: ed 0f 84 48 ff ff ff e8 d6 f9 1c 00 fb 31 db eb 45 e8 cc f9 1c 00 e8 67 90 4e 09 4d 85 ed 74 cd e8 bd f9 1c 00 fb f3 0f 1e fa <bb> 01 00 00 00 48 c7 c7 c0 50 20 8d 31 f6 ba 01 00 00 00 31 c9 41
RSP: 0018:ffffc90003c1f1c0 EFLAGS: 00000293
RAX: ffffffff816ec1c3 RBX: 0000000000000000 RCX: ffff888027443b80
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffffc90003c1f288 R08: ffffffff816ec17c R09: 1ffffffff20f6a6d
R10: dffffc0000000000 R11: fffffbfff20f6a6e R12: 1ffff92000783e38
R13: 0000000000000200 R14: 0000000000000046 R15: dffffc0000000000
 vprintk_emit+0xbc/0x1f0 kernel/printk/printk.c:2306
 _printk+0xd5/0x120 kernel/printk/printk.c:2328
 ieee80211_parse_ch_switch_ie+0xae6/0x1040 net/mac80211/spectmgmt.c:88
 ieee80211_ibss_process_chanswitch+0x277/0xf90 net/mac80211/ibss.c:803
 ieee80211_rx_mgmt_spectrum_mgmt net/mac80211/ibss.c:931 [inline]
 ieee80211_ibss_rx_queued_mgmt+0x12ba/0x2ca0 net/mac80211/ibss.c:1666

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/08/29 09:08 upstream 727dbda16b83 7ba13a15 .config console log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce-smack-root INFO: task hung in cfg80211_event_work
2023/07/29 17:57 linux-next d7b3af5a77e8 92476829 .config console log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-linux-next-kasan-gce-root INFO: task hung in cfg80211_event_work
2023/07/08 12:43 linux-next 123212f53f3e 668cb1fa .config console log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-linux-next-kasan-gce-root INFO: task hung in cfg80211_event_work
* Struck through repros no longer work on HEAD.