2015-06-12 21:12:34

by Vince Weaver

[permalink] [raw]
Subject: perf,ftrace: fuzzer triggers warning in trace_events_filter code


So I've modified my fuzzer to try to exercise the
PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
warnings.

For example, this one:

[28509.873731] ------------[ cut here ]------------
[28509.879188] WARNING: CPU: 1 PID: 9572 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x4f2/0x9b0()
[28509.890174] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_realtek intel_rapl iosf_mbi snd_hda_codec_hdmi snd_hda_codec_generic snd_hda_intel coretemp snd_hda_controller kvm_intel kvm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec snd_hda_core aesni_intel snd_hwdep tpm_tis ppdev i915 iTCO_wdt evdev iTCO_vendor_support snd_pcm aes_x86_64 snd_timer lrw snd tpm gf128mul soundcore glue_helper ablk_helper cryptd psmouse drm_kms_helper lpc_ich serio_raw pcspkr parport_pc mei_me mfd_core parport mei drm battery i2c_i801 video i2c_algo_bit wmi processor button sg sr_mod sd_mod cdrom ehci_pci ehci_hcd xhci_pci ahci xhci_hcd libahci libata e1000e crc32c_intel ptp fan scsi_mod usbcore pps_core usb_common thermal thermal_sys
[28509.967457] CPU: 1 PID: 9572 Comm: perf_fuzzer Tainted: G W 4.1.0-rc7+ #155
[28509.976717] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
[28509.985188] ffffffff81a1abb0 ffff8800ce757cb8 ffffffff816d7229 0000000000000000
[28509.993795] 0000000000000000 ffff8800ce757cf8 ffffffff81072eba 0000000000000160
[28510.002406] ffff8800cda26208 ffff8800364e4a90 0000000000000000 ffff8800cda26200
[28510.010990] Call Trace:
[28510.014189] [<ffffffff816d7229>] dump_stack+0x45/0x57
[28510.020242] [<ffffffff81072eba>] warn_slowpath_common+0x8a/0xc0
[28510.027171] [<ffffffff81072faa>] warn_slowpath_null+0x1a/0x20
[28510.033947] [<ffffffff8114b3c2>] replace_preds+0x4f2/0x9b0
[28510.040401] [<ffffffff8114c213>] ? ftrace_profile_set_filter+0x23/0x100
[28510.048083] [<ffffffff8114b902>] create_filter+0x82/0xb0
[28510.054381] [<ffffffff8114c244>] ftrace_profile_set_filter+0x54/0x100
[28510.061831] [<ffffffff8119088b>] ? strndup_user+0x4b/0xc0
[28510.068170] [<ffffffff811661c0>] perf_ioctl+0x170/0x4d0
[28510.074356] [<ffffffff81202270>] do_vfs_ioctl+0x2e0/0x4e0
[28510.080681] [<ffffffff81168305>] ? __perf_sw_event+0x65/0xa0
[28510.087299] [<ffffffff8106312d>] ? __do_page_fault+0x2ad/0x460
[28510.094105] [<ffffffff812024f1>] SyS_ioctl+0x81/0xa0
[28510.099983] [<ffffffff816df172>] system_call_fastpath+0x16/0x7a
[28510.106857] ---[ end trace 2ea55cf8a8b076c3 ]---

This corresponds to
/* Make sure the stack is empty */
pred = __pop_pred_stack(&stack);
if (WARN_ON(pred)) {
err = -EINVAL;
filter->root = NULL;
goto fail;
}


2015-06-12 21:41:08

by Steven Rostedt

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
Vince Weaver <[email protected]> wrote:

>
> So I've modified my fuzzer to try to exercise the
> PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
> warnings.

Is there any way to know what the filter string you used that generated
this?

-- Steve

