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 ]---
On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
Vince Weaver <[email protected]> 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 ]---
On Thu, 18 Jun 2015, Steven Rostedt wrote:
> On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
> Vince Weaver <[email protected]> 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
On Thu, 18 Jun 2015 17:18:47 -0400 (EDT)
Vince Weaver <[email protected]> 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
On Thu, 18 Jun 2015, Steven Rostedt wrote:
> On Wed, 17 Jun 2015 19:32:26 -0400 (EDT)
> Vince Weaver <[email protected]> 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 ]---
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