[alsa-devel] BUG: soft lockup in snd_virmidi_output_trigger
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=642c927972318775e0ea1b4779ccd8624ce9e6f...) 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).
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=642c927972318775e0ea1b4779ccd8624ce9e6f...) 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);
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=642c927972318775e0ea1b4779ccd8624ce9e6f...) 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.
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=642c927972318775e0ea1b4779ccd8624ce9e6f...) 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
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=642c927972318775e0ea1b4779ccd8624ce9e6f...) 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);-- 2.18.0
I tested it and it worked. Thanks a lot!
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);
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);-- 2.18.0
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);-- 2.18.0
participants (3)
-
Dae R. Jeong -
Dmitry Vyukov -
Takashi Iwai