Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1383124 > unrolled thread

Re: sound: use-after-free in snd_timer_interrupt

Started byDmitry Vyukov <dvyukov@google.com>
First post2016-04-20 10:00 +0200
Last post2016-04-21 10:40 +0200
Articles 5 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: sound: use-after-free in snd_timer_interrupt Dmitry Vyukov <dvyukov@google.com> - 2016-04-20 10:00 +0200
    Re: sound: use-after-free in snd_timer_interrupt Takashi Iwai <tiwai@suse.de> - 2016-04-20 10:10 +0200
      Re: sound: use-after-free in snd_timer_interrupt Takashi Iwai <tiwai@suse.de> - 2016-04-20 12:40 +0200
        Re: sound: use-after-free in snd_timer_interrupt Dmitry Vyukov <dvyukov@google.com> - 2016-04-21 10:20 +0200
          Re: sound: use-after-free in snd_timer_interrupt Takashi Iwai <tiwai@suse.de> - 2016-04-21 10:40 +0200

#1383124 — Re: sound: use-after-free in snd_timer_interrupt

FromDmitry Vyukov <dvyukov@google.com>
Date2016-04-20 10:00 +0200
SubjectRe: sound: use-after-free in snd_timer_interrupt
Message-ID<rpVdg-4bE-5@gated-at.bofh.it>
On Sun, Apr 3, 2016 at 8:33 AM, Takashi Iwai <tiwai@suse.de> wrote:
>> >> It is not easily reproducible. I've hit several times while running
>> >> fuzzer for a week. Here is one of the logs for the record:
>> >> https://gist.githubusercontent.com/dvyukov/c84798ee55721563ecb537c4d51dc9f5/raw/f00b865a85877656f13b41917f7321730f140d35/gistfile1.txt
>> >
>> > There are a few more fixes in sound/core/timer.c since 4.5, and they
>> > possibly already cover this.
>> >
>> > Please let me know if this is still seen on the upcoming 4.6-rc2.
>>
>> Hi Takashi,
>>
>> I've updated fuzzer to 05cf8077e54b20dddb756eaa26f3aeb5c38dd3cf (Apr
>> 1) yesterday. Let's see if it still happens.
>>
>> Out of curiosity, how was the bug found?
>
> Well, I'm not entirely sure whether they really cover.  It's just a
> hope, as these are patches to close some possible races :)
>
> 9984d1b5835ca29fc7025186a891ee7398d21cc7
>     ALSA: timer: Protect the whole snd_timer_close() with open race
> f65e0d299807d8a11812845c972493c3f9a18e10
>     ALSA: timer: Call notifier in the same spinlock
> 4a07083ed613644c96c34a7dd2853dc5d7c70902
>     ALSA: timer: Use mod_timer() for rearming the system timer


Hi Takashi,

I've hit it again on 806fdcce017dc98c4dbf8ed001750a0d7d2bb0af (Apr
14), all 3 commits are already in my tree.