>
> For example, this one:
>
> [28509.873731] ------------[ cut here ]------------
> [28509.879188] WARNING: CPU: 1 PID: 9572 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x4f2/0x9b0()
> [28509.890174] Modules linked in: fuse x86_pkg_temp_thermal intel_powerclamp snd_hda_codec_realtek intel_rapl iosf_mbi snd_hda_codec_hdmi snd_hda_codec_generic snd_hda_intel coretemp snd_hda_controller kvm_intel kvm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec snd_hda_core aesni_intel snd_hwdep tpm_tis ppdev i915 iTCO_wdt evdev iTCO_vendor_support snd_pcm aes_x86_64 snd_timer lrw snd tpm gf128mul soundcore glue_helper ablk_helper cryptd psmouse drm_kms_helper lpc_ich serio_raw pcspkr parport_pc mei_me mfd_core parport mei drm battery i2c_i801 video i2c_algo_bit wmi processor button sg sr_mod sd_mod cdrom ehci_pci ehci_hcd xhci_pci ahci xhci_hcd libahci libata e1000e crc32c_intel ptp fan scsi_mod usbcore pps_core usb_common thermal thermal_sys
> [28509.967457] CPU: 1 PID: 9572 Comm: perf_fuzzer Tainted: G W 4.1.0-rc7+ #155
> [28509.976717] Hardware name: LENOVO 10AM000AUS/SHARKBAY, BIOS FBKT72AUS 01/26/2014
> [28509.985188] ffffffff81a1abb0 ffff8800ce757cb8 ffffffff816d7229 0000000000000000
> [28509.993795] 0000000000000000 ffff8800ce757cf8 ffffffff81072eba 0000000000000160
> [28510.002406] ffff8800cda26208 ffff8800364e4a90 0000000000000000 ffff8800cda26200
> [28510.010990] Call Trace:
> [28510.014189] [<ffffffff816d7229>] dump_stack+0x45/0x57
> [28510.020242] [<ffffffff81072eba>] warn_slowpath_common+0x8a/0xc0
> [28510.027171] [<ffffffff81072faa>] warn_slowpath_null+0x1a/0x20
> [28510.033947] [<ffffffff8114b3c2>] replace_preds+0x4f2/0x9b0
> [28510.040401] [<ffffffff8114c213>] ? ftrace_profile_set_filter+0x23/0x100
> [28510.048083] [<ffffffff8114b902>] create_filter+0x82/0xb0
> [28510.054381] [<ffffffff8114c244>] ftrace_profile_set_filter+0x54/0x100
> [28510.061831] [<ffffffff8119088b>] ? strndup_user+0x4b/0xc0
> [28510.068170] [<ffffffff811661c0>] perf_ioctl+0x170/0x4d0
> [28510.074356] [<ffffffff81202270>] do_vfs_ioctl+0x2e0/0x4e0
> [28510.080681] [<ffffffff81168305>] ? __perf_sw_event+0x65/0xa0
> [28510.087299] [<ffffffff8106312d>] ? __do_page_fault+0x2ad/0x460
> [28510.094105] [<ffffffff812024f1>] SyS_ioctl+0x81/0xa0
> [28510.099983] [<ffffffff816df172>] system_call_fastpath+0x16/0x7a
> [28510.106857] ---[ end trace 2ea55cf8a8b076c3 ]---
>
> This corresponds to
> /* Make sure the stack is empty */
> pred = __pop_pred_stack(&stack);
> if (WARN_ON(pred)) {
> err = -EINVAL;
> filter->root = NULL;
> goto fail;
> }

2015-06-13 01:09:25

by Vince Weaver

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Fri, 12 Jun 2015, Steven Rostedt wrote:

> On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> Vince Weaver <[email protected]> wrote:
>
> >
> > So I've modified my fuzzer to try to exercise the
> > PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
> > warnings.
>
> Is there any way to know what the filter string you used that generated
> this?

Various seem to trigger it. One example is

ext4:ext4_truncate_exit
(((dev<=913)blocks==916)common_type&756)

Vince

2015-06-13 01:29:46

by Steven Rostedt

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
Vince Weaver <[email protected]> wrote:

> On Fri, 12 Jun 2015, Steven Rostedt wrote:
>
> > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > Vince Weaver <[email protected]> wrote:
> >
> > >
> > > So I've modified my fuzzer to try to exercise the
> > > PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
> > > warnings.
> >
> > Is there any way to know what the filter string you used that generated
> > this?
>
> Various seem to trigger it. One example is
>
> ext4:ext4_truncate_exit
> (((dev<=913)blocks==916)common_type&756)
>

Thanks, OK, I know what the issue is. I'm also thinking the solution
may simply be removing that WARN_ON(). But I'll look at it a little
deeper before deciding that.

The WARN_ON() simply detected an anomaly, but nothing breaks when that
anomaly occurs. Well, I don't see anything breaking, it just expected
that we couldn't get to this path, but now we know we can. Thus the
solution is to remove the WARN_ON() or detect the bad filter before
getting there.

-- Steve

