syzbot


INFO: rcu detected stall in request_firmware_work_func (2)

Status: upstream: reported C repro on 2023/08/30 10:13
Subsystems: wireless
[Documentation on labels]
Reported-by: syzbot+1425ba65f01a5682a1a2@syzkaller.appspotmail.com
First crash: 232d, last: 58d
Fix bisection: failed (error log, bisect log)
  
Discussions (1)
Title Replies (including bot) Last reply
[syzbot] [net?] [wireless?] INFO: rcu detected stall in request_firmware_work_func (2) 0 (1) 2023/08/30 10:13
Similar bugs (1)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: rcu detected stall in request_firmware_work_func kernel 1 546d 546d 0/26 auto-obsoleted due to no activity on 2023/01/16 13:12
Last patch testing requests (2)
Created Duration User Patch Repo Result
2023/09/09 17:07 26m retest repro upstream OK log
2023/08/31 11:13 21m hdanton@sina.com patch https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master OK log
Cause bisection attempts (1)
Created Duration User Patch Repo Result
2023/08/26 19:07 11h38m bisect upstream job log (1) log
marked invalid by nogikh@google.com

Sample crash report:
rcu: INFO: rcu_preempt self-detected stall on CPU
rcu: 	1-...!: (1 GPs behind) idle=6dac/0/0x3 softirq=8535/8539 fqs=0
rcu: 	(t=10500 jiffies g=5401 q=100 ncpus=2)
rcu: rcu_preempt kthread starved for 10500 jiffies! g5401 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x0 ->cpu=0
rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
rcu: RCU grace-period kthread stack dump:
task:rcu_preempt     state:R  running task     stack:29008 pid:16    ppid:2      flags:0x00004000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5381 [inline]
 __schedule+0xee1/0x59f0 kernel/sched/core.c:6710
 schedule+0xe7/0x1b0 kernel/sched/core.c:6786
 schedule_timeout+0x157/0x2c0 kernel/time/timer.c:2167
 rcu_gp_fqs_loop+0x1ec/0xa50 kernel/rcu/tree.c:1609
 rcu_gp_kthread+0x249/0x380 kernel/rcu/tree.c:1808
 kthread+0x33a/0x430 kernel/kthread.c:389
 ret_from_fork+0x2c/0x70 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>
rcu: Stack dump where RCU GP kthread last ran:
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 7 Comm: kworker/0:0 Not tainted 6.5.0-rc7-syzkaller-00164-g382d4cd18475 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
Workqueue: events request_firmware_work_func
RIP: 0010:write_comp_data+0x7/0x90 kernel/kcov.c:230
Code: 81 e2 00 01 ff 00 75 10 65 48 8b 04 25 80 b9 03 00 48 8b 80 f8 15 00 00 c3 66 2e 0f 1f 84 00 00 00 00 00 65 8b 05 c1 b6 7d 7e <49> 89 f1 89 c6 49 89 d2 81 e6 00 01 00 00 49 89 f8 65 48 8b 14 25
RSP: 0018:ffffc90000007bb8 EFLAGS: 00000246
RAX: 0000000000000102 RBX: ffffc9000e151ea0 RCX: ffffffff88587d2c
RDX: 0000000000000000 RSI: 0019999999999998 RDI: 0000000000000007
RBP: ffff88807d071b00 R08: 0000000000000005 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 00000015798ee228
R13: 0000000000000000 R14: 0000000225c17d04 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8880b9800000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000055555640eca8 CR3: 0000000027cca000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <IRQ>
 pie_calculate_probability+0x1fc/0x850 net/sched/sch_pie.c:340
 fq_pie_timer+0x1da/0x4f0 net/sched/sch_fq_pie.c:387
 call_timer_fn+0x1a0/0x580 kernel/time/timer.c:1700
 expire_timers kernel/time/timer.c:1751 [inline]
 __run_timers+0x764/0xb10 kernel/time/timer.c:2022
 run_timer_softirq+0x58/0xd0 kernel/time/timer.c:2035
 __do_softirq+0x218/0x965 kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu kernel/softirq.c:632 [inline]
 irq_exit_rcu+0xb7/0x120 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x93/0xc0 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_flush_all+0x9b6/0xf50 kernel/printk/printk.c:2939