[  343.222218] ------------[ cut here ]------------
[  343.222218] WARNING: CPU: 3 PID: 7040 at kernel/time/hrtimer.c:837
hrtimer_forward+0x26a/0x3e0
[  343.222218] Modules linked in:
[  343.222218] CPU: 3 PID: 7040 Comm: syz-executor Not tainted 4.6.0-rc3+ #349
[  343.222218] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS Bochs 01/01/2011
[  343.229525]  ffffffff87eb25c0 ffff88006d507ce0 ffffffff82c8fabf
ffffffff86abac00
[  343.229525]  fffffbfff0fd64b8 0000000000000000 0000000000000000
ffffffff86abac00
[  343.229525]  ffffffff814cfe1a 0000000000000009 ffff88006d507d28
ffffffff8136639f
[  343.229525] Call Trace:
[  343.229525]  <IRQ>  [<ffffffff82c8fabf>] dump_stack+0x12e/0x18f
[  343.229525]  [<ffffffff814cfe1a>] ? hrtimer_forward+0x26a/0x3e0
[  343.229525]  [<ffffffff8136639f>] __warn+0x19f/0x1e0
[  343.229525]  [<ffffffff813665ac>] warn_slowpath_null+0x2c/0x40
[  343.229525]  [<ffffffff814cfe1a>] hrtimer_forward+0x26a/0x3e0
[  343.229525]  [<ffffffff85382ceb>] snd_hrtimer_callback+0x11b/0x230
[  343.229525]  [<ffffffff814d1091>] __hrtimer_run_queues+0x331/0xe90
[  343.229525]  [<ffffffff85382bd0>] ? snd_hrtimer_close+0xa0/0xa0
[  343.229525]  [<ffffffff814d0d60>] ? enqueue_hrtimer+0x3d0/0x3d0
[  343.229525]  [<ffffffff814d3a62>] hrtimer_interrupt+0x182/0x430
[  343.229525]  [<ffffffff8125aa52>] local_apic_timer_interrupt+0x72/0xe0
[  343.229525]  [<ffffffff867bec99>] smp_apic_timer_interrupt+0x79/0xa0
[  343.229525]  [<ffffffff867bcfec>] apic_timer_interrupt+0x8c/0xa0
[  343.229525]  <EOI>  [<ffffffff813e2e00>] ? ___might_sleep+0x3a0/0x3a0
[  343.229525]  [<ffffffff81710fbf>] ? __might_fault+0xaf/0x1d0
[  343.229525]  [<ffffffff814d4f4d>] SyS_nanosleep+0x6d/0x100
[  343.229525]  [<ffffffff814d4ee0>] ? hrtimer_nanosleep+0x730/0x730
[  343.229525]  [<ffffffff81007b53>] ? syscall_trace_enter_phase2+0x143/0x740
[  343.229525]  [<ffffffff81008758>] ? do_syscall_64+0x48/0x640
[  343.229525]  [<ffffffff8100821b>] ? syscall_trace_enter+0xcb/0xf0
[  343.229525]  [<ffffffff814d4ee0>] ? hrtimer_nanosleep+0x730/0x730
[  343.229525]  [<ffffffff810088ef>] do_syscall_64+0x1df/0x640
[  343.229525]  [<ffffffff8100501b>] ? trace_hardirqs_on_thunk+0x1b/0x1d
[  343.229525]  [<ffffffff867bc443>] entry_SYSCALL64_slow_path+0x25/0x25
[  343.229525] ---[ end trace f4fa4ed5ea230466 ]---


For the record, here is syzkaller log:
https://gist.githubusercontent.com/dvyukov/4c31022a284421020029c877561a99ed/raw/649ebe7c882d9b4611a311f279055b272bd5443b/gistfile1.txt

[toc] | [next] | [standalone]

#1383144

