perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Vince Weaver]

The fuzzer triggered another warning in the PERF_EVENT_IOC_SET_FILTER 
code.  This is with the previous filter patch applied.

>From what I can tell the filter was:
nfs4:nfs4_fsinfo 
(((fhandle~601)&&valid&809)&&common_type>=860) 

The warning in question:
	WARN_ON_ONCE(cnt < 0);
in check_preds().

[65903.660154] WARNING: CPU: 1 PID: 731 at kernel/trace/trace_events_filter.c:1388 replace_preds+0x2e4/0xa50()
[65903.748080] CPU: 1 PID: 731 Comm: perf_fuzzer Tainted: G        W       4.1.0-rc8+ #157
[65903.757203] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[65903.765711]  ffffffff81a1ac00 ffff880117117cb8 ffffffff816d7419 0000000000000000
[65903.774323]  0000000000000000 ffff880117117cf8 ffffffff81072eba 0000000000000005
[65903.782924]  0000000000000003 ffff8800366bd018 ffff8800366bd000 ffff8800cf3e9220
[65903.791516] Call Trace:
[65903.794688]  [<ffffffff816d7419>] dump_stack+0x45/0x57
[65903.800732]  [<ffffffff81072eba>] warn_slowpath_common+0x8a/0xc0
[65903.807712]  [<ffffffff81072faa>] warn_slowpath_null+0x1a/0x20
[65903.814477]  [<ffffffff8114b1c4>] replace_preds+0x2e4/0xa50
[65903.820974]  [<ffffffff8114c2c3>] ? ftrace_profile_set_filter+0x23/0x100
[65903.828640]  [<ffffffff8114b9b2>] create_filter+0x82/0xb0
[65903.834917]  [<ffffffff8114c2f4>] ftrace_profile_set_filter+0x54/0x100
[65903.842436]  [<ffffffff811909eb>] ? strndup_user+0x4b/0xc0
[65903.848794]  [<ffffffff81166290>] perf_ioctl+0x170/0x4d0
[65903.854959]  [<ffffffff812023d0>] do_vfs_ioctl+0x2e0/0x4e0
[65903.861286]  [<ffffffff816dcdfe>] ? mutex_unlock+0xe/0x10
[65903.867492]  [<ffffffff81164756>] ? perf_event_task_enable+0xb6/0xd0
[65903.874754]  [<ffffffff81202651>] SyS_ioctl+0x81/0xa0
[65903.880655]  [<ffffffff816df372>] system_call_fastpath+0x16/0x7a
[65903.887534] ---[ end trace 48137d0593a025d9 ]---

Re: perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Steven Rostedt]

On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
Vince Weaver <vincent.weaver@maine.edu> wrote:

> 
> The fuzzer triggered another warning in the PERF_EVENT_IOC_SET_FILTER 
> code.  This is with the previous filter patch applied.
> 
> >From what I can tell the filter was:
> nfs4:nfs4_fsinfo 
> (((fhandle~601)&&valid&809)&&common_type>=860) 

Hmm, I can't trigger this with the filter file, can you?

 echo '(((fhandle~601)&&valid&809)&&common_type>=860)' > \
  /sys/kernel/debug/tracing/events/nfs4/nfs4_fsinfo/filter

I'll write a user app to use the perf syscall and see if that is
different, but in the mean time, can you try the above.

Thanks!

-- Steve

