usb/gadget: stalls in dummy_timer

From: Andrey Konovalov
Date: Mon Sep 11 2017 - 07:15:37 EST

Next message: Andrey Konovalov: "Re: usb/midi: use-after-free in snd_rawmidi_dev_seq_free"
Previous message: Milian Wolff: "[PATCH] perf: support running perf binaries with a dash in their name"
Next in thread: Alan Stern: "Re: usb/gadget: stalls in dummy_timer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi!

I've been getting stall reports like this one while fuzzing the USB
stack with gadgetfs. I'm wondering whether this is a bug in gadgetfs
or is this report induced by the changes I've made to the USB core
code. I didn't touch gadgetfs code though (except for adding a few
printk's).

I'm on commit 81a84ad3cb5711cec79f4dd53a4ce026b092c432

usbtouchscreen 2-1:8.0: usbtouch_irq - usb_submit_urb failed with result: -12
INFO: rcu_sched self-detected stall on CPU
INFO: rcu_sched detected stalls on CPUs/tasks:
2-...: (1 GPs behind) idle=ba2/140000000000002/0 softirq=100255/100259 fqs=2
(detected by 1, t=48363 jiffies, g=20668, c=20667, q=2875)
Sending NMI from CPU 1 to CPUs 2:
NMI backtrace for cpu 2
CPU: 2 PID: 9620 Comm: udevd Not tainted 4.13.0+ #87
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
task: ffff88003a414e00 task.stack: ffff88003aaa8000
RIP: 0010:inb arch/x86/include/asm/io.h:340 [inline]
RIP: 0010:io_serial_in+0x70/0x90 drivers/tty/serial/8250/8250_port.c:430
RSP: 0018:ffff88006dc05638 EFLAGS: 00000002
RAX: dffffc0000000060 RBX: 00000000000003fd RCX: 0000000000000000
RDX: 00000000000003fd RSI: 0000000000000005 RDI: ffffffff88791fe8
RBP: ffff88006dc05648 R08: fffffbfff0fe0100 R09: fffffbfff0fe0100
R10: 0000000000000007 R11: fffffbfff0fe00ff R12: ffffffff88791fe0
R13: 0000000000000020 R14: fffffbfff10f2438 R15: fffffbfff10f23ff
FS: 00007f88402d27a0(0000) GS:ffff88006dc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f88402d9000 CR3: 000000003d4ec000 CR4: 00000000000006e0
Call Trace:
<IRQ>
serial_in drivers/tty/serial/8250/8250.h:115 [inline]
wait_for_xmitr+0x8e/0x1d0 drivers/tty/serial/8250/8250_port.c:2015
serial8250_console_putchar+0x24/0x60 drivers/tty/serial/8250/8250_port.c:3149
uart_console_write+0x5c/0xf0 drivers/tty/serial/serial_core.c:1856
serial8250_console_write+0x319/0x670 drivers/tty/serial/8250/8250_port.c:3215
univ8250_console_write+0x6b/0x80 drivers/tty/serial/8250/8250_core.c:594
call_console_drivers kernel/printk/printk.c:1586 [inline]
console_unlock+0x8a1/0xcd0 kernel/printk/printk.c:2245
vprintk_emit+0x567/0x5d0 kernel/printk/printk.c:1769
vprintk_default+0x2d/0x40 kernel/printk/printk.c:1808
vprintk_func+0x5c/0xd0 kernel/printk/printk_safe.c:382
printk+0xcd/0xfe kernel/printk/printk.c:1841
print_cpu_stall_info_begin kernel/rcu/tree_plugin.h:1643 [inline]
print_cpu_stall+0x1a4/0x6d0 kernel/rcu/tree.c:1524
check_cpu_stall.isra.72+0x707/0xe90 kernel/rcu/tree.c:1604
__rcu_pending kernel/rcu/tree.c:3457 [inline]
rcu_pending kernel/rcu/tree.c:3519 [inline]
rcu_check_callbacks+0x241/0xa50 kernel/rcu/tree.c:2861
update_process_times+0x35/0x70 kernel/time/timer.c:1590
tick_sched_handle+0xf5/0x160 kernel/time/tick-sched.c:161
tick_sched_timer+0x47/0x120 kernel/time/tick-sched.c:1190
__run_hrtimer kernel/time/hrtimer.c:1213 [inline]
__hrtimer_run_queues+0x3f4/0x970 kernel/time/hrtimer.c:1277
hrtimer_interrupt+0x22a/0x720 kernel/time/hrtimer.c:1311
local_apic_timer_interrupt+0x74/0xe0 arch/x86/kernel/apic/apic.c:1019
smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:1043
apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:814 [inline]
RIP: 0010:__raw_spin_unlock_irqrestore
include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0xf5/0x160 kernel/locking/spinlock.c:191
RSP: 0018:ffff88006dc06c40 EFLAGS: 00000a06 ORIG_RAX: ffffffffffffff10
RAX: 1ffff1000db80d95 RBX: 1ffff1000db80d89 RCX: dffffc0000000000
RDX: dffffc0000000000 RSI: 0000000000000a06 RDI: 0000000000000a06
RBP: ffff88006dc06d48 R08: fffffbfff0fe0104 R09: fffffbfff0fe0104
R10: ffff88006dc06420 R11: fffffbfff0fe0103 R12: 1ffff1000db80d9d
R13: 1ffff1000db80d8d R14: ffff88006ac48000 R15: ffff88006c172b08
spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
dummy_timer+0x1aa8/0x38c0 drivers/usb/gadget/udc/dummy_hcd.c:1938
call_timer_fn+0xba/0x390 kernel/time/timer.c:1281
expire_timers kernel/time/timer.c:1320 [inline]
__run_timers+0x9d0/0xda0 kernel/time/timer.c:1620
run_timer_softirq+0x51/0xb0 kernel/time/timer.c:1646
__do_softirq+0x258/0x7ac kernel/softirq.c:284
invoke_softirq kernel/softirq.c:364 [inline]
irq_exit+0x14e/0x180 kernel/softirq.c:405
exiting_irq arch/x86/include/asm/apic.h:638 [inline]
smp_apic_timer_interrupt+0x7b/0xa0 arch/x86/kernel/apic/apic.c:1044
Lost 134 message(s)!
rcu_sched kthread starved for 48353 jiffies! g20668 c20667 f0x0
RCU_GP_WAIT_FQS(3) ->state=0x1
rcu_sched S18936 9 2 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2771 [inline]
__schedule+0x6fa/0x1780 kernel/sched/core.c:3332
schedule+0x106/0x450 kernel/sched/core.c:3391
schedule_timeout+0x1d8/0x440 kernel/time/timer.c:1743
rcu_gp_kthread+0x1edd/0x47e0 kernel/rcu/tree.c:2242
kthread+0x324/0x3f0 kernel/kthread.c:231
ret_from_fork+0x25/0x30 arch/x86/entry/entry_64.S:425
2-...: (1 GPs behind) idle=ba2/140000000000002/0 softirq=100255/100259 fqs=3
(t=48363 jiffies g=20668 c=20667 q=2875)
NMI backtrace for cpu 2
CPU: 2 PID: 9620 Comm: udevd Not tainted 4.13.0+ #87
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:16 [inline]
dump_stack+0x192/0x22c lib/dump_stack.c:52
nmi_cpu_backtrace+0x1f5/0x220 lib/nmi_backtrace.c:102
nmi_trigger_cpumask_backtrace+0x108/0x160 lib/nmi_backtrace.c:61
arch_trigger_cpumask_backtrace+0x19/0x20 arch/x86/kernel/apic/hw_nmi.c:37
trigger_single_cpu_backtrace include/linux/nmi.h:123 [inline]
rcu_dump_cpu_stacks+0x272/0x306 kernel/rcu/tree.c:1390
print_cpu_stall+0x3b5/0x6d0 kernel/rcu/tree.c:1536
check_cpu_stall.isra.72+0x707/0xe90 kernel/rcu/tree.c:1604
__rcu_pending kernel/rcu/tree.c:3457 [inline]
rcu_pending kernel/rcu/tree.c:3519 [inline]
rcu_check_callbacks+0x241/0xa50 kernel/rcu/tree.c:2861
update_process_times+0x35/0x70 kernel/time/timer.c:1590
tick_sched_handle+0xf5/0x160 kernel/time/tick-sched.c:161
tick_sched_timer+0x47/0x120 kernel/time/tick-sched.c:1190
__run_hrtimer kernel/time/hrtimer.c:1213 [inline]
__hrtimer_run_queues+0x3f4/0x970 kernel/time/hrtimer.c:1277
hrtimer_interrupt+0x22a/0x720 kernel/time/hrtimer.c:1311
local_apic_timer_interrupt+0x74/0xe0 arch/x86/kernel/apic/apic.c:1019
smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:1043
apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:814 [inline]
RIP: 0010:__raw_spin_unlock_irqrestore
include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0xf5/0x160 kernel/locking/spinlock.c:191
RSP: 0018:ffff88006dc06c40 EFLAGS: 00000a06 ORIG_RAX: ffffffffffffff10
RAX: 1ffff1000db80d95 RBX: 1ffff1000db80d89 RCX: dffffc0000000000
RDX: dffffc0000000000 RSI: 0000000000000a06 RDI: 0000000000000a06
RBP: ffff88006dc06d48 R08: fffffbfff0fe0104 R09: fffffbfff0fe0104
R10: ffff88006dc06420 R11: fffffbfff0fe0103 R12: 1ffff1000db80d9d
R13: 1ffff1000db80d8d R14: ffff88006ac48000 R15: ffff88006c172b08
spin_unlock_irqrestore include/linux/spinlock.h:354 [inline]
dummy_timer+0x1aa8/0x38c0 drivers/usb/gadget/udc/dummy_hcd.c:1938
call_timer_fn+0xba/0x390 kernel/time/timer.c:1281
expire_timers kernel/time/timer.c:1320 [inline]
__run_timers+0x9d0/0xda0 kernel/time/timer.c:1620
run_timer_softirq+0x51/0xb0 kernel/time/timer.c:1646
__do_softirq+0x258/0x7ac kernel/softirq.c:284
invoke_softirq kernel/softirq.c:364 [inline]
irq_exit+0x14e/0x180 kernel/softirq.c:405
exiting_irq arch/x86/include/asm/apic.h:638 [inline]
smp_apic_timer_interrupt+0x7b/0xa0 arch/x86/kernel/apic/apic.c:1044
apic_timer_interrupt+0x89/0x90 arch/x86/entry/entry_64.S:482
RIP: 0010:_copy_from_iter_full+0x399/0x1240 lib/iov_iter.c:597
RSP: 0018:ffff88003aaaf570 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffffed0007555ec1
RDX: 0000000000000000 RSI: 1ffff10007555e7f RDI: ffffed0007555ec9
RBP: ffff88003aaafa10 R08: ffffed00076640cb R09: ffffed00076640cb
R10: 0000000000000000 R11: ffffed00076640ca R12: ffffed0007555f2d
R13: dffffc0000000000 R14: 0000000000000000 R15: ffff88003aaaf9e8
</IRQ>
copy_from_iter_full include/linux/uio.h:126 [inline]
memcpy_from_msg include/linux/skbuff.h:3176 [inline]
netlink_sendmsg+0x9c7/0xe40 net/netlink/af_netlink.c:1839
sock_sendmsg_nosec net/socket.c:633 [inline]
sock_sendmsg+0xcf/0x110 net/socket.c:643
___sys_sendmsg+0x97e/0xb30 net/socket.c:2035
__sys_sendmsg+0x13d/0x320 net/socket.c:2069
SYSC_sendmsg net/socket.c:2080 [inline]
SyS_sendmsg+0x32/0x50 net/socket.c:2076
entry_SYSCALL_64_fastpath+0x1a/0xa5
RIP: 0033:0x7f883f9e7320
RSP: 002b:00007ffcad3d23a8 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 00000000024b5850 RCX: 00007f883f9e7320
RDX: 0000000000000000 RSI: 00007ffcad3d23f0 RDI: 000000000000000b
RBP: 0000000000000000 R08: 00000000ffffffff R09: 0000000000000000
R10: 73752f302e646368 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000024b4030 R14: 00007ffcad3d1f50 R15: 0000000000000001
dummy_hcd dummy_hcd.0: timer fired with no URBs pending?

Next message: Andrey Konovalov: "Re: usb/midi: use-after-free in snd_rawmidi_dev_seq_free"
Previous message: Milian Wolff: "[PATCH] perf: support running perf binaries with a dash in their name"
Next in thread: Alan Stern: "Re: usb/gadget: stalls in dummy_timer"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]