FromTakashi Iwai <tiwai@suse.de>
Date2016-04-20 10:10 +0200
Message-ID<rpVmW-4Cl-23@gated-at.bofh.it>
In reply to#1383124
On Wed, 20 Apr 2016 09:56:04 +0200,
Dmitry Vyukov wrote:
> 
> On Sun, Apr 3, 2016 at 8:33 AM, Takashi Iwai <tiwai@suse.de> wrote:
> >> >> It is not easily reproducible. I've hit several times while running
> >> >> fuzzer for a week. Here is one of the logs for the record:
> >> >> https://gist.githubusercontent.com/dvyukov/c84798ee55721563ecb537c4d51dc9f5/raw/f00b865a85877656f13b41917f7321730f140d35/gistfile1.txt
> >> >
> >> > There are a few more fixes in sound/core/timer.c since 4.5, and they
> >> > possibly already cover this.
> >> >
> >> > Please let me know if this is still seen on the upcoming 4.6-rc2.
> >>
> >> Hi Takashi,
> >>
> >> I've updated fuzzer to 05cf8077e54b20dddb756eaa26f3aeb5c38dd3cf (Apr
> >> 1) yesterday. Let's see if it still happens.
> >>
> >> Out of curiosity, how was the bug found?
> >
> > Well, I'm not entirely sure whether they really cover.  It's just a
> > hope, as these are patches to close some possible races :)
> >
> > 9984d1b5835ca29fc7025186a891ee7398d21cc7
> >     ALSA: timer: Protect the whole snd_timer_close() with open race
> > f65e0d299807d8a11812845c972493c3f9a18e10
> >     ALSA: timer: Call notifier in the same spinlock
> > 4a07083ed613644c96c34a7dd2853dc5d7c70902
> >     ALSA: timer: Use mod_timer() for rearming the system timer
> 
> 
> Hi Takashi,
> 
> I've hit it again on 806fdcce017dc98c4dbf8ed001750a0d7d2bb0af (Apr
> 14), all 3 commits are already in my tree.
> 
> [  343.222218] ------------[ cut here ]------------
> [  343.222218] WARNING: CPU: 3 PID: 7040 at kernel/time/hrtimer.c:837
> hrtimer_forward+0x26a/0x3e0

This is a different warning.  The previous was use-after-free, and
this is a warning about re-arming the queued hrtimer.
Maybe there is a slightly remaining race about hrtimer_start() and the
interrupt handler in snd-hrtimer.


thanks,

Takashi

> [  343.222218] Modules linked in:
> [  343.222218] CPU: 3 PID: 7040 Comm: syz-executor Not tainted 4.6.0-rc3+ #349
> [  343.222218] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS Bochs 01/01/2011
> [  343.229525]  ffffffff87eb25c0 ffff88006d507ce0 ffffffff82c8fabf
> ffffffff86abac00
> [  343.229525]  fffffbfff0fd64b8 0000000000000000 0000000000000000
> ffffffff86abac00
> [  343.229525]  ffffffff814cfe1a 0000000000000009 ffff88006d507d28
> ffffffff8136639f
> [  343.229525] Call Trace:
> [  343.229525]  <IRQ>  [<ffffffff82c8fabf>] dump_stack+0x12e/0x18f
> [  343.229525]  [<ffffffff814cfe1a>] ? hrtimer_forward+0x26a/0x3e0
> [  343.229525]  [<ffffffff8136639f>] __warn+0x19f/0x1e0
> [  343.229525]  [<ffffffff813665ac>] warn_slowpath_null+0x2c/0x40
> [  343.229525]  [<ffffffff814cfe1a>] hrtimer_forward+0x26a/0x3e0
> [  343.229525]  [<ffffffff85382ceb>] snd_hrtimer_callback+0x11b/0x230
> [  343.229525]  [<ffffffff814d1091>] __hrtimer_run_queues+0x331/0xe90
> [  343.229525]  [<ffffffff85382bd0>] ? snd_hrtimer_close+0xa0/0xa0
> [  343.229525]  [<ffffffff814d0d60>] ? enqueue_hrtimer+0x3d0/0x3d0
> [  343.229525]  [<ffffffff814d3a62>] hrtimer_interrupt+0x182/0x430
> [  343.229525]  [<ffffffff8125aa52>] local_apic_timer_interrupt+0x72/0xe0
> [  343.229525]  [<ffffffff867bec99>] smp_apic_timer_interrupt+0x79/0xa0
> [  343.229525]  [<ffffffff867bcfec>] apic_timer_interrupt+0x8c/0xa0
> [  343.229525]  <EOI>  [<ffffffff813e2e00>] ? ___might_sleep+0x3a0/0x3a0
> [  343.229525]  [<ffffffff81710fbf>] ? __might_fault+0xaf/0x1d0
> [  343.229525]  [<ffffffff814d4f4d>] SyS_nanosleep+0x6d/0x100
> [  343.229525]  [<ffffffff814d4ee0>] ? hrtimer_nanosleep+0x730/0x730
> [  343.229525]  [<ffffffff81007b53>] ? syscall_trace_enter_phase2+0x143/0x740
> [  343.229525]  [<ffffffff81008758>] ? do_syscall_64+0x48/0x640
> [  343.229525]  [<ffffffff8100821b>] ? syscall_trace_enter+0xcb/0xf0
> [  343.229525]  [<ffffffff814d4ee0>] ? hrtimer_nanosleep+0x730/0x730
> [  343.229525]  [<ffffffff810088ef>] do_syscall_64+0x1df/0x640
> [  343.229525]  [<ffffffff8100501b>] ? trace_hardirqs_on_thunk+0x1b/0x1d
> [  343.229525]  [<ffffffff867bc443>] entry_SYSCALL64_slow_path+0x25/0x25
> [  343.229525] ---[ end trace f4fa4ed5ea230466 ]---
> 
> 
> For the record, here is syzkaller log:
> https://gist.githubusercontent.com/dvyukov/4c31022a284421020029c877561a99ed/raw/649ebe7c882d9b4611a311f279055b272bd5443b/gistfile1.txt
>