> 
> The warning in question:
> 	WARN_ON_ONCE(cnt < 0);
> in check_preds().
> 
> [65903.660154] WARNING: CPU: 1 PID: 731 at kernel/trace/trace_events_filter.c:1388 replace_preds+0x2e4/0xa50()
> [65903.748080] CPU: 1 PID: 731 Comm: perf_fuzzer Tainted: G        W       4.1.0-rc8+ #157
> [65903.757203] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [65903.765711]  ffffffff81a1ac00 ffff880117117cb8 ffffffff816d7419 0000000000000000
> [65903.774323]  0000000000000000 ffff880117117cf8 ffffffff81072eba 0000000000000005
> [65903.782924]  0000000000000003 ffff8800366bd018 ffff8800366bd000 ffff8800cf3e9220
> [65903.791516] Call Trace:
> [65903.794688]  [<ffffffff816d7419>] dump_stack+0x45/0x57
> [65903.800732]  [<ffffffff81072eba>] warn_slowpath_common+0x8a/0xc0
> [65903.807712]  [<ffffffff81072faa>] warn_slowpath_null+0x1a/0x20
> [65903.814477]  [<ffffffff8114b1c4>] replace_preds+0x2e4/0xa50
> [65903.820974]  [<ffffffff8114c2c3>] ? ftrace_profile_set_filter+0x23/0x100
> [65903.828640]  [<ffffffff8114b9b2>] create_filter+0x82/0xb0
> [65903.834917]  [<ffffffff8114c2f4>] ftrace_profile_set_filter+0x54/0x100
> [65903.842436]  [<ffffffff811909eb>] ? strndup_user+0x4b/0xc0
> [65903.848794]  [<ffffffff81166290>] perf_ioctl+0x170/0x4d0
> [65903.854959]  [<ffffffff812023d0>] do_vfs_ioctl+0x2e0/0x4e0
> [65903.861286]  [<ffffffff816dcdfe>] ? mutex_unlock+0xe/0x10
> [65903.867492]  [<ffffffff81164756>] ? perf_event_task_enable+0xb6/0xd0
> [65903.874754]  [<ffffffff81202651>] SyS_ioctl+0x81/0xa0
> [65903.880655]  [<ffffffff816df372>] system_call_fastpath+0x16/0x7a
> [65903.887534] ---[ end trace 48137d0593a025d9 ]---

Re: perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Vince Weaver]

On Thu, 18 Jun 2015, Steven Rostedt wrote:

> On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
> Vince Weaver <vincent.weaver@maine.edu> wrote:
> 
> > 
> > The fuzzer triggered another warning in the PERF_EVENT_IOC_SET_FILTER 
> > code.  This is with the previous filter patch applied.
> > 
> > >From what I can tell the filter was:
> > nfs4:nfs4_fsinfo 
> > (((fhandle~601)&&valid&809)&&common_type>=860) 
> 
> Hmm, I can't trigger this with the filter file, can you?
> 
>  echo '(((fhandle~601)&&valid&809)&&common_type>=860)' > \
>   /sys/kernel/debug/tracing/events/nfs4/nfs4_fsinfo/filter
> 
> I'll write a user app to use the perf syscall and see if that is
> different, but in the mean time, can you try the above.

I can't seem to replicate this with perf or echo.

Unfortunately I made many changes to the fuzzer since hitting the bug so 
it's a bit hard to replicate with the fuzzer.  I'll keep fuzzing and see 
if I can hit it again.

As an aside, I can't find any documentation of how the "~" glob operator 
works in ftrace filters.  Can you give a quick example of a valid filter 
that uses it?

Thanks,

Vince

Re: perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Steven Rostedt]

On Thu, 18 Jun 2015 17:18:47 -0400 (EDT)
Vince Weaver <vincent.weaver@maine.edu> wrote:


> As an aside, I can't find any documentation of how the "~" glob operator 

Hmm, I need to add documentation then.

> works in ftrace filters.  Can you give a quick example of a valid filter 
> that uses it?

It works with strings...

for sched:sched_switch

    prev_comm ~ "ls*"

-- Steve

Re: perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Vince Weaver]

On Thu, 18 Jun 2015, Steven Rostedt wrote:

