WARNING in set_restore_sigmask

WARNING in set_restore_sigmask

[Dmitry Vyukov]

Hello,

I've got the following WARNING while running syzkaller fuzzer:

------------[ cut here ]------------
WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
sigsuspend+0x18e/0x1f0()
Modules linked in:
CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
 ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
 ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
 [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
 [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
 [<     inline     >] set_restore_sigmask
./arch/x86/include/asm/thread_info.h:236
 [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
 [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
 [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
 [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185
---[ end trace da5c27e3b7defd96 ]---

Unfortunately I cannot reproduce it. But the only two programs that
contain rt_sigsuspend that were executed before the warning are:
https://gist.githubusercontent.com/dvyukov/cacf219b67de2aa08733/raw/de22347ab1ebd0c90dc7f8af9b348ba143b7ba6c/gistfile1.txt
https://gist.githubusercontent.com/dvyukov/2b419fac83636e7ba0e3/raw/0b32b477180f385d6430b2186f1e474c3bb5a829/gistfile1.txt
Note that most syscalls there are redherring, because I don't have
/dev/audio7 nor /dev/fd5. So ioctls are fail, and shmget also fails.
These programs call exit(0) and can SIGSEGV concurrently, though.

I am on commit 92e963f50fc74041b5e9e744c330dca48e04f08d

Re: WARNING in set_restore_sigmask

[Dmitry Vyukov]

On Fri, Jan 29, 2016 at 10:16 AM, Dmitry Vyukov <dvyukov@google.com> wrote:
> Hello,
>
> I've got the following WARNING while running syzkaller fuzzer:
>
> ------------[ cut here ]------------
> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
> sigsuspend+0x18e/0x1f0()
> Modules linked in:
> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
> Call Trace:
>  [<     inline     >] __dump_stack lib/dump_stack.c:15
>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
>  [<     inline     >] set_restore_sigmask
> ./arch/x86/include/asm/thread_info.h:236
>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
>  [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
>  [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
>  [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
> arch/x86/entry/entry_64.S:185
> ---[ end trace da5c27e3b7defd96 ]---
>
> Unfortunately I cannot reproduce it. But the only two programs that
> contain rt_sigsuspend that were executed before the warning are:
> https://gist.githubusercontent.com/dvyukov/cacf219b67de2aa08733/raw/de22347ab1ebd0c90dc7f8af9b348ba143b7ba6c/gistfile1.txt
> https://gist.githubusercontent.com/dvyukov/2b419fac83636e7ba0e3/raw/0b32b477180f385d6430b2186f1e474c3bb5a829/gistfile1.txt
> Note that most syscalls there are redherring, because I don't have
> /dev/audio7 nor /dev/fd5. So ioctls are fail, and shmget also fails.
> These programs call exit(0) and can SIGSEGV concurrently, though.
>
> I am on commit 92e963f50fc74041b5e9e744c330dca48e04f08d

+syzkaller group

Re: WARNING in set_restore_sigmask

[Thomas Gleixner]

Dmitry,

On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
> sigsuspend+0x18e/0x1f0()
> Modules linked in:
> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
> Call Trace:
>  [<     inline     >] __dump_stack lib/dump_stack.c:15
>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
>  [<     inline     >] set_restore_sigmask
> ./arch/x86/include/asm/thread_info.h:236
>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
>  [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
>  [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
>  [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
> arch/x86/entry/entry_64.S:185
> ---[ end trace da5c27e3b7defd96 ]---

That could be just a spurious wakeup of unknown provenience. The sigsuspend
code has no protection against those. I can't see why that happens ...

> Unfortunately I cannot reproduce it. But the only two programs that

I would be helpful if you could run your fuzzers with a minimal set of trace
points enabled (raw_syscalls, sched events) and set
/proc/sys/kernel/traceoff_on_warning to 1, so the trace freezes when a warning
is triggered.

That might give us at least some insight into these one off issues.

Thanks,

	tglx

Re: WARNING in set_restore_sigmask

[Dmitry Vyukov]

On Fri, Jan 29, 2016 at 12:53 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> Dmitry,
>
> On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
>> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
>> sigsuspend+0x18e/0x1f0()
>> Modules linked in:
>> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
>>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
>>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
>> Call Trace:
>>  [<     inline     >] __dump_stack lib/dump_stack.c:15
>>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
>>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
>>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
>>  [<     inline     >] set_restore_sigmask
>> ./arch/x86/include/asm/thread_info.h:236
>>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
>>  [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
>>  [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
>>  [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
>> arch/x86/entry/entry_64.S:185
>> ---[ end trace da5c27e3b7defd96 ]---
>
> That could be just a spurious wakeup of unknown provenience. The sigsuspend
> code has no protection against those. I can't see why that happens ...

You mean that you _see_ why this warning happens?

>
>> Unfortunately I cannot reproduce it. But the only two programs that
>
> I would be helpful if you could run your fuzzers with a minimal set of trace
> points enabled (raw_syscalls, sched events) and set
> /proc/sys/kernel/traceoff_on_warning to 1, so the trace freezes when a warning
> is triggered.
>
> That might give us at least some insight into these one off issues.

Can you please give more concrete instructions? I never used
tracepoints. What configs do I need to enable? What runtime setup? etc

Re: WARNING in set_restore_sigmask

[Thomas Gleixner]

On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
> On Fri, Jan 29, 2016 at 12:53 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> > Dmitry,
> >
> > On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
> >> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
> >> sigsuspend+0x18e/0x1f0()
> >> Modules linked in:
> >> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
> >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> >>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
> >>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
> >>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
> >> Call Trace:
> >>  [<     inline     >] __dump_stack lib/dump_stack.c:15
> >>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
> >>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
> >>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
> >>  [<     inline     >] set_restore_sigmask
> >> ./arch/x86/include/asm/thread_info.h:236
> >>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
> >>  [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
> >>  [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
> >>  [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
> >> arch/x86/entry/entry_64.S:185
> >> ---[ end trace da5c27e3b7defd96 ]---
> >
> > That could be just a spurious wakeup of unknown provenience. The sigsuspend
> > code has no protection against those. I can't see why that happens ...
> 
> You mean that you _see_ why this warning happens?

It happens when a spurious wakeup occurs, but I don't see how that happens in
your fuzzing apps.

> >
> >> Unfortunately I cannot reproduce it. But the only two programs that
> >
> > I would be helpful if you could run your fuzzers with a minimal set of trace
> > points enabled (raw_syscalls, sched events) and set
> > /proc/sys/kernel/traceoff_on_warning to 1, so the trace freezes when a warning
> > is triggered.
> >
> > That might give us at least some insight into these one off issues.
> 
> Can you please give more concrete instructions? I never used
> tracepoints. What configs do I need to enable? What runtime setup? etc

CONFIG_FTRACE=y

Then after booting:

mount debugfs if not mounted already

# mount -t debugfs debugfs /sys/kernel/debug

# echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/enable
# echo 1 > /proc/sys/kernel/traceoff_on_warning

That freezes the trace when a warning/bug is hit. You can then retrieve the
trace via:

# cat /sys/kernel/debug/tracing/trace

You can also do

# echo 1 > /proc/sys/kernel/ftrace_dump_on_oops

which will spill out the trace buffer over serial console. That's useful if
your kernel crashes completely. But be aware that it might take quite some
time ....

Thanks,

	tglx

Re: WARNING in set_restore_sigmask

[Dmitry Vyukov]

On Fri, Jan 29, 2016 at 2:57 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
>> On Fri, Jan 29, 2016 at 12:53 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
>> > Dmitry,
>> >
>> > On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
>> >> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
>> >> sigsuspend+0x18e/0x1f0()
>> >> Modules linked in:
>> >> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
>> >> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>> >>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
>> >>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
>> >>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
>> >> Call Trace:
>> >>  [<     inline     >] __dump_stack lib/dump_stack.c:15
>> >>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
>> >>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
>> >>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
>> >>  [<     inline     >] set_restore_sigmask
>> >> ./arch/x86/include/asm/thread_info.h:236
>> >>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
>> >>  [<     inline     >] SYSC_rt_sigsuspend kernel/signal.c:3533
>> >>  [<ffffffff81387d7c>] SyS_rt_sigsuspend+0xac/0xe0 kernel/signal.c:3523
>> >>  [<ffffffff86653236>] entry_SYSCALL_64_fastpath+0x16/0x7a
>> >> arch/x86/entry/entry_64.S:185
>> >> ---[ end trace da5c27e3b7defd96 ]---
>> >
>> > That could be just a spurious wakeup of unknown provenience. The sigsuspend
>> > code has no protection against those. I can't see why that happens ...
>>
>> You mean that you _see_ why this warning happens?
>
> It happens when a spurious wakeup occurs, but I don't see how that happens in
> your fuzzing apps.
>
>> >
>> >> Unfortunately I cannot reproduce it. But the only two programs that
>> >
>> > I would be helpful if you could run your fuzzers with a minimal set of trace
>> > points enabled (raw_syscalls, sched events) and set
>> > /proc/sys/kernel/traceoff_on_warning to 1, so the trace freezes when a warning
>> > is triggered.
>> >
>> > That might give us at least some insight into these one off issues.
>>
>> Can you please give more concrete instructions? I never used
>> tracepoints. What configs do I need to enable? What runtime setup? etc
>
> CONFIG_FTRACE=y
>
> Then after booting:
>
> mount debugfs if not mounted already
>
> # mount -t debugfs debugfs /sys/kernel/debug
>
> # echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
> # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
> # echo 1 > /proc/sys/kernel/traceoff_on_warning
>
> That freezes the trace when a warning/bug is hit. You can then retrieve the
> trace via:
>
> # cat /sys/kernel/debug/tracing/trace
>
> You can also do
>
> # echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
>
> which will spill out the trace buffer over serial console. That's useful if
> your kernel crashes completely. But be aware that it might take quite some
> time ....

I need something that will work without supervision. I need to use
/proc/sys/kernel/ftrace_dump_on_oops instead of
/proc/sys/kernel/traceoff_on_warning then, right?

Quite some time? Does it dump trace from boot? In my setup kernel can
work up to an hour under super heavy parallel workload... Need to
check how it will cope with it.

Re: WARNING in set_restore_sigmask

[Thomas Gleixner]

On Fri, 29 Jan 2016, Dmitry Vyukov wrote:
> On Fri, Jan 29, 2016 at 2:57 PM, Thomas Gleixner <tglx@linutronix.de> wrote:
> I need something that will work without supervision. I need to use
> /proc/sys/kernel/ftrace_dump_on_oops instead of
> /proc/sys/kernel/traceoff_on_warning then, right?
> 
> Quite some time? Does it dump trace from boot? In my setup kernel can
> work up to an hour under super heavy parallel workload... Need to
> check how it will cope with it.

The time depends on the serial speed and the trace buffer size and the number
of cpus. Don't worry about the uptime. The buffer is a ringbuffer with limited
capacity, so the dump time is constant.

If you want that /proc/sys/kernel/ftrace_dump_on_oops spills out on warnings
as well, you need to enable

/proc/sys/kernel/traceoff_on_warning
/proc/sys/kernel/ftrace_dump_on_oops

and 

/proc/sys/kernel/panic_on_warn

because we do not dump on warnings.

Thanks,

	tglx

Re: WARNING in set_restore_sigmask

[Oleg Nesterov]

On 01/29, Dmitry Vyukov wrote:
>
> Hello,
>
> I've got the following WARNING while running syzkaller fuzzer:
>
> ------------[ cut here ]------------
> WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
> sigsuspend+0x18e/0x1f0()
> Modules linked in:
> CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
>  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
>  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
>  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
> Call Trace:
>  [<     inline     >] __dump_stack lib/dump_stack.c:15
>  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
>  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
>  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
>  [<     inline     >] set_restore_sigmask
> ./arch/x86/include/asm/thread_info.h:236
>  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513

See http://marc.info/?t=145373722000004 the patch is already in -mm tree.

Oleg.

Re: WARNING in set_restore_sigmask

[Thomas Gleixner]

On Fri, 29 Jan 2016, Oleg Nesterov wrote:
> >  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
> 
> See http://marc.info/?t=145373722000004 the patch is already in -mm tree.

Nice! So my analysis was not that far off.

Thanks,

	tglx

Re: WARNING in set_restore_sigmask

[Steven Rostedt]

On Fri, 29 Jan 2016 15:10:18 +0100 (CET)
Thomas Gleixner <tglx@linutronix.de> wrote:


> The time depends on the serial speed and the trace buffer size and the number
> of cpus. Don't worry about the uptime. The buffer is a ringbuffer with limited
> capacity, so the dump time is constant.
> 
> If you want that /proc/sys/kernel/ftrace_dump_on_oops spills out on warnings
> as well, you need to enable
> 
> /proc/sys/kernel/traceoff_on_warning
> /proc/sys/kernel/ftrace_dump_on_oops
> 
> and 
> 
> /proc/sys/kernel/panic_on_warn
> 
> because we do not dump on warnings.

To save time in the wait, you may also want to do:

# echo 50 > /sys/kernel/debug/tracing/buffer_size_kb

which will make each per cpu buffer 50 kb, instead of the default of a
meg each. That will cut down the time to spit out the ftrace buffer to
serial console, but it wont have as much data. 50 kb should be enough
to trace back to the problem point though.

-- Steve

Re: WARNING in set_restore_sigmask

[Andrew Morton]

On Fri, 29 Jan 2016 15:13:47 +0100 Oleg Nesterov <oleg@redhat.com> wrote:

> On 01/29, Dmitry Vyukov wrote:
> >
> > Hello,
> >
> > I've got the following WARNING while running syzkaller fuzzer:
> >
> > ------------[ cut here ]------------
> > WARNING: CPU: 2 PID: 10905 at ./arch/x86/include/asm/thread_info.h:236
> > sigsuspend+0x18e/0x1f0()
> > Modules linked in:
> > CPU: 2 PID: 10905 Comm: syz-executor Not tainted 4.5.0-rc1+ #300
> > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> >  00000000ffffffff ffff88006139fe38 ffffffff82be118d 0000000000000000
> >  ffff88006d054740 ffffffff867387e0 ffff88006139fe78 ffffffff813536d9
> >  ffffffff813839ce ffffffff867387e0 00000000000000ec 0000000020000000
> > Call Trace:
> >  [<     inline     >] __dump_stack lib/dump_stack.c:15
> >  [<ffffffff82be118d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
> >  [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
> >  [<ffffffff81353909>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
> >  [<     inline     >] set_restore_sigmask
> > ./arch/x86/include/asm/thread_info.h:236
> >  [<ffffffff813839ce>] sigsuspend+0x18e/0x1f0 kernel/signal.c:3513
> 
> See http://marc.info/?t=145373722000004 the patch is already in -mm tree.

I'll get this into 4.5 as we now appear to have some code which actually
triggers it.

I wonder where that wakeup is coming from.