Message-ID: <0000000000007a02930611d2efbb@google.com>
Date: Tue, 20 Feb 2024 08:45:18 -0800
From: syzbot <syzbot+269f9ad9bc32451d5fb5@...kaller.appspotmail.com>
To: bp@...en8.de, dave.hansen@...ux.intel.com, hpa@...or.com, 
	linux-input@...r.kernel.org, linux-kernel@...r.kernel.org, 
	linux-usb@...r.kernel.org, mingo@...hat.com, syzkaller-bugs@...glegroups.com, 
	tglx@...utronix.de, x86@...nel.org
Subject: [syzbot] [input?] [usb?] INFO: rcu detected stall in sys_syslog (2)

Hello,

syzbot found the following issue on:

HEAD commit:    4f5e5092fdbf Merge tag 'net-6.8-rc5' of git://git.kernel.o..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=12cff3a4180000
kernel config:  https://syzkaller.appspot.com/x/.config?x=1d7c92dd8d5c7a1e
dashboard link: https://syzkaller.appspot.com/bug?extid=269f9ad9bc32451d5fb5
compiler:       Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=15f4a68a180000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/d430539932db/disk-4f5e5092.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/6369586e33b7/vmlinux-4f5e5092.xz
kernel image: https://storage.googleapis.com/syzbot-assets/9c1e38f80254/bzImage-4f5e5092.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+269f9ad9bc32451d5fb5@...kaller.appspotmail.com

rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
 0-...D
 } 2649 jiffies s: 5869 root: 0x1/.
rcu: blocking rcu_node structures (internal RCU debug):

Sending NMI from CPU 1 to CPUs 0:
 kthread+0x2ef/0x390 kernel/kthread.c:388
NMI backtrace for cpu 0
CPU: 0 PID: 5441 Comm: syz-executor.0 Not tainted 6.8.0-rc4-syzkaller-00180-g4f5e5092fdbf #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/25/2024
RIP: 0010:check_kcov_mode kernel/kcov.c:173 [inline]
RIP: 0010:__sanitizer_cov_trace_pc+0x2e/0x70 kernel/kcov.c:207
Code: 48 8b 04 24 65 48 8b 0d b0 52 70 7e 65 8b 15 b1 52 70 7e f7 c2 00 01 ff 00 74 11 f7 c2 00 01 00 00 74 35 83 b9 fc 15 00 00 00 <74> 2c 8b 91 d8 15 00 00 83 fa 02 75 21 48 8b 91 e0 15 00 00 48 8b
RSP: 0018:ffffc90000006128 EFLAGS: 00000046
RAX: ffffffff8b5fbfa4 RBX: 0000000000000131 RCX: ffff88805db05940
RDX: 0000000000000103 RSI: 0000000000000131 RDI: ffffc900000061e0
RBP: ffffc90000006270 R08: ffffffff8b60127a R09: 0000000000000000
R10: ffffc900000061e0 R11: fffff52000000c3f R12: 00000000ffff0a00
R13: dffffc0000000000 R14: ffffc900000061e0 R15: ffffc900000065c1
FS:  0000555555c97480(0000) GS:ffff8880b9400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fe746ba8008 CR3: 000000002f932000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 <NMI>
 </NMI>
 <IRQ>
 put_dec+0x14/0xe0 lib/vsprintf.c:291
 number+0x337/0xf90 lib/vsprintf.c:511
 vsnprintf+0x1542/0x1da0 lib/vsprintf.c:2890
 sprintf+0xda/0x120 lib/vsprintf.c:3028
 print_time kernel/printk/printk.c:1324 [inline]
 info_print_prefix+0x16b/0x310 kernel/printk/printk.c:1350
 record_print_text kernel/printk/printk.c:1399 [inline]
 printk_get_next_message+0x408/0xce0 kernel/printk/printk.c:2828
 console_emit_next_record kernel/printk/printk.c:2868 [inline]
 console_flush_all+0x42d/0xec0 kernel/printk/printk.c:2967
 console_unlock+0x13b/0x4d0 kernel/printk/printk.c:3036
 vprintk_emit+0x508/0x720 kernel/printk/printk.c:2303
 _printk+0xd5/0x120 kernel/printk/printk.c:2328
 printk_stack_address arch/x86/kernel/dumpstack.c:72 [inline]
 show_trace_log_lvl+0x438/0x520 arch/x86/kernel/dumpstack.c:285
 sched_show_task+0x50c/0x6d0 kernel/sched/core.c:9171
 show_state_filter+0x19e/0x270 kernel/sched/core.c:9216
 kbd_keycode drivers/tty/vt/keyboard.c:1524 [inline]
 kbd_event+0x30fa/0x4910 drivers/tty/vt/keyboard.c:1543
 input_to_handler drivers/input/input.c:132 [inline]
 input_pass_values+0x945/0x1200 drivers/input/input.c:161
 input_event_dispose+0x402/0x650 drivers/input/input.c:389
 input_handle_event+0xa71/0xbe0 drivers/input/input.c:406
 input_event+0xa4/0xd0 drivers/input/input.c:435
 hidinput_hid_event+0x138b/0x1c90 drivers/hid/hid-input.c:1731
 hid_process_event+0x439/0x590 drivers/hid/hid-core.c:1541
 hid_input_array_field+0x3fb/0x5c0 drivers/hid/hid-core.c:1653
 hid_process_report drivers/hid/hid-core.c:1695 [inline]
 hid_report_raw_event+0xf4f/0x18a0 drivers/hid/hid-core.c:2016
 hid_input_report+0x416/0x500 drivers/hid/hid-core.c:2090
 hid_irq_in+0x4a0/0x6d0 drivers/hid/usbhid/hid-core.c:284
 __usb_hcd_giveback_urb+0x373/0x530 drivers/usb/core/hcd.c:1650
 dummy_timer+0x8aa/0x3220 drivers/usb/gadget/udc/dummy_hcd.c:1987
 call_timer_fn+0x17e/0x600 kernel/time/timer.c:1700
 expire_timers kernel/time/timer.c:1751 [inline]
 __run_timers+0x621/0x830 kernel/time/timer.c:2038
 run_timer_softirq+0x67/0xf0 kernel/time/timer.c:2051
 __do_softirq+0x2bb/0x942 kernel/softirq.c:553
 invoke_softirq kernel/softirq.c:427 [inline]
 __irq_exit_rcu+0xf1/0x1c0 kernel/softirq.c:632
 irq_exit_rcu+0x9/0x30 kernel/softirq.c:644
 sysvec_apic_timer_interrupt+0x97/0xb0 arch/x86/kernel/apic/apic.c:1076
 </IRQ>
 <TASK>
 asm_sysvec_apic_timer_interrupt+0x1a/0x20 arch/x86/include/asm/idtentry.h:649