> On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
> Vince Weaver <vincent.weaver@maine.edu> wrote:
> 
> > 
> > The fuzzer triggered another warning in the PERF_EVENT_IOC_SET_FILTER 
> > code.  This is with the previous filter patch applied.
> > 
> > >From what I can tell the filter was:
> > nfs4:nfs4_fsinfo 
> > (((fhandle~601)&&valid&809)&&common_type>=860) 
> 
> Hmm, I can't trigger this with the filter file, can you?
> 
>  echo '(((fhandle~601)&&valid&809)&&common_type>=860)' > \
>   /sys/kernel/debug/tracing/events/nfs4/nfs4_fsinfo/filter
> 
> I'll write a user app to use the perf syscall and see if that is
> different, but in the mean time, can you try the above.

OK, fuzzing found another test case, this one I can reproduce using perf:

power:cpu_frequency
filter is (without the quotes)
"                           (                   (                                        ==                                              )                                                                                                      )                                   "

yes I know that filter is a bit rediculous.  Some of those spaces might be 
tabs.  Anyway it leads to:

[13626.276459] WARNING: CPU: 3 PID: 17880 at kernel/trace/trace_events_filter.c:1388 replace_preds+0x2e4/0xa50()
[13626.360782] CPU: 3 PID: 17880 Comm: perf_fuzzer Not tainted 4.1.0-rc8+ #158
[13626.368264] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[13626.376238]  ffffffff81a1ac10 ffff8800bf30fcb8 ffffffff816d7439 0000000000000000
[13626.384294]  0000000000000000 ffff8800bf30fcf8 ffffffff81072eba ffff8800c56c0200
[13626.392329]  0000000000000001 ffff880036e4e418 ffff880036e4e400 ffff8800c56c01a0
[13626.400377] Call Trace:
[13626.403023]  [<ffffffff816d7439>] dump_stack+0x45/0x57
[13626.408539]  [<ffffffff81072eba>] warn_slowpath_common+0x8a/0xc0
[13626.415002]  [<ffffffff81072faa>] warn_slowpath_null+0x1a/0x20
[13626.421289]  [<ffffffff8114b1c4>] replace_preds+0x2e4/0xa50
[13626.427262]  [<ffffffff8114c2c3>] ? ftrace_profile_set_filter+0x23/0x100
[13626.434456]  [<ffffffff8114b9b2>] create_filter+0x82/0xb0
[13626.440680]  [<ffffffff8114c2f4>] ftrace_profile_set_filter+0x54/0x100
[13626.448135]  [<ffffffff81190a0b>] ? strndup_user+0x4b/0xc0
[13626.454464]  [<ffffffff81166260>] perf_ioctl+0x170/0x4d0
[13626.460638]  [<ffffffff810bb653>] ? up_write+0x23/0x50
[13626.466579]  [<ffffffff812023f0>] do_vfs_ioctl+0x2e0/0x4e0
[13626.472920]  [<ffffffff8120d0a5>] ? __fget+0x5/0xe0
[13626.478581]  [<ffffffff811a8f68>] ? SyS_mmap_pgoff+0xe8/0x290
[13626.485140]  [<ffffffff81202671>] SyS_ioctl+0x81/0xa0
[13626.490963]  [<ffffffff816df372>] system_call_fastpath+0x16/0x7a
[13626.497824] ---[ end trace 1beaa0aa99bf553f ]---

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
Please read the FAQ at  http://www.tux.org/lkml/

Re: perf/ftrace: fuzzer triggers another warning with PERF_EVENT_IOC_SET_FILTER

[Vince Weaver]

On Fri, 19 Jun 2015, Vince Weaver wrote:
> 
> OK, fuzzing found another test case, this one I can reproduce using perf:

and I'm wrong, I wasn't reproducing it with perf, I was looking at the 
wrong window :(

So weird, definitely I can trigger this warning, but it's not reproducible 
with the fuzzer or with manually trying things.  I'm not really sure how 
that can happen.  

Is it possible that two processes might try to update the preds 
linked-list for an event's filter simultaneously?  So this might be a 
hard-to-trigger race condition?  But I don't think the fuzzer actually 
ever has two threads trying to do ioctl at the same time.  hmmm.

Vince


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
Please read the FAQ at  http://www.tux.org/lkml/