2015-06-15 21:50:37

by Steven Rostedt

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
Vince Weaver <[email protected]> wrote:

> On Fri, 12 Jun 2015, Steven Rostedt wrote:
>
> > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > Vince Weaver <[email protected]> wrote:
> >
> > >
> > > So I've modified my fuzzer to try to exercise the
> > > PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
> > > warnings.
> >
> > Is there any way to know what the filter string you used that generated
> > this?
>
> Various seem to trigger it. One example is
>
> ext4:ext4_truncate_exit
> (((dev<=913)blocks==916)common_type&756)
>

Does this patch fix your issue?

-- Steve

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 71511ebc70db..dae84db83d97 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -1369,19 +1369,26 @@ static int check_preds(struct filter_parse_state *ps)
{
int n_normal_preds = 0, n_logical_preds = 0;
struct postfix_elt *elt;
+ int cnt = 0;

list_for_each_entry(elt, &ps->postfix, list) {
- if (elt->op == OP_NONE)
+ if (elt->op == OP_NONE) {
+ cnt++;
continue;
+ }

if (elt->op == OP_AND || elt->op == OP_OR) {
n_logical_preds++;
+ cnt--;
continue;
}
+ if (elt->op != OP_NOT)
+ cnt--;
n_normal_preds++;
+ WARN_ON_ONCE(cnt < 0);
}

- if (!n_normal_preds || n_logical_preds >= n_normal_preds) {
+ if (cnt != 1 || !n_normal_preds || n_logical_preds >= n_normal_preds) {
parse_error(ps, FILT_ERR_INVALID_FILTER, 0);
return -EINVAL;
}

2015-06-16 16:17:37

by Steven Rostedt

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Mon, 15 Jun 2015 17:50:25 -0400
Steven Rostedt <[email protected]> wrote:

> On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
> Vince Weaver <[email protected]> wrote:
>
> > On Fri, 12 Jun 2015, Steven Rostedt wrote:
> >
> > > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > > Vince Weaver <[email protected]> wrote:
> > >
> > > >
> > > > So I've modified my fuzzer to try to exercise the
> > > > PERF_EVENT_IOC_SET_FILTER ioctl() and it is starting to turn up some
> > > > warnings.
> > >
> > > Is there any way to know what the filter string you used that generated
> > > this?
> >
> > Various seem to trigger it. One example is
> >
> > ext4:ext4_truncate_exit
> > (((dev<=913)blocks==916)common_type&756)
> >
>
> Does this patch fix your issue?

I got this patch all ready and set to push to Linus. But I was hoping
to add a Tested-by: from you. I already have you as Reported-by.

I would like to get this in before 4.1 is released.

Thanks,

-- Steve

>
> diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> index 71511ebc70db..dae84db83d97 100644
> --- a/kernel/trace/trace_events_filter.c
> +++ b/kernel/trace/trace_events_filter.c
> @@ -1369,19 +1369,26 @@ static int check_preds(struct filter_parse_state *ps)
> {
> int n_normal_preds = 0, n_logical_preds = 0;
> struct postfix_elt *elt;
> + int cnt = 0;
>
> list_for_each_entry(elt, &ps->postfix, list) {
> - if (elt->op == OP_NONE)
> + if (elt->op == OP_NONE) {
> + cnt++;
> continue;
> + }
>
> if (elt->op == OP_AND || elt->op == OP_OR) {
> n_logical_preds++;
> + cnt--;
> continue;
> }
> + if (elt->op != OP_NOT)
> + cnt--;
> n_normal_preds++;
> + WARN_ON_ONCE(cnt < 0);
> }
>
> - if (!n_normal_preds || n_logical_preds >= n_normal_preds) {
> + if (cnt != 1 || !n_normal_preds || n_logical_preds >= n_normal_preds) {
> parse_error(ps, FILT_ERR_INVALID_FILTER, 0);
> return -EINVAL;
> }

2015-06-17 05:03:45

by Vince Weaver

[permalink] [raw]
Subject: Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

On Tue, 16 Jun 2015, Steven Rostedt wrote:
> > Does this patch fix your issue?
>
> I got this patch all ready and set to push to Linus. But I was hoping
> to add a Tested-by: from you. I already have you as Reported-by.
>
> I would like to get this in before 4.1 is released.

sorry for the delay. I've patched the kernel and I am unable to replicate
the Warning with it applied. So feel free to add a Tested-by from me.

Vince