Code: 90 1b 23 00 9c 5b 81 e3 00 02 00 00 31 ff 48 89 de e8 8e 66 1c 00 48 85 db 0f 85 94 03 00 00 e8 f0 6a 1c 00 fb 48 8b 44 24 08 <48> 8b 14 24 0f b6 00 83 e2 07 38 d0 7f 08 84 c0 0f 85 9d 04 00 00
RSP: 0018:ffffc900000c7920 EFLAGS: 00000293
RAX: fffff52000018f4f RBX: 0000000000000000 RCX: 0000000000000000
RDX: ffff88801664bb80 RSI: ffffffff81699db0 RDI: 0000000000000007
RBP: ffffffff8d4cb1a0 R08: 0000000000000007 R09: 0000000000000000
R10: 0000000000000000 R11: 205d375420202020 R12: 0000000000000001
R13: ffffffff8d4cb1f8 R14: dffffc0000000000 R15: 0000000000000001
 console_unlock+0xc6/0x1f0 kernel/printk/printk.c:3007
 vprintk_emit+0x1c5/0x640 kernel/printk/printk.c:2307
 vprintk+0x89/0xa0 kernel/printk/printk_safe.c:50
 _printk+0xc8/0x100 kernel/printk/printk.c:2328
 regdb_fw_cb+0x155/0x270 net/wireless/reg.c:1008
 request_firmware_work_func+0x13a/0x240 drivers/base/firmware_loader/main.c:1162
 process_one_work+0xaa2/0x16f0 kernel/workqueue.c:2600
 worker_thread+0x687/0x1110 kernel/workqueue.c:2751
 kthread+0x33a/0x430 kernel/kthread.c:389
 ret_from_fork+0x2c/0x70 arch/x86/kernel/process.c:145
 ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:304
 </TASK>
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 2.097 msecs
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 6.5.0-rc7-syzkaller-00164-g382d4cd18475 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/26/2023
RIP: 0010:check_kcov_mode kernel/kcov.c:173 [inline]
RIP: 0010:write_comp_data+0x32/0x90 kernel/kcov.c:236
Code: 89 f1 89 c6 49 89 d2 81 e6 00 01 00 00 49 89 f8 65 48 8b 14 25 80 b9 03 00 a9 00 01 ff 00 74 0e 85 f6 74 59 8b 82 04 16 00 00 <85> c0 74 4f 8b 82 e0 15 00 00 83 f8 03 75 44 48 8b 82 e8 15 00 00
RSP: 0018:ffffc900001e0bb8 EFLAGS: 00000206
RAX: 0000000000000000 RBX: 0000000000abcc77 RCX: ffffffff88587ddd
RDX: ffff888017261dc0 RSI: 0000000000000100 RDI: 0000000000000005
RBP: 00000010c6f7a0b5 R08: 0000000000000005 R09: 00000000000f4240
R10: 00000000000f4240 R11: 0000000000000000 R12: 00000000000f4240
R13: 0000000000000002 R14: 0000000000112e0b R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020000080 CR3: 0000000020b50000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <IRQ>
 pie_calculate_probability+0x2ad/0x850 net/sched/sch_pie.c:345
 fq_pie_timer+0x1da/0x4f0 net/sched/sch_fq_pie.c:387
 call_timer_fn+0x1a0/0x580 kernel/time/timer.c:1700
 expire_timers kernel/time/timer.c:1751 [inline]
 __run_timers+0x764/0xb10 kernel/time/timer.c:2022
 run_timer_softirq+0x58/0xd0 kernel/time/timer.c:2035
 __do_softirq+0x218/0x965 kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu kernel/softirq.c:632 [inline]
 irq_exit_rcu+0xb7/0x120 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x93/0xc0 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:native_irq_disable arch/x86/include/asm/irqflags.h:37 [inline]
RIP: 0010:arch_local_irq_disable arch/x86/include/asm/irqflags.h:72 [inline]
RIP: 0010:acpi_safe_halt+0x1b/0x20 drivers/acpi/processor_idle.c:113
Code: ed c3 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 65 48 8b 04 25 80 b9 03 00 48 8b 00 a8 08 75 0c 66 90 0f 00 2d 97 a6 a0 00 fb f4 <fa> c3 0f 1f 00 0f b6 47 08 3c 01 74 0b 3c 02 74 05 8b 7f 04 eb 9f
RSP: 0018:ffffc90000177d60 EFLAGS: 00000246
RAX: 0000000000004000 RBX: 0000000000000001 RCX: ffffffff8a328aae
RDX: 0000000000000001 RSI: ffff888145e5c000 RDI: ffff888145e5c064
RBP: ffff888145e5c064 R08: 0000000000000001 R09: ffffed1017326d9d
R10: ffff8880b9936ceb R11: 0000000000000000 R12: ffff888013727000
R13: ffffffff8d4509c0 R14: 0000000000000001 R15: 0000000000000000
 acpi_idle_enter+0xc5/0x160 drivers/acpi/processor_idle.c:707
 cpuidle_enter_state+0x82/0x500 drivers/cpuidle/cpuidle.c:267
 cpuidle_enter+0x4e/0xa0 drivers/cpuidle/cpuidle.c:388
 cpuidle_idle_call kernel/sched/idle.c:215 [inline]
 do_idle+0x315/0x3f0 kernel/sched/idle.c:282
 cpu_startup_entry+0x18/0x20 kernel/sched/idle.c:379
 start_secondary+0x200/0x290 arch/x86/kernel/smpboot.c:326
 secondary_startup_64_no_verify+0x167/0x16b
 </TASK>

Crashes (5):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2023/08/26 10:08 upstream 382d4cd18475 03d9c195 .config console log report syz C [disk image] [vmlinux] [kernel image] ci-upstream-kasan-gce INFO: rcu detected stall in request_firmware_work_func
2024/02/16 00:13 https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git usb-testing 88bae831f381 fd39cf6f .config console log report info [disk image] [vmlinux] [kernel image] ci2-upstream-usb INFO: rcu detected stall in request_firmware_work_func
2023/11/20 19:11 https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git usb-testing 98b1cc82c4af cb976f63 .config console log report info [disk image] [vmlinux] [kernel image] ci2-upstream-usb INFO: rcu detected stall in request_firmware_work_func
2023/11/08 08:01 https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git usb-testing d2f51b3516da 83211397 .config console log report info [disk image] [vmlinux] [kernel image] ci2-upstream-usb INFO: rcu detected stall in request_firmware_work_func
2023/10/09 03:04 https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git usb-testing 1053c4a4b8fc 5e837c76 .config console log report info [disk image] [vmlinux] [kernel image] ci2-upstream-usb INFO: rcu detected stall in request_firmware_work_func
* Struck through repros no longer work on HEAD.