perf,ftrace: fuzzer triggers warning in trace_events_filter code

perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Vince Weaver]

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;
                }

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Steven Rostedt]

On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
Vince Weaver <vincent.weaver@maine.edu> 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;
>                 }

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Vince Weaver]

On Fri, 12 Jun 2015, Steven Rostedt wrote:

> On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> Vince Weaver <vincent.weaver@maine.edu> 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

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Steven Rostedt]

On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
Vince Weaver <vincent.weaver@maine.edu> wrote:

> On Fri, 12 Jun 2015, Steven Rostedt wrote:
> 
> > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > Vince Weaver <vincent.weaver@maine.edu> 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

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Steven Rostedt]

On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
Vince Weaver <vincent.weaver@maine.edu> wrote:

> On Fri, 12 Jun 2015, Steven Rostedt wrote:
> 
> > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > Vince Weaver <vincent.weaver@maine.edu> 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;
 	}

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Steven Rostedt]

On Mon, 15 Jun 2015 17:50:25 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 12 Jun 2015 21:15:10 -0400 (EDT)
> Vince Weaver <vincent.weaver@maine.edu> wrote:
> 
> > On Fri, 12 Jun 2015, Steven Rostedt wrote:
> > 
> > > On Fri, 12 Jun 2015 17:18:22 -0400 (EDT)
> > > Vince Weaver <vincent.weaver@maine.edu> 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;
>  	}

Re: perf,ftrace: fuzzer triggers warning in trace_events_filter code

[Vince Weaver]

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