[toc] | [prev] | [next] | [standalone]

#1383248

FromTakashi Iwai <tiwai@suse.de>
Date2016-04-20 12:40 +0200
Message-ID<rpXI6-6qG-3@gated-at.bofh.it>
In reply to#1383144

[Multipart message — attachments visible in raw view] — view raw

On Wed, 20 Apr 2016 10:08:55 +0200,
Takashi Iwai wrote:
> 
> On Wed, 20 Apr 2016 09:56:04 +0200,
> Dmitry Vyukov wrote:
> > 
> > On Sun, Apr 3, 2016 at 8:33 AM, Takashi Iwai <tiwai@suse.de> wrote:
> > >> >> It is not easily reproducible. I've hit several times while running
> > >> >> fuzzer for a week. Here is one of the logs for the record:
> > >> >> https://gist.githubusercontent.com/dvyukov/c84798ee55721563ecb537c4d51dc9f5/raw/f00b865a85877656f13b41917f7321730f140d35/gistfile1.txt
> > >> >
> > >> > There are a few more fixes in sound/core/timer.c since 4.5, and they
> > >> > possibly already cover this.
> > >> >
> > >> > Please let me know if this is still seen on the upcoming 4.6-rc2.
> > >>
> > >> Hi Takashi,
> > >>
> > >> I've updated fuzzer to 05cf8077e54b20dddb756eaa26f3aeb5c38dd3cf (Apr
> > >> 1) yesterday. Let's see if it still happens.
> > >>
> > >> Out of curiosity, how was the bug found?
> > >
> > > Well, I'm not entirely sure whether they really cover.  It's just a
> > > hope, as these are patches to close some possible races :)
> > >
> > > 9984d1b5835ca29fc7025186a891ee7398d21cc7
> > >     ALSA: timer: Protect the whole snd_timer_close() with open race
> > > f65e0d299807d8a11812845c972493c3f9a18e10
> > >     ALSA: timer: Call notifier in the same spinlock
> > > 4a07083ed613644c96c34a7dd2853dc5d7c70902
> > >     ALSA: timer: Use mod_timer() for rearming the system timer
> > 
> > 
> > Hi Takashi,
> > 
> > I've hit it again on 806fdcce017dc98c4dbf8ed001750a0d7d2bb0af (Apr
> > 14), all 3 commits are already in my tree.
> > 
> > [  343.222218] ------------[ cut here ]------------
> > [  343.222218] WARNING: CPU: 3 PID: 7040 at kernel/time/hrtimer.c:837
> > hrtimer_forward+0x26a/0x3e0
> 
> This is a different warning.  The previous was use-after-free, and
> this is a warning about re-arming the queued hrtimer.
> Maybe there is a slightly remaining race about hrtimer_start() and the
> interrupt handler in snd-hrtimer.

