* BUG: soft lockup in snd_virmidi_output_trigger
@ 2018-04-09 5:58 syzbot
2018-04-09 13:03 ` Takashi Iwai
0 siblings, 1 reply; 11+ messages in thread
From: syzbot @ 2018-04-09 5:58 UTC (permalink / raw)
To: alsa-devel, linux-kernel, perex, syzkaller-bugs, tiwai
Hello,
syzbot hit the following crash on upstream commit
3fd14cdcc05a682b03743683ce3a726898b20555 (Fri Apr 6 19:15:41 2018 +0000)
Merge tag 'mtd/for-4.17' of git://git.infradead.org/linux-mtd
syzbot dashboard link:
https://syzkaller.appspot.com/bug?extid=619d9f40141d826b097e
Unfortunately, I don't have any reproducer for this crash yet.
Raw console output:
https://syzkaller.appspot.com/x/log.txt?id=4594231414882304
Kernel config:
https://syzkaller.appspot.com/x/.config?id=-5813481738265533882
compiler: gcc (GCC) 8.0.1 20180301 (experimental)
IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+619d9f40141d826b097e@syzkaller.appspotmail.com
It will help syzbot understand when the bug is fixed. See footer for
details.
If you forward the report, please keep this part and the footer.
8021q: adding VLAN 0 to HW filter on device team0
IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
8021q: adding VLAN 0 to HW filter on device team0
IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
8021q: adding VLAN 0 to HW filter on device team0
watchdog: BUG: soft lockup - CPU#1 stuck for 134s! [syz-executor2:10431]
Modules linked in:
irq event stamp: 35856
hardirqs last enabled at (35855): [<ffffffff874a1734>]
__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (35855): [<ffffffff874a1734>]
_raw_spin_unlock_irqrestore+0x74/0xc0 kernel/locking/spinlock.c:184
hardirqs last disabled at (35856): [<ffffffff87600901>]
interrupt_entry+0xb1/0xf0 arch/x86/entry/entry_64.S:624
softirqs last enabled at (162): [<ffffffff87800778>]
__do_softirq+0x778/0xaf5 kernel/softirq.c:311
softirqs last disabled at (95): [<ffffffff81467a61>] invoke_softirq
kernel/softirq.c:365 [inline]
softirqs last disabled at (95): [<ffffffff81467a61>] irq_exit+0x1d1/0x200
kernel/softirq.c:405
CPU: 1 PID: 10431 Comm: syz-executor2 Not tainted 4.16.0+ #4
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783
[inline]
RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160
[inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0xa1/0xc0
kernel/locking/spinlock.c:184
RSP: 0018:ffff880184db7780 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: dffffc0000000000 RBX: 0000000000000282 RCX: 0000000000000000
RDX: 1ffffffff1162e55 RSI: 0000000000000001 RDI: 0000000000000282
RBP: ffff880184db7790 R08: ffffed0035d21962 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8801ae90cb08
R13: ffff880184db7810 R14: 0000000000000001 R15: ffff8801cb9a5880
FS: 00007fc943ad8700(0000) GS:ffff8801db100000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fc943ad7db8 CR3: 00000001b070d000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
snd_virmidi_output_trigger+0x522/0x6c0 sound/core/seq/seq_virmidi.c:205
snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
snd_rawmidi_kernel_write1+0x519/0x700 sound/core/rawmidi.c:1288
snd_rawmidi_write+0x2e2/0xdc0 sound/core/rawmidi.c:1338
__vfs_write+0x10b/0x880 fs/read_write.c:485
vfs_write+0x1f8/0x560 fs/read_write.c:549
ksys_write+0xf9/0x250 fs/read_write.c:598
SYSC_write fs/read_write.c:610 [inline]
SyS_write+0x24/0x30 fs/read_write.c:607
do_syscall_64+0x29e/0x9d0 arch/x86/entry/common.c:287
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x455259
RSP: 002b:00007fc943ad7c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007fc943ad86d4 RCX: 0000000000455259
RDX: 00000000e78e624c RSI: 0000000020000040 RDI: 0000000000000014
RBP: 000000000072c010 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000000006ca R14: 00000000006fd390 R15: 0000000000000002
Code: c7 a8 72 b1 88 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea 03 80
3c 02 00 75 21 48 83 3d 4e 5b 67 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00
00 eb bb 0f 0b 0f 0b e8 6f 29 68 fa eb 97 e8 68 29
---
This bug is generated by a dumb bot. It may contain errors.
See https://goo.gl/tpsmEJ for details.
Direct all questions to syzkaller@googlegroups.com.
syzbot will keep track of this bug report.
If you forgot to add the Reported-by tag, once the fix for this bug is
merged
into any tree, please reply to this email with:
#syz fix: exact-commit-title
To mark this as a duplicate of another syzbot report, please reply with:
#syz dup: exact-subject-of-another-report
If it's a one-off invalid bug report, please reply with:
#syz invalid
Note: if the crash happens again, it will cause creation of a new bug
report.
Note: all commands must start from beginning of the line in the email body.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-04-09 5:58 BUG: soft lockup in snd_virmidi_output_trigger syzbot
@ 2018-04-09 13:03 ` Takashi Iwai
2018-04-09 13:52 ` Dmitry Vyukov
0 siblings, 1 reply; 11+ messages in thread
From: Takashi Iwai @ 2018-04-09 13:03 UTC (permalink / raw)
To: syzbot; +Cc: alsa-devel, syzkaller-bugs, perex, linux-kernel
On Mon, 09 Apr 2018 07:58:01 +0200,
syzbot wrote:
>
> Hello,
>
> syzbot hit the following crash on upstream commit
> 3fd14cdcc05a682b03743683ce3a726898b20555 (Fri Apr 6 19:15:41 2018 +0000)
> Merge tag 'mtd/for-4.17' of git://git.infradead.org/linux-mtd
> syzbot dashboard link:
> https://syzkaller.appspot.com/bug?extid=619d9f40141d826b097e
>
> Unfortunately, I don't have any reproducer for this crash yet.
> Raw console output:
> https://syzkaller.appspot.com/x/log.txt?id=4594231414882304
> Kernel config:
> https://syzkaller.appspot.com/x/.config?id=-5813481738265533882
> compiler: gcc (GCC) 8.0.1 20180301 (experimental)
>
> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> Reported-by: syzbot+619d9f40141d826b097e@syzkaller.appspotmail.com
> It will help syzbot understand when the bug is fixed. See footer for
> details.
> If you forward the report, please keep this part and the footer.
>
> 8021q: adding VLAN 0 to HW filter on device team0
> IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
> 8021q: adding VLAN 0 to HW filter on device team0
> IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
> 8021q: adding VLAN 0 to HW filter on device team0
> watchdog: BUG: soft lockup - CPU#1 stuck for 134s! [syz-executor2:10431]
> Modules linked in:
> irq event stamp: 35856
> hardirqs last enabled at (35855): [<ffffffff874a1734>]
> __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160
> [inline]
> hardirqs last enabled at (35855): [<ffffffff874a1734>]
> _raw_spin_unlock_irqrestore+0x74/0xc0 kernel/locking/spinlock.c:184
> hardirqs last disabled at (35856): [<ffffffff87600901>]
> interrupt_entry+0xb1/0xf0 arch/x86/entry/entry_64.S:624
> softirqs last enabled at (162): [<ffffffff87800778>]
> __do_softirq+0x778/0xaf5 kernel/softirq.c:311
> softirqs last disabled at (95): [<ffffffff81467a61>] invoke_softirq
> kernel/softirq.c:365 [inline]
> softirqs last disabled at (95): [<ffffffff81467a61>]
> irq_exit+0x1d1/0x200 kernel/softirq.c:405
> CPU: 1 PID: 10431 Comm: syz-executor2 Not tainted 4.16.0+ #4
> Hardware name: Google Google Compute Engine/Google Compute Engine,
> BIOS Google 01/01/2011
> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783
> [inline]
> RIP: 0010:__raw_spin_unlock_irqrestore
> include/linux/spinlock_api_smp.h:160 [inline]
> RIP: 0010:_raw_spin_unlock_irqrestore+0xa1/0xc0
> kernel/locking/spinlock.c:184
> RSP: 0018:ffff880184db7780 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
> RAX: dffffc0000000000 RBX: 0000000000000282 RCX: 0000000000000000
> RDX: 1ffffffff1162e55 RSI: 0000000000000001 RDI: 0000000000000282
> RBP: ffff880184db7790 R08: ffffed0035d21962 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000000 R12: ffff8801ae90cb08
> R13: ffff880184db7810 R14: 0000000000000001 R15: ffff8801cb9a5880
> FS: 00007fc943ad8700(0000) GS:ffff8801db100000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007fc943ad7db8 CR3: 00000001b070d000 CR4: 00000000001406e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Call Trace:
> spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
> snd_virmidi_output_trigger+0x522/0x6c0 sound/core/seq/seq_virmidi.c:205
> snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
> snd_rawmidi_kernel_write1+0x519/0x700 sound/core/rawmidi.c:1288
> snd_rawmidi_write+0x2e2/0xdc0 sound/core/rawmidi.c:1338
> __vfs_write+0x10b/0x880 fs/read_write.c:485
> vfs_write+0x1f8/0x560 fs/read_write.c:549
> ksys_write+0xf9/0x250 fs/read_write.c:598
> SYSC_write fs/read_write.c:610 [inline]
> SyS_write+0x24/0x30 fs/read_write.c:607
> do_syscall_64+0x29e/0x9d0 arch/x86/entry/common.c:287
> entry_SYSCALL_64_after_hwframe+0x42/0xb7
> RIP: 0033:0x455259
> RSP: 002b:00007fc943ad7c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
> RAX: ffffffffffffffda RBX: 00007fc943ad86d4 RCX: 0000000000455259
> RDX: 00000000e78e624c RSI: 0000000020000040 RDI: 0000000000000014
> RBP: 000000000072c010 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
> R13: 00000000000006ca R14: 00000000006fd390 R15: 0000000000000002
> Code: c7 a8 72 b1 88 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea
> 03 80 3c 02 00 75 21 48 83 3d 4e 5b 67 01 00 74 0e 48 89 df 57 9d
> <0f> 1f 44 00 00 eb bb 0f 0b 0f 0b e8 6f 29 68 fa eb 97 e8 68 29
This is quite new, and I still don't figure out what went wrong.
At first I thought of the endless loop in snd_virmidi_output_trigger()
(e.g the error handling of snd_midi_event_encode() continues the loop,
and it may go into an endless loop in theory. But, practically,
snd_midi_event_encode() never returns an error, so it shouldn't
matter.) But it doesn't explain why the report points to
spin_unlock_IRQ restore().
If you have a similar report or any relevant information, please let
me know.
thanks,
Takashi
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-04-09 13:03 ` Takashi Iwai
@ 2018-04-09 13:52 ` Dmitry Vyukov
0 siblings, 0 replies; 11+ messages in thread
From: Dmitry Vyukov @ 2018-04-09 13:52 UTC (permalink / raw)
To: Takashi Iwai; +Cc: syzbot, alsa-devel, syzkaller-bugs, Jaroslav Kysela, LKML
On Mon, Apr 9, 2018 at 3:03 PM, Takashi Iwai <tiwai@suse.de> wrote:
> On Mon, 09 Apr 2018 07:58:01 +0200,
> syzbot wrote:
>>
>> Hello,
>>
>> syzbot hit the following crash on upstream commit
>> 3fd14cdcc05a682b03743683ce3a726898b20555 (Fri Apr 6 19:15:41 2018 +0000)
>> Merge tag 'mtd/for-4.17' of git://git.infradead.org/linux-mtd
>> syzbot dashboard link:
>> https://syzkaller.appspot.com/bug?extid=619d9f40141d826b097e
>>
>> Unfortunately, I don't have any reproducer for this crash yet.
>> Raw console output:
>> https://syzkaller.appspot.com/x/log.txt?id=4594231414882304
>> Kernel config:
>> https://syzkaller.appspot.com/x/.config?id=-5813481738265533882
>> compiler: gcc (GCC) 8.0.1 20180301 (experimental)
>>
>> IMPORTANT: if you fix the bug, please add the following tag to the commit:
>> Reported-by: syzbot+619d9f40141d826b097e@syzkaller.appspotmail.com
>> It will help syzbot understand when the bug is fixed. See footer for
>> details.
>> If you forward the report, please keep this part and the footer.
>>
>> 8021q: adding VLAN 0 to HW filter on device team0
>> IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
>> 8021q: adding VLAN 0 to HW filter on device team0
>> IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
>> 8021q: adding VLAN 0 to HW filter on device team0
>> watchdog: BUG: soft lockup - CPU#1 stuck for 134s! [syz-executor2:10431]
>> Modules linked in:
>> irq event stamp: 35856
>> hardirqs last enabled at (35855): [<ffffffff874a1734>]
>> __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160
>> [inline]
>> hardirqs last enabled at (35855): [<ffffffff874a1734>]
>> _raw_spin_unlock_irqrestore+0x74/0xc0 kernel/locking/spinlock.c:184
>> hardirqs last disabled at (35856): [<ffffffff87600901>]
>> interrupt_entry+0xb1/0xf0 arch/x86/entry/entry_64.S:624
>> softirqs last enabled at (162): [<ffffffff87800778>]
>> __do_softirq+0x778/0xaf5 kernel/softirq.c:311
>> softirqs last disabled at (95): [<ffffffff81467a61>] invoke_softirq
>> kernel/softirq.c:365 [inline]
>> softirqs last disabled at (95): [<ffffffff81467a61>]
>> irq_exit+0x1d1/0x200 kernel/softirq.c:405
>> CPU: 1 PID: 10431 Comm: syz-executor2 Not tainted 4.16.0+ #4
>> Hardware name: Google Google Compute Engine/Google Compute Engine,
>> BIOS Google 01/01/2011
>> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783
>> [inline]
>> RIP: 0010:__raw_spin_unlock_irqrestore
>> include/linux/spinlock_api_smp.h:160 [inline]
>> RIP: 0010:_raw_spin_unlock_irqrestore+0xa1/0xc0
>> kernel/locking/spinlock.c:184
>> RSP: 0018:ffff880184db7780 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
>> RAX: dffffc0000000000 RBX: 0000000000000282 RCX: 0000000000000000
>> RDX: 1ffffffff1162e55 RSI: 0000000000000001 RDI: 0000000000000282
>> RBP: ffff880184db7790 R08: ffffed0035d21962 R09: 0000000000000000
>> R10: 0000000000000000 R11: 0000000000000000 R12: ffff8801ae90cb08
>> R13: ffff880184db7810 R14: 0000000000000001 R15: ffff8801cb9a5880
>> FS: 00007fc943ad8700(0000) GS:ffff8801db100000(0000) knlGS:0000000000000000
>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007fc943ad7db8 CR3: 00000001b070d000 CR4: 00000000001406e0
>> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
>> Call Trace:
>> spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
>> snd_virmidi_output_trigger+0x522/0x6c0 sound/core/seq/seq_virmidi.c:205
>> snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
>> snd_rawmidi_kernel_write1+0x519/0x700 sound/core/rawmidi.c:1288
>> snd_rawmidi_write+0x2e2/0xdc0 sound/core/rawmidi.c:1338
>> __vfs_write+0x10b/0x880 fs/read_write.c:485
>> vfs_write+0x1f8/0x560 fs/read_write.c:549
>> ksys_write+0xf9/0x250 fs/read_write.c:598
>> SYSC_write fs/read_write.c:610 [inline]
>> SyS_write+0x24/0x30 fs/read_write.c:607
>> do_syscall_64+0x29e/0x9d0 arch/x86/entry/common.c:287
>> entry_SYSCALL_64_after_hwframe+0x42/0xb7
>> RIP: 0033:0x455259
>> RSP: 002b:00007fc943ad7c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
>> RAX: ffffffffffffffda RBX: 00007fc943ad86d4 RCX: 0000000000455259
>> RDX: 00000000e78e624c RSI: 0000000020000040 RDI: 0000000000000014
>> RBP: 000000000072c010 R08: 0000000000000000 R09: 0000000000000000
>> R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
>> R13: 00000000000006ca R14: 00000000006fd390 R15: 0000000000000002
>> Code: c7 a8 72 b1 88 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea
>> 03 80 3c 02 00 75 21 48 83 3d 4e 5b 67 01 00 74 0e 48 89 df 57 9d
>> <0f> 1f 44 00 00 eb bb 0f 0b 0f 0b e8 6f 29 68 fa eb 97 e8 68 29
>
> This is quite new, and I still don't figure out what went wrong.
>
> At first I thought of the endless loop in snd_virmidi_output_trigger()
> (e.g the error handling of snd_midi_event_encode() continues the loop,
> and it may go into an endless loop in theory. But, practically,
> snd_midi_event_encode() never returns an error, so it shouldn't
> matter.) But it doesn't explain why the report points to
> spin_unlock_IRQ restore().
>
> If you have a similar report or any relevant information, please let
> me know.
All information syzbot has is available here (not much for now though):
https://syzkaller.appspot.com/bug?extid=619d9f40141d826b097e
And here are all other reports, if case you want to correlate it with
other stalls:
https://syzkaller.appspot.com
^ permalink raw reply [flat|nested] 11+ messages in thread
* BUG: soft lockup in snd_virmidi_output_trigger
@ 2018-07-26 5:53 Dae R. Jeong
2018-07-26 12:50 ` Takashi Iwai
0 siblings, 1 reply; 11+ messages in thread
From: Dae R. Jeong @ 2018-07-26 5:53 UTC (permalink / raw)
To: perex, tiwai; +Cc: alsa-devel, linux-kernel, kt0755, bammanag, syzkaller
Reporting the crash: BUG: soft lockup in snd_virmidi_output_trigger
This crash has been found in v4.18-rc3 using RaceFuzzer (a modified
version of Syzkaller), which we describe more at the end of this
report.
Note that this bug is previously reported by Syzkaller a few month ago.
(https://syzkaller.appspot.com/bug?id=642c927972318775e0ea1b4779ccd8624ce9e6f5)
Nonetheless, the crash still can be detected. We guess that the crash has
not fixed yet.
We report the crash log and the attached reproducer with a hope that they are
helpful to diagnose the crash and to fix a bug.
C Reproducer:
https://kiwi.cs.purdue.edu/static/race-fuzzer/repro-dab082.c
Kernel config:
https://kiwi.cs.purdue.edu/static/race-fuzzer/config-dab082
(Please disregard all code related to "should_hypercall" in the C repro,
as this is only for our debugging purposes using our own hypervisor.)
Crash log:
==================================================================
watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [syz-executor0:24261]
Modules linked in:
irq event stamp: 6692
hardirqs last enabled at (6691): [<ffffffff84eb1f12>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (6691): [<ffffffff84eb1f12>] _raw_spin_unlock_irqrestore+0x62/0x90 kernel/locking/spinlock.c:184
hardirqs last disabled at (6692): [<ffffffff85000905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
softirqs last enabled at (1468): [<ffffffff852005ff>] __do_softirq+0x5ff/0x7f4 kernel/softirq.c:314
softirqs last disabled at (1455): [<ffffffff8130de56>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (1455): [<ffffffff8130de56>] irq_exit+0x126/0x130 kernel/softirq.c:408
CPU: 1 PID: 24261 Comm: syz-executor0 Not tainted 4.18.0-rc3 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
RIP: 0010:_raw_spin_unlock_irqrestore+0x7d/0x90 kernel/locking/spinlock.c:184
Code: 0d c8 ce 16 7b 5b 41 5c 5d c3 e8 3e 0f 52 fc 48 c7 c7 68 b0 71 86 e8 62 4c 8d fc 48 83 3d 42 91 86 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00 00 eb cd 0f 0b 0f 0b 0f 1f 84 00 00 00 00 00 55 48 89
RSP: 0018:ffff8801b8e4f7e8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 0000000000000000 RBX: 0000000000000282 RCX: ffffffff84eb1f1e
RDX: dffffc0000000000 RSI: dffffc0000000000 RDI: 0000000000000282
RBP: ffff8801b8e4f7f8 R08: ffffed002573a06a R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012b9d0348
R13: ffff8801e6417580 R14: ffff8801b8e4f868 R15: ffff8801e64175a8
FS: 00007f3447a49700(0000) GS:ffff8801f6d00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f3447a48db8 CR3: 00000001ee58d000 CR4: 00000000000006e0
Call Trace:
spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
snd_virmidi_output_trigger+0x37d/0x420 sound/core/seq/seq_virmidi.c:205
snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
snd_rawmidi_kernel_write1+0x383/0x410 sound/core/rawmidi.c:1288
snd_rawmidi_write+0x249/0xa50 sound/core/rawmidi.c:1338
__vfs_write+0xf9/0x5d0 fs/read_write.c:485
vfs_write+0x195/0x380 fs/read_write.c:549
ksys_write+0xdb/0x1d0 fs/read_write.c:598
__do_sys_write fs/read_write.c:610 [inline]
__se_sys_write fs/read_write.c:607 [inline]
__x64_sys_write+0x43/0x50 fs/read_write.c:607
do_syscall_64+0x182/0x540 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x44b939
Code: 8d 6b fc ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 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 0f 83 5b 6b fc ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f3447a48b48 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 000000000071bfa0 RCX: 000000000044b939
RDX: 000000002000010b RSI: 0000000020000100 RDI: 0000000000000013
RBP: 000000000000b7a8 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007f3447a496d4
R13: 00000000ffffffff R14: 00000000006f7848 R15: 0000000000000000
= About RaceFuzzer
RaceFuzzer is a customized version of Syzkaller, specifically tailored
to find race condition bugs in the Linux kernel. While we leverage
many different technique, the notable feature of RaceFuzzer is in
leveraging a custom hypervisor (QEMU/KVM) to interleave the
scheduling. In particular, we modified the hypervisor to intentionally
stall a per-core execution, which is similar to supporting per-core
breakpoint functionality. This allows RaceFuzzer to force the kernel
to deterministically trigger racy condition (which may rarely happen
in practice due to randomness in scheduling).
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-26 5:53 Dae R. Jeong
@ 2018-07-26 12:50 ` Takashi Iwai
2018-07-26 12:58 ` Dmitry Vyukov
2018-07-27 4:13 ` Dae R. Jeong
0 siblings, 2 replies; 11+ messages in thread
From: Takashi Iwai @ 2018-07-26 12:50 UTC (permalink / raw)
To: Dae R. Jeong
Cc: perex, alsa-devel, kt0755, syzkaller, bammanag, linux-kernel
On Thu, 26 Jul 2018 07:53:26 +0200,
Dae R. Jeong wrote:
>
> Reporting the crash: BUG: soft lockup in snd_virmidi_output_trigger
>
> This crash has been found in v4.18-rc3 using RaceFuzzer (a modified
> version of Syzkaller), which we describe more at the end of this
> report.
>
> Note that this bug is previously reported by Syzkaller a few month ago.
> (https://syzkaller.appspot.com/bug?id=642c927972318775e0ea1b4779ccd8624ce9e6f5)
> Nonetheless, the crash still can be detected. We guess that the crash has
> not fixed yet.
> We report the crash log and the attached reproducer with a hope that they are
> helpful to diagnose the crash and to fix a bug.
>
> C Reproducer:
> https://kiwi.cs.purdue.edu/static/race-fuzzer/repro-dab082.c
>
> Kernel config:
> https://kiwi.cs.purdue.edu/static/race-fuzzer/config-dab082
>
> (Please disregard all code related to "should_hypercall" in the C repro,
> as this is only for our debugging purposes using our own hypervisor.)
>
>
> Crash log:
> ==================================================================
> watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [syz-executor0:24261]
> Modules linked in:
> irq event stamp: 6692
> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] _raw_spin_unlock_irqrestore+0x62/0x90 kernel/locking/spinlock.c:184
> hardirqs last disabled at (6692): [<ffffffff85000905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
> softirqs last enabled at (1468): [<ffffffff852005ff>] __do_softirq+0x5ff/0x7f4 kernel/softirq.c:314
> softirqs last disabled at (1455): [<ffffffff8130de56>] invoke_softirq kernel/softirq.c:368 [inline]
> softirqs last disabled at (1455): [<ffffffff8130de56>] irq_exit+0x126/0x130 kernel/softirq.c:408
> CPU: 1 PID: 24261 Comm: syz-executor0 Not tainted 4.18.0-rc3 #1
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
> RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> RIP: 0010:_raw_spin_unlock_irqrestore+0x7d/0x90 kernel/locking/spinlock.c:184
> Code: 0d c8 ce 16 7b 5b 41 5c 5d c3 e8 3e 0f 52 fc 48 c7 c7 68 b0 71 86 e8 62 4c 8d fc 48 83 3d 42 91 86 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00 00 eb cd 0f 0b 0f 0b 0f 1f 84 00 00 00 00 00 55 48 89
> RSP: 0018:ffff8801b8e4f7e8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
> RAX: 0000000000000000 RBX: 0000000000000282 RCX: ffffffff84eb1f1e
> RDX: dffffc0000000000 RSI: dffffc0000000000 RDI: 0000000000000282
> RBP: ffff8801b8e4f7f8 R08: ffffed002573a06a R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012b9d0348
> R13: ffff8801e6417580 R14: ffff8801b8e4f868 R15: ffff8801e64175a8
> FS: 00007f3447a49700(0000) GS:ffff8801f6d00000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007f3447a48db8 CR3: 00000001ee58d000 CR4: 00000000000006e0
> Call Trace:
> spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
> snd_virmidi_output_trigger+0x37d/0x420 sound/core/seq/seq_virmidi.c:205
> snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
> snd_rawmidi_kernel_write1+0x383/0x410 sound/core/rawmidi.c:1288
> snd_rawmidi_write+0x249/0xa50 sound/core/rawmidi.c:1338
This seems to be a long loop in snd_virmidi_output_trigger processed
in a spinlock. The below patch puts a cond_resched() for avoiding the
possible stalls, and it seems working.
Let me know if this works for you.
thanks,
Takashi
-- 8< --
From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH] ALSA: virmidi: Fix too long output trigger loop
The virmidi output trigger tries to parse the all available bytes and
process sequencer events as much as possible. In a normal situation,
this is supposed to be relatively short, but a program may give a huge
buffer and it'll take a long time in a single spin lock, which may
eventually lead to a soft lockup.
This patch simply adds a workaround, a cond_resched() call in the loop
if applicable. A better solution would be to move the event processor
into a work, but let's put a duct-tape quickly at first.
Reported-by: Dae R. Jeong <threeearcat@gmail.com>
Cc: <stable@vger.kernel.org>
Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
sound/core/seq/seq_virmidi.c | 6 ++++++
1 file changed, 6 insertions(+)
diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
index 289ae6bb81d9..65549d41533e 100644
--- a/sound/core/seq/seq_virmidi.c
+++ b/sound/core/seq/seq_virmidi.c
@@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
int count, res;
unsigned char buf[32], *pbuf;
unsigned long flags;
+ bool check_resched = !in_atomic();
if (up) {
vmidi->trigger = 1;
@@ -200,6 +201,11 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
}
}
+ if (!check_resched)
+ continue;
+ spin_unlock_irqrestore(&substream->runtime->lock, flags);
+ cond_resched();
+ spin_lock_irqsave(&substream->runtime->lock, flags);
}
out:
spin_unlock_irqrestore(&substream->runtime->lock, flags);
--
2.18.0
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-26 12:50 ` Takashi Iwai
@ 2018-07-26 12:58 ` Dmitry Vyukov
2018-07-26 13:07 ` Takashi Iwai
2018-07-27 4:13 ` Dae R. Jeong
1 sibling, 1 reply; 11+ messages in thread
From: Dmitry Vyukov @ 2018-07-26 12:58 UTC (permalink / raw)
To: Takashi Iwai
Cc: Dae R. Jeong, Jaroslav Kysela, alsa-devel, kt0755, syzkaller,
bammanag, LKML
On Thu, Jul 26, 2018 at 2:50 PM, Takashi Iwai <tiwai@suse.de> wrote:
> On Thu, 26 Jul 2018 07:53:26 +0200,
> Dae R. Jeong wrote:
>>
>> Reporting the crash: BUG: soft lockup in snd_virmidi_output_trigger
>>
>> This crash has been found in v4.18-rc3 using RaceFuzzer (a modified
>> version of Syzkaller), which we describe more at the end of this
>> report.
>>
>> Note that this bug is previously reported by Syzkaller a few month ago.
>> (https://syzkaller.appspot.com/bug?id=642c927972318775e0ea1b4779ccd8624ce9e6f5)
>> Nonetheless, the crash still can be detected. We guess that the crash has
>> not fixed yet.
>> We report the crash log and the attached reproducer with a hope that they are
>> helpful to diagnose the crash and to fix a bug.
>>
>> C Reproducer:
>> https://kiwi.cs.purdue.edu/static/race-fuzzer/repro-dab082.c
>>
>> Kernel config:
>> https://kiwi.cs.purdue.edu/static/race-fuzzer/config-dab082
>>
>> (Please disregard all code related to "should_hypercall" in the C repro,
>> as this is only for our debugging purposes using our own hypervisor.)
>>
>>
>> Crash log:
>> ==================================================================
>> watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [syz-executor0:24261]
>> Modules linked in:
>> irq event stamp: 6692
>> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
>> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] _raw_spin_unlock_irqrestore+0x62/0x90 kernel/locking/spinlock.c:184
>> hardirqs last disabled at (6692): [<ffffffff85000905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
>> softirqs last enabled at (1468): [<ffffffff852005ff>] __do_softirq+0x5ff/0x7f4 kernel/softirq.c:314
>> softirqs last disabled at (1455): [<ffffffff8130de56>] invoke_softirq kernel/softirq.c:368 [inline]
>> softirqs last disabled at (1455): [<ffffffff8130de56>] irq_exit+0x126/0x130 kernel/softirq.c:408
>> CPU: 1 PID: 24261 Comm: syz-executor0 Not tainted 4.18.0-rc3 #1
>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
>> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
>> RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
>> RIP: 0010:_raw_spin_unlock_irqrestore+0x7d/0x90 kernel/locking/spinlock.c:184
>> Code: 0d c8 ce 16 7b 5b 41 5c 5d c3 e8 3e 0f 52 fc 48 c7 c7 68 b0 71 86 e8 62 4c 8d fc 48 83 3d 42 91 86 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00 00 eb cd 0f 0b 0f 0b 0f 1f 84 00 00 00 00 00 55 48 89
>> RSP: 0018:ffff8801b8e4f7e8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
>> RAX: 0000000000000000 RBX: 0000000000000282 RCX: ffffffff84eb1f1e
>> RDX: dffffc0000000000 RSI: dffffc0000000000 RDI: 0000000000000282
>> RBP: ffff8801b8e4f7f8 R08: ffffed002573a06a R09: 0000000000000000
>> R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012b9d0348
>> R13: ffff8801e6417580 R14: ffff8801b8e4f868 R15: ffff8801e64175a8
>> FS: 00007f3447a49700(0000) GS:ffff8801f6d00000(0000) knlGS:0000000000000000
>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007f3447a48db8 CR3: 00000001ee58d000 CR4: 00000000000006e0
>> Call Trace:
>> spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
>> snd_virmidi_output_trigger+0x37d/0x420 sound/core/seq/seq_virmidi.c:205
>> snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
>> snd_rawmidi_kernel_write1+0x383/0x410 sound/core/rawmidi.c:1288
>> snd_rawmidi_write+0x249/0xa50 sound/core/rawmidi.c:1338
>
> This seems to be a long loop in snd_virmidi_output_trigger processed
> in a spinlock. The below patch puts a cond_resched() for avoiding the
> possible stalls, and it seems working.
>
> Let me know if this works for you.
>
>
> thanks,
>
> Takashi
>
> -- 8< --
> From: Takashi Iwai <tiwai@suse.de>
> Subject: [PATCH] ALSA: virmidi: Fix too long output trigger loop
>
> The virmidi output trigger tries to parse the all available bytes and
> process sequencer events as much as possible. In a normal situation,
> this is supposed to be relatively short, but a program may give a huge
> buffer and it'll take a long time in a single spin lock, which may
> eventually lead to a soft lockup.
>
> This patch simply adds a workaround, a cond_resched() call in the loop
> if applicable. A better solution would be to move the event processor
> into a work, but let's put a duct-tape quickly at first.
>
> Reported-by: Dae R. Jeong <threeearcat@gmail.com>
> Cc: <stable@vger.kernel.org>
> Signed-off-by: Takashi Iwai <tiwai@suse.de>
> ---
> sound/core/seq/seq_virmidi.c | 6 ++++++
> 1 file changed, 6 insertions(+)
>
> diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> index 289ae6bb81d9..65549d41533e 100644
> --- a/sound/core/seq/seq_virmidi.c
> +++ b/sound/core/seq/seq_virmidi.c
> @@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> int count, res;
> unsigned char buf[32], *pbuf;
> unsigned long flags;
> + bool check_resched = !in_atomic();
>
> if (up) {
> vmidi->trigger = 1;
> @@ -200,6 +201,11 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
> }
> }
> + if (!check_resched)
> + continue;
> + spin_unlock_irqrestore(&substream->runtime->lock, flags);
> + cond_resched();
> + spin_lock_irqsave(&substream->runtime->lock, flags);
> }
> out:
> spin_unlock_irqrestore(&substream->runtime->lock, flags);
Just in case: is it a killable loop? It seems that user can make
kernel stuck there almost infinitely.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-26 12:58 ` Dmitry Vyukov
@ 2018-07-26 13:07 ` Takashi Iwai
0 siblings, 0 replies; 11+ messages in thread
From: Takashi Iwai @ 2018-07-26 13:07 UTC (permalink / raw)
To: Dmitry Vyukov
Cc: Dae R. Jeong, Jaroslav Kysela, alsa-devel, kt0755, syzkaller,
bammanag, LKML
On Thu, 26 Jul 2018 14:58:59 +0200,
Dmitry Vyukov wrote:
>
> On Thu, Jul 26, 2018 at 2:50 PM, Takashi Iwai <tiwai@suse.de> wrote:
> > On Thu, 26 Jul 2018 07:53:26 +0200,
> > Dae R. Jeong wrote:
> >>
> >> Reporting the crash: BUG: soft lockup in snd_virmidi_output_trigger
> >>
> >> This crash has been found in v4.18-rc3 using RaceFuzzer (a modified
> >> version of Syzkaller), which we describe more at the end of this
> >> report.
> >>
> >> Note that this bug is previously reported by Syzkaller a few month ago.
> >> (https://syzkaller.appspot.com/bug?id=642c927972318775e0ea1b4779ccd8624ce9e6f5)
> >> Nonetheless, the crash still can be detected. We guess that the crash has
> >> not fixed yet.
> >> We report the crash log and the attached reproducer with a hope that they are
> >> helpful to diagnose the crash and to fix a bug.
> >>
> >> C Reproducer:
> >> https://kiwi.cs.purdue.edu/static/race-fuzzer/repro-dab082.c
> >>
> >> Kernel config:
> >> https://kiwi.cs.purdue.edu/static/race-fuzzer/config-dab082
> >>
> >> (Please disregard all code related to "should_hypercall" in the C repro,
> >> as this is only for our debugging purposes using our own hypervisor.)
> >>
> >>
> >> Crash log:
> >> ==================================================================
> >> watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [syz-executor0:24261]
> >> Modules linked in:
> >> irq event stamp: 6692
> >> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> >> hardirqs last enabled at (6691): [<ffffffff84eb1f12>] _raw_spin_unlock_irqrestore+0x62/0x90 kernel/locking/spinlock.c:184
> >> hardirqs last disabled at (6692): [<ffffffff85000905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
> >> softirqs last enabled at (1468): [<ffffffff852005ff>] __do_softirq+0x5ff/0x7f4 kernel/softirq.c:314
> >> softirqs last disabled at (1455): [<ffffffff8130de56>] invoke_softirq kernel/softirq.c:368 [inline]
> >> softirqs last disabled at (1455): [<ffffffff8130de56>] irq_exit+0x126/0x130 kernel/softirq.c:408
> >> CPU: 1 PID: 24261 Comm: syz-executor0 Not tainted 4.18.0-rc3 #1
> >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
> >> RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
> >> RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> >> RIP: 0010:_raw_spin_unlock_irqrestore+0x7d/0x90 kernel/locking/spinlock.c:184
> >> Code: 0d c8 ce 16 7b 5b 41 5c 5d c3 e8 3e 0f 52 fc 48 c7 c7 68 b0 71 86 e8 62 4c 8d fc 48 83 3d 42 91 86 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00 00 eb cd 0f 0b 0f 0b 0f 1f 84 00 00 00 00 00 55 48 89
> >> RSP: 0018:ffff8801b8e4f7e8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
> >> RAX: 0000000000000000 RBX: 0000000000000282 RCX: ffffffff84eb1f1e
> >> RDX: dffffc0000000000 RSI: dffffc0000000000 RDI: 0000000000000282
> >> RBP: ffff8801b8e4f7f8 R08: ffffed002573a06a R09: 0000000000000000
> >> R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012b9d0348
> >> R13: ffff8801e6417580 R14: ffff8801b8e4f868 R15: ffff8801e64175a8
> >> FS: 00007f3447a49700(0000) GS:ffff8801f6d00000(0000) knlGS:0000000000000000
> >> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >> CR2: 00007f3447a48db8 CR3: 00000001ee58d000 CR4: 00000000000006e0
> >> Call Trace:
> >> spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
> >> snd_virmidi_output_trigger+0x37d/0x420 sound/core/seq/seq_virmidi.c:205
> >> snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
> >> snd_rawmidi_kernel_write1+0x383/0x410 sound/core/rawmidi.c:1288
> >> snd_rawmidi_write+0x249/0xa50 sound/core/rawmidi.c:1338
> >
> > This seems to be a long loop in snd_virmidi_output_trigger processed
> > in a spinlock. The below patch puts a cond_resched() for avoiding the
> > possible stalls, and it seems working.
> >
> > Let me know if this works for you.
> >
> >
> > thanks,
> >
> > Takashi
> >
> > -- 8< --
> > From: Takashi Iwai <tiwai@suse.de>
> > Subject: [PATCH] ALSA: virmidi: Fix too long output trigger loop
> >
> > The virmidi output trigger tries to parse the all available bytes and
> > process sequencer events as much as possible. In a normal situation,
> > this is supposed to be relatively short, but a program may give a huge
> > buffer and it'll take a long time in a single spin lock, which may
> > eventually lead to a soft lockup.
> >
> > This patch simply adds a workaround, a cond_resched() call in the loop
> > if applicable. A better solution would be to move the event processor
> > into a work, but let's put a duct-tape quickly at first.
> >
> > Reported-by: Dae R. Jeong <threeearcat@gmail.com>
> > Cc: <stable@vger.kernel.org>
> > Signed-off-by: Takashi Iwai <tiwai@suse.de>
> > ---
> > sound/core/seq/seq_virmidi.c | 6 ++++++
> > 1 file changed, 6 insertions(+)
> >
> > diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> > index 289ae6bb81d9..65549d41533e 100644
> > --- a/sound/core/seq/seq_virmidi.c
> > +++ b/sound/core/seq/seq_virmidi.c
> > @@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> > int count, res;
> > unsigned char buf[32], *pbuf;
> > unsigned long flags;
> > + bool check_resched = !in_atomic();
> >
> > if (up) {
> > vmidi->trigger = 1;
> > @@ -200,6 +201,11 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> > vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
> > }
> > }
> > + if (!check_resched)
> > + continue;
> > + spin_unlock_irqrestore(&substream->runtime->lock, flags);
> > + cond_resched();
> > + spin_lock_irqsave(&substream->runtime->lock, flags);
> > }
> > out:
> > spin_unlock_irqrestore(&substream->runtime->lock, flags);
>
>
>
> Just in case: is it a killable loop? It seems that user can make
> kernel stuck there almost infinitely.
Well, the original buffer size in rawmidi is limited, so this loop
should be limited, too. I haven't seen the unkillable task through
tests.
thanks,
Takashi
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-26 12:50 ` Takashi Iwai
2018-07-26 12:58 ` Dmitry Vyukov
@ 2018-07-27 4:13 ` Dae R. Jeong
2018-07-27 5:20 ` Takashi Iwai
1 sibling, 1 reply; 11+ messages in thread
From: Dae R. Jeong @ 2018-07-27 4:13 UTC (permalink / raw)
To: Takashi Iwai; +Cc: perex, alsa-devel, kt0755, syzkaller, bammanag, linux-kernel
On Thu, Jul 26, 2018 at 02:50:25PM +0200, Takashi Iwai wrote:
> On Thu, 26 Jul 2018 07:53:26 +0200,
> Dae R. Jeong wrote:
> >
> > Reporting the crash: BUG: soft lockup in snd_virmidi_output_trigger
> >
> > This crash has been found in v4.18-rc3 using RaceFuzzer (a modified
> > version of Syzkaller), which we describe more at the end of this
> > report.
> >
> > Note that this bug is previously reported by Syzkaller a few month ago.
> > (https://syzkaller.appspot.com/bug?id=642c927972318775e0ea1b4779ccd8624ce9e6f5)
> > Nonetheless, the crash still can be detected. We guess that the crash has
> > not fixed yet.
> > We report the crash log and the attached reproducer with a hope that they are
> > helpful to diagnose the crash and to fix a bug.
> >
> > C Reproducer:
> > https://kiwi.cs.purdue.edu/static/race-fuzzer/repro-dab082.c
> >
> > Kernel config:
> > https://kiwi.cs.purdue.edu/static/race-fuzzer/config-dab082
> >
> > (Please disregard all code related to "should_hypercall" in the C repro,
> > as this is only for our debugging purposes using our own hypervisor.)
> >
> >
> > Crash log:
> > ==================================================================
> > watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [syz-executor0:24261]
> > Modules linked in:
> > irq event stamp: 6692
> > hardirqs last enabled at (6691): [<ffffffff84eb1f12>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> > hardirqs last enabled at (6691): [<ffffffff84eb1f12>] _raw_spin_unlock_irqrestore+0x62/0x90 kernel/locking/spinlock.c:184
> > hardirqs last disabled at (6692): [<ffffffff85000905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
> > softirqs last enabled at (1468): [<ffffffff852005ff>] __do_softirq+0x5ff/0x7f4 kernel/softirq.c:314
> > softirqs last disabled at (1455): [<ffffffff8130de56>] invoke_softirq kernel/softirq.c:368 [inline]
> > softirqs last disabled at (1455): [<ffffffff8130de56>] irq_exit+0x126/0x130 kernel/softirq.c:408
> > CPU: 1 PID: 24261 Comm: syz-executor0 Not tainted 4.18.0-rc3 #1
> > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
> > RIP: 0010:arch_local_irq_restore arch/x86/include/asm/paravirt.h:783 [inline]
> > RIP: 0010:__raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
> > RIP: 0010:_raw_spin_unlock_irqrestore+0x7d/0x90 kernel/locking/spinlock.c:184
> > Code: 0d c8 ce 16 7b 5b 41 5c 5d c3 e8 3e 0f 52 fc 48 c7 c7 68 b0 71 86 e8 62 4c 8d fc 48 83 3d 42 91 86 01 00 74 0e 48 89 df 57 9d <0f> 1f 44 00 00 eb cd 0f 0b 0f 0b 0f 1f 84 00 00 00 00 00 55 48 89
> > RSP: 0018:ffff8801b8e4f7e8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
> > RAX: 0000000000000000 RBX: 0000000000000282 RCX: ffffffff84eb1f1e
> > RDX: dffffc0000000000 RSI: dffffc0000000000 RDI: 0000000000000282
> > RBP: ffff8801b8e4f7f8 R08: ffffed002573a06a R09: 0000000000000000
> > R10: 0000000000000000 R11: 0000000000000000 R12: ffff88012b9d0348
> > R13: ffff8801e6417580 R14: ffff8801b8e4f868 R15: ffff8801e64175a8
> > FS: 00007f3447a49700(0000) GS:ffff8801f6d00000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 00007f3447a48db8 CR3: 00000001ee58d000 CR4: 00000000000006e0
> > Call Trace:
> > spin_unlock_irqrestore include/linux/spinlock.h:365 [inline]
> > snd_virmidi_output_trigger+0x37d/0x420 sound/core/seq/seq_virmidi.c:205
> > snd_rawmidi_output_trigger sound/core/rawmidi.c:150 [inline]
> > snd_rawmidi_kernel_write1+0x383/0x410 sound/core/rawmidi.c:1288
> > snd_rawmidi_write+0x249/0xa50 sound/core/rawmidi.c:1338
>
> This seems to be a long loop in snd_virmidi_output_trigger processed
> in a spinlock. The below patch puts a cond_resched() for avoiding the
> possible stalls, and it seems working.
>
> Let me know if this works for you.
>
>
> thanks,
>
> Takashi
>
> -- 8< --
> From: Takashi Iwai <tiwai@suse.de>
> Subject: [PATCH] ALSA: virmidi: Fix too long output trigger loop
>
> The virmidi output trigger tries to parse the all available bytes and
> process sequencer events as much as possible. In a normal situation,
> this is supposed to be relatively short, but a program may give a huge
> buffer and it'll take a long time in a single spin lock, which may
> eventually lead to a soft lockup.
>
> This patch simply adds a workaround, a cond_resched() call in the loop
> if applicable. A better solution would be to move the event processor
> into a work, but let's put a duct-tape quickly at first.
>
> Reported-by: Dae R. Jeong <threeearcat@gmail.com>
> Cc: <stable@vger.kernel.org>
> Signed-off-by: Takashi Iwai <tiwai@suse.de>
> ---
> sound/core/seq/seq_virmidi.c | 6 ++++++
> 1 file changed, 6 insertions(+)
>
> diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> index 289ae6bb81d9..65549d41533e 100644
> --- a/sound/core/seq/seq_virmidi.c
> +++ b/sound/core/seq/seq_virmidi.c
> @@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> int count, res;
> unsigned char buf[32], *pbuf;
> unsigned long flags;
> + bool check_resched = !in_atomic();
>
> if (up) {
> vmidi->trigger = 1;
> @@ -200,6 +201,11 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
> }
> }
> + if (!check_resched)
> + continue;
> + spin_unlock_irqrestore(&substream->runtime->lock, flags);
> + cond_resched();
> + spin_lock_irqsave(&substream->runtime->lock, flags);
> }
> out:
> spin_unlock_irqrestore(&substream->runtime->lock, flags);
> --
> 2.18.0
>
I tested it and it worked.
Thanks a lot!
Dae R. Jeong
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-27 4:13 ` Dae R. Jeong
@ 2018-07-27 5:20 ` Takashi Iwai
2018-07-27 5:51 ` Dae R. Jeong
0 siblings, 1 reply; 11+ messages in thread
From: Takashi Iwai @ 2018-07-27 5:20 UTC (permalink / raw)
To: Dae R. Jeong; +Cc: perex, alsa-devel, kt0755, syzkaller, bammanag, linux-kernel
On Fri, 27 Jul 2018 06:13:22 +0200,
Dae R. Jeong wrote:
>
> I tested it and it worked.
> Thanks a lot!
Good to hear. Below is the final patch with a proper comment (and
with syzbot reported-by, too) I'm going to queue to sound.git tree.
thanks,
Takashi
-- 8< --
From: Takashi Iwai <tiwai@suse.de>
Subject: [PATCH v2] ALSA: virmidi: Fix too long output trigger loop
The virmidi output trigger tries to parse the all available bytes and
process sequencer events as much as possible. In a normal situation,
this is supposed to be relatively short, but a program may give a huge
buffer and it'll take a long time in a single spin lock, which may
eventually lead to a soft lockup.
This patch simply adds a workaround, a cond_resched() call in the loop
if applicable. A better solution would be to move the event processor
into a work, but let's put a duct-tape quickly at first.
Reported-and-tested-by: Dae R. Jeong <threeearcat@gmail.com>
Reported-by: syzbot+e4c8abb920efa77bace9@syzkaller.appspotmail.com
Cc: <stable@vger.kernel.org>
Signed-off-by: Takashi Iwai <tiwai@suse.de>
---
sound/core/seq/seq_virmidi.c | 10 ++++++++++
1 file changed, 10 insertions(+)
diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
index 289ae6bb81d9..8ebbca554e99 100644
--- a/sound/core/seq/seq_virmidi.c
+++ b/sound/core/seq/seq_virmidi.c
@@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
int count, res;
unsigned char buf[32], *pbuf;
unsigned long flags;
+ bool check_resched = !in_atomic();
if (up) {
vmidi->trigger = 1;
@@ -200,6 +201,15 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
}
}
+ if (!check_resched)
+ continue;
+ /* do temporary unlock & cond_resched() for avoiding
+ * CPU soft lockup, which may happen via a write from
+ * a huge rawmidi buffer
+ */
+ spin_unlock_irqrestore(&substream->runtime->lock, flags);
+ cond_resched();
+ spin_lock_irqsave(&substream->runtime->lock, flags);
}
out:
spin_unlock_irqrestore(&substream->runtime->lock, flags);
--
2.18.0
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-27 5:20 ` Takashi Iwai
@ 2018-07-27 5:51 ` Dae R. Jeong
2018-07-27 7:02 ` Takashi Iwai
0 siblings, 1 reply; 11+ messages in thread
From: Dae R. Jeong @ 2018-07-27 5:51 UTC (permalink / raw)
To: Takashi Iwai; +Cc: perex, alsa-devel, kt0755, syzkaller, bammanag, linux-kernel
On Fri, Jul 27, 2018 at 07:20:30AM +0200, Takashi Iwai wrote:
I think there is a mistake on the reported-by tag.
The reported-by tag (e4c8abb920ef...) is for WARNING in port_delete.
I guess the tag below is correct.
Reported-by: syzbot+619d9f40141d826b097e@syzkaller.appspotmail.com
Could you please make sure that the reported-by tag is correct?
By the way, I can't reproduce the crash WARNING in port_delete so
far. I feel sad for saying this..
I really want to reproduce the crash and thus, to help to fix the
crash. If there is any progress on it, I will let you know
immediately.
Best regards,
Dae R. Jeong
> On Fri, 27 Jul 2018 06:13:22 +0200,
> Dae R. Jeong wrote:
> >
> > I tested it and it worked.
> > Thanks a lot!
>
> Good to hear. Below is the final patch with a proper comment (and
> with syzbot reported-by, too) I'm going to queue to sound.git tree.
>
>
> thanks,
>
> Takashi
>
> -- 8< --
>
> From: Takashi Iwai <tiwai@suse.de>
> Subject: [PATCH v2] ALSA: virmidi: Fix too long output trigger loop
>
> The virmidi output trigger tries to parse the all available bytes and
> process sequencer events as much as possible. In a normal situation,
> this is supposed to be relatively short, but a program may give a huge
> buffer and it'll take a long time in a single spin lock, which may
> eventually lead to a soft lockup.
>
> This patch simply adds a workaround, a cond_resched() call in the loop
> if applicable. A better solution would be to move the event processor
> into a work, but let's put a duct-tape quickly at first.
>
> Reported-and-tested-by: Dae R. Jeong <threeearcat@gmail.com>
> Reported-by: syzbot+e4c8abb920efa77bace9@syzkaller.appspotmail.com
> Cc: <stable@vger.kernel.org>
> Signed-off-by: Takashi Iwai <tiwai@suse.de>
> ---
> sound/core/seq/seq_virmidi.c | 10 ++++++++++
> 1 file changed, 10 insertions(+)
>
> diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> index 289ae6bb81d9..8ebbca554e99 100644
> --- a/sound/core/seq/seq_virmidi.c
> +++ b/sound/core/seq/seq_virmidi.c
> @@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> int count, res;
> unsigned char buf[32], *pbuf;
> unsigned long flags;
> + bool check_resched = !in_atomic();
>
> if (up) {
> vmidi->trigger = 1;
> @@ -200,6 +201,15 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
> }
> }
> + if (!check_resched)
> + continue;
> + /* do temporary unlock & cond_resched() for avoiding
> + * CPU soft lockup, which may happen via a write from
> + * a huge rawmidi buffer
> + */
> + spin_unlock_irqrestore(&substream->runtime->lock, flags);
> + cond_resched();
> + spin_lock_irqsave(&substream->runtime->lock, flags);
> }
> out:
> spin_unlock_irqrestore(&substream->runtime->lock, flags);
> --
> 2.18.0
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: BUG: soft lockup in snd_virmidi_output_trigger
2018-07-27 5:51 ` Dae R. Jeong
@ 2018-07-27 7:02 ` Takashi Iwai
0 siblings, 0 replies; 11+ messages in thread
From: Takashi Iwai @ 2018-07-27 7:02 UTC (permalink / raw)
To: Dae R. Jeong; +Cc: perex, alsa-devel, kt0755, syzkaller, bammanag, linux-kernel
On Fri, 27 Jul 2018 07:51:04 +0200,
Dae R. Jeong wrote:
>
> On Fri, Jul 27, 2018 at 07:20:30AM +0200, Takashi Iwai wrote:
>
> I think there is a mistake on the reported-by tag.
> The reported-by tag (e4c8abb920ef...) is for WARNING in port_delete.
> I guess the tag below is correct.
> Reported-by: syzbot+619d9f40141d826b097e@syzkaller.appspotmail.com
> Could you please make sure that the reported-by tag is correct?
Indeed, corrected now. Thanks.
> By the way, I can't reproduce the crash WARNING in port_delete so
> far. I feel sad for saying this..
> I really want to reproduce the crash and thus, to help to fix the
> crash. If there is any progress on it, I will let you know
> immediately.
This looks like a sheer race condition.
Thanks for your help in anyway!
Takashi
>
> Best regards,
> Dae R. Jeong
>
> > On Fri, 27 Jul 2018 06:13:22 +0200,
> > Dae R. Jeong wrote:
> > >
> > > I tested it and it worked.
> > > Thanks a lot!
> >
> > Good to hear. Below is the final patch with a proper comment (and
> > with syzbot reported-by, too) I'm going to queue to sound.git tree.
> >
> >
> > thanks,
> >
> > Takashi
> >
> > -- 8< --
> >
> > From: Takashi Iwai <tiwai@suse.de>
> > Subject: [PATCH v2] ALSA: virmidi: Fix too long output trigger loop
> >
> > The virmidi output trigger tries to parse the all available bytes and
> > process sequencer events as much as possible. In a normal situation,
> > this is supposed to be relatively short, but a program may give a huge
> > buffer and it'll take a long time in a single spin lock, which may
> > eventually lead to a soft lockup.
> >
> > This patch simply adds a workaround, a cond_resched() call in the loop
> > if applicable. A better solution would be to move the event processor
> > into a work, but let's put a duct-tape quickly at first.
> >
> > Reported-and-tested-by: Dae R. Jeong <threeearcat@gmail.com>
> > Reported-by: syzbot+e4c8abb920efa77bace9@syzkaller.appspotmail.com
> > Cc: <stable@vger.kernel.org>
> > Signed-off-by: Takashi Iwai <tiwai@suse.de>
> > ---
> > sound/core/seq/seq_virmidi.c | 10 ++++++++++
> > 1 file changed, 10 insertions(+)
> >
> > diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
> > index 289ae6bb81d9..8ebbca554e99 100644
> > --- a/sound/core/seq/seq_virmidi.c
> > +++ b/sound/core/seq/seq_virmidi.c
> > @@ -163,6 +163,7 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> > int count, res;
> > unsigned char buf[32], *pbuf;
> > unsigned long flags;
> > + bool check_resched = !in_atomic();
> >
> > if (up) {
> > vmidi->trigger = 1;
> > @@ -200,6 +201,15 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
> > vmidi->event.type = SNDRV_SEQ_EVENT_NONE;
> > }
> > }
> > + if (!check_resched)
> > + continue;
> > + /* do temporary unlock & cond_resched() for avoiding
> > + * CPU soft lockup, which may happen via a write from
> > + * a huge rawmidi buffer
> > + */
> > + spin_unlock_irqrestore(&substream->runtime->lock, flags);
> > + cond_resched();
> > + spin_lock_irqsave(&substream->runtime->lock, flags);
> > }
> > out:
> > spin_unlock_irqrestore(&substream->runtime->lock, flags);
> > --
> > 2.18.0
> >
>
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2018-07-27 7:02 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-04-09 5:58 BUG: soft lockup in snd_virmidi_output_trigger syzbot
2018-04-09 13:03 ` Takashi Iwai
2018-04-09 13:52 ` Dmitry Vyukov
2018-07-26 5:53 Dae R. Jeong
2018-07-26 12:50 ` Takashi Iwai
2018-07-26 12:58 ` Dmitry Vyukov
2018-07-26 13:07 ` Takashi Iwai
2018-07-27 4:13 ` Dae R. Jeong
2018-07-27 5:20 ` Takashi Iwai
2018-07-27 5:51 ` Dae R. Jeong
2018-07-27 7:02 ` Takashi Iwai
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).