RIP: 0010:__asan_memcpy+0x3b/0x70 mm/kasan/shadow.c:106
Code: 49 89 ff 48 8b 5c 24 20 48 89 f7 48 89 d6 31 d2 48 89 d9 e8 a7 e3 ff ff 84 c0 74 2c 4c 89 ff 4c 89 e6 ba 01 00 00 00 48 89 d9 <e8> 90 e3 ff ff 84 c0 74 15 4c 89 ff 4c 89 f6 4c 89 e2 5b 41 5c 41
RSP: 0018:ffffc90004e875f8 EFLAGS: 00000202
RAX: 0000000000000001 RBX: ffffffff8b5fca58 RCX: ffffffff8b5fca58
RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffc90004e879c8
RBP: ffffc90004e87710 R08: 0000000000000004 R09: fffffbfff1756eb8
R10: dffffc0000000000 R11: fffffbfff1756eb8 R12: 0000000000000001
R13: dffffc0000000000 R14: ffffffff8bab75c4 R15: ffffc90004e879c8
 vsnprintf+0x948/0x1da0 lib/vsprintf.c:2786
 sprintf+0xda/0x120 lib/vsprintf.c:3028
 print_caller kernel/printk/printk.c:1335 [inline]
 info_print_prefix+0x204/0x310 kernel/printk/printk.c:1352
 get_record_print_text_size kernel/printk/printk.c:1487 [inline]
 find_first_fitting_seq+0x1b2/0x580 kernel/printk/printk.c:1516
 syslog_print_all+0x1ae/0x7e0 kernel/printk/printk.c:1664
 do_syslog+0x38d/0x890 kernel/printk/printk.c:1742
 __do_sys_syslog kernel/printk/printk.c:1820 [inline]
 __se_sys_syslog kernel/printk/printk.c:1818 [inline]
 __x64_sys_syslog+0x7c/0x90 kernel/printk/printk.c:1818
 do_syscall_64+0xf9/0x240
 entry_SYSCALL_64_after_hwframe+0x6f/0x77
RIP: 0033:0x7f92d367dda9
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 e1 20 00 00 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffec8726828 EFLAGS: 00000246 ORIG_RAX: 0000000000000067
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f92d367dda9
RDX: 000000000000003f RSI: 00007ffec8726900 RDI: 0000000000000003
RBP: 00007ffec8726900 R08: 00007ffec87e60b0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffec8726ee8
R13: 00007ffec8726ee8 R14: 0000000000000001 R15: 00000000fffffff1
 </TASK>
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/R-bat_e state:I stack:28848 pid:2748  tgid:2748  ppid:2      flags:0x00004000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 rescuer_thread+0xc45/0xda0 kernel/workqueue.c:2937
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/u4:10   state:I stack:25808 pid:2799  tgid:2799  ppid:2      flags:0x00004000
Workqueue:  0x0 (events_unbound)
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 worker_thread+0xc26/0x1000 kernel/workqueue.c:2802
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/u4:11   state:I stack:24248 pid:2829  tgid:2829  ppid:2      flags:0x00004000
Workqueue:  0x0 (events_unbound)
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 worker_thread+0xc26/0x1000 kernel/workqueue.c:2802
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/u4:12   state:I stack:23024 pid:2849  tgid:2849  ppid:2      flags:0x00004000
Workqueue:  0x0 (events_unbound)
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 worker_thread+0xc26/0x1000 kernel/workqueue.c:2802
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/u4:13   state:I stack:26800 pid:2888  tgid:2888  ppid:2      flags:0x00004000
Workqueue:  0x0 (events_unbound)
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 worker_thread+0xc26/0x1000 kernel/workqueue.c:2802
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/u4:14   state:I stack:29392 pid:2906  tgid:2906  ppid:2      flags:0x00004000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 worker_thread+0xc26/0x1000 kernel/workqueue.c:2802
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>
task:kworker/R-zswap state:I stack:29744 pid:4464  tgid:4464  ppid:2      flags:0x00004000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:5400 [inline]
 __schedule+0x17d1/0x49f0 kernel/sched/core.c:6727
 __schedule_loop kernel/sched/core.c:6802 [inline]
 schedule+0x149/0x260 kernel/sched/core.c:6817
 rescuer_thread+0xc45/0xda0 kernel/workqueue.c:2937
 kthread+0x2ef/0x390 kernel/kthread.c:388
 ret_from_fork+0x4b/0x80 arch/x86/kernel/process.c:147
 ret_from_fork_asm+0x1b/0x30 arch/x86/entry/entry_64.S:242
 </TASK>


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@...glegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the report is already addressed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

If you want to overwrite report's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the report is a duplicate of another one, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

Powered by blists - more mailing lists