Could you check whether two patches below help anything?
This should harden against the race between hrtimer callback and
another start/stop calls.


Takashi

[toc] | [prev] | [next] | [standalone]

#1383923

FromDmitry Vyukov <dvyukov@google.com>
Date2016-04-21 10:20 +0200
Message-ID<rqi09-65V-5@gated-at.bofh.it>
In reply to#1383248
On Wed, Apr 20, 2016 at 12:31 PM, Takashi Iwai <tiwai@suse.de> wrote:
> On Wed, 20 Apr 2016 10:08:55 +0200,
> Takashi Iwai wrote:
>>
>> On Wed, 20 Apr 2016 09:56:04 +0200,
>> Dmitry Vyukov wrote:
>> >
>> > On Sun, Apr 3, 2016 at 8:33 AM, Takashi Iwai <tiwai@suse.de> wrote:
>> > >> >> It is not easily reproducible. I've hit several times while running
>> > >> >> fuzzer for a week. Here is one of the logs for the record:
>> > >> >> https://gist.githubusercontent.com/dvyukov/c84798ee55721563ecb537c4d51dc9f5/raw/f00b865a85877656f13b41917f7321730f140d35/gistfile1.txt
>> > >> >
>> > >> > There are a few more fixes in sound/core/timer.c since 4.5, and they
>> > >> > possibly already cover this.
>> > >> >
>> > >> > Please let me know if this is still seen on the upcoming 4.6-rc2.
>> > >>
>> > >> Hi Takashi,
>> > >>
>> > >> I've updated fuzzer to 05cf8077e54b20dddb756eaa26f3aeb5c38dd3cf (Apr
>> > >> 1) yesterday. Let's see if it still happens.
>> > >>
>> > >> Out of curiosity, how was the bug found?
>> > >
>> > > Well, I'm not entirely sure whether they really cover.  It's just a
>> > > hope, as these are patches to close some possible races :)
>> > >
>> > > 9984d1b5835ca29fc7025186a891ee7398d21cc7
>> > >     ALSA: timer: Protect the whole snd_timer_close() with open race
>> > > f65e0d299807d8a11812845c972493c3f9a18e10
>> > >     ALSA: timer: Call notifier in the same spinlock
>> > > 4a07083ed613644c96c34a7dd2853dc5d7c70902
>> > >     ALSA: timer: Use mod_timer() for rearming the system timer
>> >
>> >
>> > Hi Takashi,
>> >
>> > I've hit it again on 806fdcce017dc98c4dbf8ed001750a0d7d2bb0af (Apr
>> > 14), all 3 commits are already in my tree.
>> >
>> > [  343.222218] ------------[ cut here ]------------
>> > [  343.222218] WARNING: CPU: 3 PID: 7040 at kernel/time/hrtimer.c:837
>> > hrtimer_forward+0x26a/0x3e0
>>
>> This is a different warning.  The previous was use-after-free, and
>> this is a warning about re-arming the queued hrtimer.
>> Maybe there is a slightly remaining race about hrtimer_start() and the
>> interrupt handler in snd-hrtimer.
>
> Could you check whether two patches below help anything?
> This should harden against the race between hrtimer callback and
> another start/stop calls.

I don't have a reliable way to reproduce it. I've tried to replay the
logs for hours, but no success. And I've hit it only three times:

-rw-r----- 1 346004 Apr 19 02:36 crash-qemu-23-1461026201572599961
-rw-r----- 1 393438 Mar 27 08:24 crash-qemu-8-1459059850150353721
-rw-r----- 1 393439 Mar 10 19:44 crash-qemu-16-1457635446972474955

I will merge the patches and restart the fuzzer. It will be difficult
to conclude whether it fixes the bug or not, but at least it will test
the patches.

[toc] | [prev] | [next] | [standalone]

#1383932

FromTakashi Iwai <tiwai@suse.de>
Date2016-04-21 10:40 +0200
Message-ID<rqijw-6dW-13@gated-at.bofh.it>
In reply to#1383923
On Thu, 21 Apr 2016 10:14:10 +0200,
Dmitry Vyukov wrote:
> 
> On Wed, Apr 20, 2016 at 12:31 PM, Takashi Iwai <tiwai@suse.de> wrote:
> > On Wed, 20 Apr 2016 10:08:55 +0200,
> > Takashi Iwai wrote:
> >>
> >> On Wed, 20 Apr 2016 09:56:04 +0200,
> >> Dmitry Vyukov wrote:
> >> >
> >> > On Sun, Apr 3, 2016 at 8:33 AM, Takashi Iwai <tiwai@suse.de> wrote:
> >> > >> >> It is not easily reproducible. I've hit several times while running
> >> > >> >> fuzzer for a week. Here is one of the logs for the record:
> >> > >> >> https://gist.githubusercontent.com/dvyukov/c84798ee55721563ecb537c4d51dc9f5/raw/f00b865a85877656f13b41917f7321730f140d35/gistfile1.txt
> >> > >> >
> >> > >> > There are a few more fixes in sound/core/timer.c since 4.5, and they
> >> > >> > possibly already cover this.
> >> > >> >
> >> > >> > Please let me know if this is still seen on the upcoming 4.6-rc2.
> >> > >>
> >> > >> Hi Takashi,
> >> > >>
> >> > >> I've updated fuzzer to 05cf8077e54b20dddb756eaa26f3aeb5c38dd3cf (Apr
> >> > >> 1) yesterday. Let's see if it still happens.
> >> > >>
> >> > >> Out of curiosity, how was the bug found?
> >> > >
> >> > > Well, I'm not entirely sure whether they really cover.  It's just a
> >> > > hope, as these are patches to close some possible races :)
> >> > >
> >> > > 9984d1b5835ca29fc7025186a891ee7398d21cc7
> >> > >     ALSA: timer: Protect the whole snd_timer_close() with open race
> >> > > f65e0d299807d8a11812845c972493c3f9a18e10
> >> > >     ALSA: timer: Call notifier in the same spinlock
> >> > > 4a07083ed613644c96c34a7dd2853dc5d7c70902
> >> > >     ALSA: timer: Use mod_timer() for rearming the system timer
> >> >
> >> >
> >> > Hi Takashi,
> >> >
> >> > I've hit it again on 806fdcce017dc98c4dbf8ed001750a0d7d2bb0af (Apr
> >> > 14), all 3 commits are already in my tree.
> >> >
> >> > [  343.222218] ------------[ cut here ]------------
> >> > [  343.222218] WARNING: CPU: 3 PID: 7040 at kernel/time/hrtimer.c:837
> >> > hrtimer_forward+0x26a/0x3e0
> >>
> >> This is a different warning.  The previous was use-after-free, and
> >> this is a warning about re-arming the queued hrtimer.
> >> Maybe there is a slightly remaining race about hrtimer_start() and the
> >> interrupt handler in snd-hrtimer.
> >
> > Could you check whether two patches below help anything?
> > This should harden against the race between hrtimer callback and
> > another start/stop calls.
> 
> I don't have a reliable way to reproduce it. I've tried to replay the
> logs for hours, but no success. And I've hit it only three times:
> 
> -rw-r----- 1 346004 Apr 19 02:36 crash-qemu-23-1461026201572599961
> -rw-r----- 1 393438 Mar 27 08:24 crash-qemu-8-1459059850150353721
> -rw-r----- 1 393439 Mar 10 19:44 crash-qemu-16-1457635446972474955
> 
> I will merge the patches and restart the fuzzer. It will be difficult
> to conclude whether it fixes the bug or not, but at least it will test
> the patches.

Thanks!  I'll test the patches for a while and merge for 4.7 if no
regression is found, too.


Takashi

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web