2015-06-17 12:36:52

by Steven Rostedt

[permalink] [raw]
Subject: [GIT PULL] tracing: Have filter check for balanced ops


Linus,

Vince Weaver reported a warning when he added perf event filters
into his fuzzer tests. There's a missing check of balanced
operations when parenthesis are used, and this triggers a WARN_ON()
and when reading the failure, the filter reports no failure occurred.

The operands were not being checked if they match, this adds that.

Please pull the latest trace-fix-filter-4.1-rc8 tree, which can be found at:


git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
trace-fix-filter-4.1-rc8

Tag SHA1: 34bcfc82862ee15a76b98c54126f64abf52191c3
Head SHA1: 2cf30dc180cea808077f003c5116388183e54f9e


Steven Rostedt (1):
tracing: Have filter check for balanced ops

----
kernel/trace/trace_events_filter.c | 11 +++++++++--
1 file changed, 9 insertions(+), 2 deletions(-)
---------------------------
commit 2cf30dc180cea808077f003c5116388183e54f9e
Author: Steven Rostedt <[email protected]>
Date: Mon Jun 15 17:50:25 2015 -0400

tracing: Have filter check for balanced ops

When the following filter is used it causes a warning to trigger:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: No error

------------[ cut here ]------------
WARNING: CPU: 2 PID: 1223 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x3c5/0x990()
Modules linked in: bnep lockd grace bluetooth ...
CPU: 3 PID: 1223 Comm: bash Tainted: G W 4.1.0-rc3-test+ #450
Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
0000000000000668 ffff8800c106bc98 ffffffff816ed4f9 ffff88011ead0cf0
0000000000000000 ffff8800c106bcd8 ffffffff8107fb07 ffffffff8136b46c
ffff8800c7d81d48 ffff8800d4c2bc00 ffff8800d4d4f920 00000000ffffffea
Call Trace:
[<ffffffff816ed4f9>] dump_stack+0x4c/0x6e
[<ffffffff8107fb07>] warn_slowpath_common+0x97/0xe0
[<ffffffff8136b46c>] ? _kstrtoull+0x2c/0x80
[<ffffffff8107fb6a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81159065>] replace_preds+0x3c5/0x990
[<ffffffff811596b2>] create_filter+0x82/0xb0
[<ffffffff81159944>] apply_event_filter+0xd4/0x180
[<ffffffff81152bbf>] event_filter_write+0x8f/0x120
[<ffffffff811db2a8>] __vfs_write+0x28/0xe0
[<ffffffff811dda43>] ? __sb_start_write+0x53/0xf0
[<ffffffff812e51e0>] ? security_file_permission+0x30/0xc0
[<ffffffff811dc408>] vfs_write+0xb8/0x1b0
[<ffffffff811dc72f>] SyS_write+0x4f/0xb0
[<ffffffff816f5217>] system_call_fastpath+0x12/0x6a
---[ end trace e11028bd95818dcd ]---

Worse yet, reading the error message (the filter again) it says that
there was no error, when there clearly was. The issue is that the
code that checks the input does not check for balanced ops. That is,
having an op between a closed parenthesis and the next token.

This would only cause a warning, and fail out before doing any real
harm, but it should still not caues a warning, and the error reported
should work:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: Meaningless filter expression

And give no kernel warning.

Link: http://lkml.kernel.org/r/[email protected]

Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: [email protected] # 2.6.31+
Reported-by: Vince Weaver <[email protected]>
Tested-by: Vince Weaver <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index ced69da0ff55..7f2e97ce71a7 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-22 13:53:38

by Luis Henriques

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

Hi Steven,

On Wed, Jun 17, 2015 at 08:36:38AM -0400, Steven Rostedt wrote:
...
> diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> index ced69da0ff55..7f2e97ce71a7 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--;

Since the OP_NOT was introduced only with e12c09cf3087 ("tracing: Add
NOT to filtering logic"), how would stable kernels backport this fix?
Do you think that just dropping the 'if' and do the 'cnt--'
unconditionally would be ok?

Cheers,
--
Lu?s

2015-06-22 14:03:27

by Luis Henriques

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Mon, Jun 22, 2015 at 02:53:17PM +0100, Luis Henriques wrote:
> Hi Steven,
>
> On Wed, Jun 17, 2015 at 08:36:38AM -0400, Steven Rostedt wrote:
> ...
> > diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> > index ced69da0ff55..7f2e97ce71a7 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--;
>
> Since the OP_NOT was introduced only with e12c09cf3087 ("tracing: Add
> NOT to filtering logic"), how would stable kernels backport this fix?
> Do you think that just dropping the 'if' and do the 'cnt--'
> unconditionally would be ok?

Something like the patch below (only compile-tested).

Cheers,
--
Lu?s

>From db7ac73e73dd0ef0259d5d2871b7b9402b12e4d3 Mon Sep 17 00:00:00 2001
From: Steven Rostedt <[email protected]>
Date: Mon, 15 Jun 2015 17:50:25 -0400
Subject: [PATCH] tracing: Have filter check for balanced ops

commit 2cf30dc180cea808077f003c5116388183e54f9e upstream.

When the following filter is used it causes a warning to trigger:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: No error

------------[ cut here ]------------
WARNING: CPU: 2 PID: 1223 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x3c5/0x990()
Modules linked in: bnep lockd grace bluetooth ...
CPU: 3 PID: 1223 Comm: bash Tainted: G W 4.1.0-rc3-test+ #450
Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
0000000000000668 ffff8800c106bc98 ffffffff816ed4f9 ffff88011ead0cf0
0000000000000000 ffff8800c106bcd8 ffffffff8107fb07 ffffffff8136b46c
ffff8800c7d81d48 ffff8800d4c2bc00 ffff8800d4d4f920 00000000ffffffea
Call Trace:
[<ffffffff816ed4f9>] dump_stack+0x4c/0x6e
[<ffffffff8107fb07>] warn_slowpath_common+0x97/0xe0
[<ffffffff8136b46c>] ? _kstrtoull+0x2c/0x80
[<ffffffff8107fb6a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81159065>] replace_preds+0x3c5/0x990
[<ffffffff811596b2>] create_filter+0x82/0xb0
[<ffffffff81159944>] apply_event_filter+0xd4/0x180
[<ffffffff81152bbf>] event_filter_write+0x8f/0x120
[<ffffffff811db2a8>] __vfs_write+0x28/0xe0
[<ffffffff811dda43>] ? __sb_start_write+0x53/0xf0
[<ffffffff812e51e0>] ? security_file_permission+0x30/0xc0
[<ffffffff811dc408>] vfs_write+0xb8/0x1b0
[<ffffffff811dc72f>] SyS_write+0x4f/0xb0
[<ffffffff816f5217>] system_call_fastpath+0x12/0x6a
---[ end trace e11028bd95818dcd ]---

Worse yet, reading the error message (the filter again) it says that
there was no error, when there clearly was. The issue is that the
code that checks the input does not check for balanced ops. That is,
having an op between a closed parenthesis and the next token.

This would only cause a warning, and fail out before doing any real
harm, but it should still not caues a warning, and the error reported
should work:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: Meaningless filter expression

And give no kernel warning.

Link: http://lkml.kernel.org/r/[email protected]

Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Reported-by: Vince Weaver <[email protected]>
Tested-by: Vince Weaver <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
[ luis: backported to 3.16:
- unconditionally decrement cnt as the OP_NOT logic was introduced only
by e12c09cf3087 ("tracing: Add NOT to filtering logic") ]
Signed-off-by: Luis Henriques <[email protected]>
---
kernel/trace/trace_events_filter.c | 10 ++++++++--
1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 8a8631926a07..cc1cdaff9e9f 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -1399,19 +1399,25 @@ 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;
}
+ 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-22 14:17:33

by Steven Rostedt

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Mon, 22 Jun 2015 15:03:14 +0100
Luis Henriques <[email protected]> wrote:

> On Mon, Jun 22, 2015 at 02:53:17PM +0100, Luis Henriques wrote:
> > Hi Steven,
> >
> > On Wed, Jun 17, 2015 at 08:36:38AM -0400, Steven Rostedt wrote:
> > ...
> > > diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> > > index ced69da0ff55..7f2e97ce71a7 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--;
> >
> > Since the OP_NOT was introduced only with e12c09cf3087 ("tracing: Add
> > NOT to filtering logic"), how would stable kernels backport this fix?
> > Do you think that just dropping the 'if' and do the 'cnt--'
> > unconditionally would be ok?
>
> Something like the patch below (only compile-tested).
>
> Cheers,
> --
> Luís
>
> >From db7ac73e73dd0ef0259d5d2871b7b9402b12e4d3 Mon Sep 17 00:00:00 2001
> From: Steven Rostedt <[email protected]>
> Date: Mon, 15 Jun 2015 17:50:25 -0400
> Subject: [PATCH] tracing: Have filter check for balanced ops
>
> commit 2cf30dc180cea808077f003c5116388183e54f9e upstream.
>
> When the following filter is used it causes a warning to trigger:
>
> # cd /sys/kernel/debug/tracing
> # echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
> -bash: echo: write error: Invalid argument
> # cat events/ext4/ext4_truncate_exit/filter
> ((dev==1)blocks==2)
> ^
> parse_error: No error
>
> ------------[ cut here ]------------
> WARNING: CPU: 2 PID: 1223 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x3c5/0x990()
> Modules linked in: bnep lockd grace bluetooth ...
> CPU: 3 PID: 1223 Comm: bash Tainted: G W 4.1.0-rc3-test+ #450
> Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
> 0000000000000668 ffff8800c106bc98 ffffffff816ed4f9 ffff88011ead0cf0
> 0000000000000000 ffff8800c106bcd8 ffffffff8107fb07 ffffffff8136b46c
> ffff8800c7d81d48 ffff8800d4c2bc00 ffff8800d4d4f920 00000000ffffffea
> Call Trace:
> [<ffffffff816ed4f9>] dump_stack+0x4c/0x6e
> [<ffffffff8107fb07>] warn_slowpath_common+0x97/0xe0
> [<ffffffff8136b46c>] ? _kstrtoull+0x2c/0x80
> [<ffffffff8107fb6a>] warn_slowpath_null+0x1a/0x20
> [<ffffffff81159065>] replace_preds+0x3c5/0x990
> [<ffffffff811596b2>] create_filter+0x82/0xb0
> [<ffffffff81159944>] apply_event_filter+0xd4/0x180
> [<ffffffff81152bbf>] event_filter_write+0x8f/0x120
> [<ffffffff811db2a8>] __vfs_write+0x28/0xe0
> [<ffffffff811dda43>] ? __sb_start_write+0x53/0xf0
> [<ffffffff812e51e0>] ? security_file_permission+0x30/0xc0
> [<ffffffff811dc408>] vfs_write+0xb8/0x1b0
> [<ffffffff811dc72f>] SyS_write+0x4f/0xb0
> [<ffffffff816f5217>] system_call_fastpath+0x12/0x6a
> ---[ end trace e11028bd95818dcd ]---
>
> Worse yet, reading the error message (the filter again) it says that
> there was no error, when there clearly was. The issue is that the
> code that checks the input does not check for balanced ops. That is,
> having an op between a closed parenthesis and the next token.
>
> This would only cause a warning, and fail out before doing any real
> harm, but it should still not caues a warning, and the error reported
> should work:
>
> # cd /sys/kernel/debug/tracing
> # echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
> -bash: echo: write error: Invalid argument
> # cat events/ext4/ext4_truncate_exit/filter
> ((dev==1)blocks==2)
> ^
> parse_error: Meaningless filter expression
>
> And give no kernel warning.
>
> Link: http://lkml.kernel.org/r/[email protected]
>
> Cc: Peter Zijlstra <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Arnaldo Carvalho de Melo <[email protected]>
> Reported-by: Vince Weaver <[email protected]>
> Tested-by: Vince Weaver <[email protected]>
> Signed-off-by: Steven Rostedt <[email protected]>
> [ luis: backported to 3.16:
> - unconditionally decrement cnt as the OP_NOT logic was introduced only
> by e12c09cf3087 ("tracing: Add NOT to filtering logic") ]
> Signed-off-by: Luis Henriques <[email protected]>
> ---
> kernel/trace/trace_events_filter.c | 10 ++++++++--
> 1 file changed, 8 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
> index 8a8631926a07..cc1cdaff9e9f 100644
> --- a/kernel/trace/trace_events_filter.c
> +++ b/kernel/trace/trace_events_filter.c
> @@ -1399,19 +1399,25 @@ 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;
> }
> + cnt--;

To make this patch simpler, just move the "cnt--;" above the OP_AND and
OP_OR check and remove the "cnt--;" from that if statement.

But yeah, this looks fine. You can test it with the example in the
change log.

echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter

And see if it gives an error other than "parse_error: No error".

-- Steve


> 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-22 14:49:53

by Luis Henriques

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Mon, Jun 22, 2015 at 10:17:28AM -0400, Steven Rostedt wrote:
...
> To make this patch simpler, just move the "cnt--;" above the OP_AND and
> OP_OR check and remove the "cnt--;" from that if statement.
>
> But yeah, this looks fine. You can test it with the example in the
> change log.
>
> echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
>
> And see if it gives an error other than "parse_error: No error".
>
> -- Steve

Thanks Steven, I've done a quick test with a 3.16-ckt kernel and I can
confirm that the modified patch (i.e. including your suggestion) fixes
the problem.

I'm attaching the patch below and CC'ing stable mailing-list.

Cheers,
--
Lu?s

>From 19305c2d68fbb43ba219881082b95da2e4e82db5 Mon Sep 17 00:00:00 2001
From: Steven Rostedt <[email protected]>
Date: Mon, 15 Jun 2015 17:50:25 -0400
Subject: [PATCH] tracing: Have filter check for balanced ops

commit 2cf30dc180cea808077f003c5116388183e54f9e upstream.

When the following filter is used it causes a warning to trigger:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: No error

------------[ cut here ]------------
WARNING: CPU: 2 PID: 1223 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x3c5/0x990()
Modules linked in: bnep lockd grace bluetooth ...
CPU: 3 PID: 1223 Comm: bash Tainted: G W 4.1.0-rc3-test+ #450
Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
0000000000000668 ffff8800c106bc98 ffffffff816ed4f9 ffff88011ead0cf0
0000000000000000 ffff8800c106bcd8 ffffffff8107fb07 ffffffff8136b46c
ffff8800c7d81d48 ffff8800d4c2bc00 ffff8800d4d4f920 00000000ffffffea
Call Trace:
[<ffffffff816ed4f9>] dump_stack+0x4c/0x6e
[<ffffffff8107fb07>] warn_slowpath_common+0x97/0xe0
[<ffffffff8136b46c>] ? _kstrtoull+0x2c/0x80
[<ffffffff8107fb6a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81159065>] replace_preds+0x3c5/0x990
[<ffffffff811596b2>] create_filter+0x82/0xb0
[<ffffffff81159944>] apply_event_filter+0xd4/0x180
[<ffffffff81152bbf>] event_filter_write+0x8f/0x120
[<ffffffff811db2a8>] __vfs_write+0x28/0xe0
[<ffffffff811dda43>] ? __sb_start_write+0x53/0xf0
[<ffffffff812e51e0>] ? security_file_permission+0x30/0xc0
[<ffffffff811dc408>] vfs_write+0xb8/0x1b0
[<ffffffff811dc72f>] SyS_write+0x4f/0xb0
[<ffffffff816f5217>] system_call_fastpath+0x12/0x6a
---[ end trace e11028bd95818dcd ]---

Worse yet, reading the error message (the filter again) it says that
there was no error, when there clearly was. The issue is that the
code that checks the input does not check for balanced ops. That is,
having an op between a closed parenthesis and the next token.

This would only cause a warning, and fail out before doing any real
harm, but it should still not caues a warning, and the error reported
should work:

# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: Meaningless filter expression

And give no kernel warning.

Link: http://lkml.kernel.org/r/[email protected]

Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Reported-by: Vince Weaver <[email protected]>
Tested-by: Vince Weaver <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
[ luis: backported to 3.16:
- unconditionally decrement cnt as the OP_NOT logic was introduced only
by e12c09cf3087 ("tracing: Add NOT to filtering logic") ]
Signed-off-by: Luis Henriques <[email protected]>
---
kernel/trace/trace_events_filter.c | 9 +++++++--
1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 8a8631926a07..cb347e85f75e 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -1399,19 +1399,24 @@ 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;
+ }

+ cnt--;
if (elt->op == OP_AND || elt->op == OP_OR) {
n_logical_preds++;
continue;
}
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-24 14:55:01

by Greg KH

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Mon, Jun 22, 2015 at 03:49:40PM +0100, Luis Henriques wrote:
> On Mon, Jun 22, 2015 at 10:17:28AM -0400, Steven Rostedt wrote:
> ...
> > To make this patch simpler, just move the "cnt--;" above the OP_AND and
> > OP_OR check and remove the "cnt--;" from that if statement.
> >
> > But yeah, this looks fine. You can test it with the example in the
> > change log.
> >
> > echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
> >
> > And see if it gives an error other than "parse_error: No error".
> >
> > -- Steve
>
> Thanks Steven, I've done a quick test with a 3.16-ckt kernel and I can
> confirm that the modified patch (i.e. including your suggestion) fixes
> the problem.
>
> I'm attaching the patch below and CC'ing stable mailing-list.
>
> Cheers,
> --
> Lu?s

Thanks, I've used this patch for 3.10 and 3.14.

greg k-h

2015-06-25 04:03:58

by Sasha Levin

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On 06/17/2015 08:36 AM, Steven Rostedt wrote:
> Linus,
>
> Vince Weaver reported a warning when he added perf event filters
> into his fuzzer tests. There's a missing check of balanced
> operations when parenthesis are used, and this triggers a WARN_ON()
> and when reading the failure, the filter reports no failure occurred.

Hey Steven,

My fuzzings are hitting the warning added by this patch:

[2175114.187536] WARNING: CPU: 16 PID: 10388 at kernel/trace/trace_events_filter.c:1388 replace_preds+0x814/0x2140()
[2175114.190213] Modules linked in:
[2175114.191111] CPU: 16 PID: 10388 Comm: trinity-c48 Not tainted 4.1.0-next-20150623-sasha-00039-ga1eb83a-dirty #2280
[2175114.194463] ffff880a23350000 000000006a8e22d4 ffff880a2335f878 ffffffffabc8cfa3
[2175114.196547] 0000000000000000 0000000000000000 ffff880a2335f8c8 ffffffffa21ebd36
[2175114.198604] ffff880e60fe09e0 ffffffffa24608f4 ffff880e61b14830 ffff880e60fe09d8
[2175114.200666] Call Trace:
[2175114.201377] [<ffffffffabc8cfa3>] dump_stack+0x4f/0x7b
[2175114.202793] [<ffffffffa21ebd36>] warn_slowpath_common+0xc6/0x120
[2175114.206235] [<ffffffffa21ebf7a>] warn_slowpath_null+0x1a/0x20
[2175114.207819] [<ffffffffa24608f4>] replace_preds+0x814/0x2140
[2175114.216433] [<ffffffffa24638aa>] create_filter+0x15a/0x210
[2175114.231529] [<ffffffffa246406b>] apply_event_filter+0x28b/0x780
[2175114.241196] [<ffffffffa2450306>] event_filter_write+0x106/0x1c0
[2175114.242823] [<ffffffffa260dd48>] do_loop_readv_writev+0x128/0x1e0
[2175114.248901] [<ffffffffa261051e>] do_readv_writev+0x5ae/0x6c0
[2175114.256760] [<ffffffffa2610742>] vfs_writev+0x72/0xb0
[2175114.258134] [<ffffffffa2613bb4>] SyS_pwritev+0x1b4/0x220
[2175114.261291] [<ffffffffabcf9962>] tracesys_phase2+0x88/0x8d


Thanks,
Sasha

2015-06-25 04:34:38

by Steven Rostedt

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Thu, 25 Jun 2015 00:03:02 -0400
Sasha Levin <[email protected]> wrote:

> On 06/17/2015 08:36 AM, Steven Rostedt wrote:
> > Linus,
> >
> > Vince Weaver reported a warning when he added perf event filters
> > into his fuzzer tests. There's a missing check of balanced
> > operations when parenthesis are used, and this triggers a WARN_ON()
> > and when reading the failure, the filter reports no failure occurred.
>
> Hey Steven,
>
> My fuzzings are hitting the warning added by this patch:

Yes, Vince said he was able to hit it as well. But the warning itself
is useless if you don't supply what filter was used to trigger it.

-- Steve


>
> [2175114.187536] WARNING: CPU: 16 PID: 10388 at kernel/trace/trace_events_filter.c:1388 replace_preds+0x814/0x2140()
> [2175114.190213] Modules linked in:
> [2175114.191111] CPU: 16 PID: 10388 Comm: trinity-c48 Not tainted 4.1.0-next-20150623-sasha-00039-ga1eb83a-dirty #2280
> [2175114.194463] ffff880a23350000 000000006a8e22d4 ffff880a2335f878 ffffffffabc8cfa3
> [2175114.196547] 0000000000000000 0000000000000000 ffff880a2335f8c8 ffffffffa21ebd36
> [2175114.198604] ffff880e60fe09e0 ffffffffa24608f4 ffff880e61b14830 ffff880e60fe09d8
> [2175114.200666] Call Trace:
> [2175114.201377] [<ffffffffabc8cfa3>] dump_stack+0x4f/0x7b
> [2175114.202793] [<ffffffffa21ebd36>] warn_slowpath_common+0xc6/0x120
> [2175114.206235] [<ffffffffa21ebf7a>] warn_slowpath_null+0x1a/0x20
> [2175114.207819] [<ffffffffa24608f4>] replace_preds+0x814/0x2140
> [2175114.216433] [<ffffffffa24638aa>] create_filter+0x15a/0x210
> [2175114.231529] [<ffffffffa246406b>] apply_event_filter+0x28b/0x780
> [2175114.241196] [<ffffffffa2450306>] event_filter_write+0x106/0x1c0
> [2175114.242823] [<ffffffffa260dd48>] do_loop_readv_writev+0x128/0x1e0
> [2175114.248901] [<ffffffffa261051e>] do_readv_writev+0x5ae/0x6c0
> [2175114.256760] [<ffffffffa2610742>] vfs_writev+0x72/0xb0
> [2175114.258134] [<ffffffffa2613bb4>] SyS_pwritev+0x1b4/0x220
> [2175114.261291] [<ffffffffabcf9962>] tracesys_phase2+0x88/0x8d
>
>
> Thanks,
> Sasha

2015-06-25 20:12:32

by Sasha Levin

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On 06/25/2015 12:35 AM, Steven Rostedt wrote:
> On Thu, 25 Jun 2015 00:03:02 -0400
> Sasha Levin <[email protected]> wrote:
>
>> On 06/17/2015 08:36 AM, Steven Rostedt wrote:
>>> Linus,
>>>
>>> Vince Weaver reported a warning when he added perf event filters
>>> into his fuzzer tests. There's a missing check of balanced
>>> operations when parenthesis are used, and this triggers a WARN_ON()
>>> and when reading the failure, the filter reports no failure occurred.
>>
>> Hey Steven,
>>
>> My fuzzings are hitting the warning added by this patch:
>
> Yes, Vince said he was able to hit it as well. But the warning itself
> is useless if you don't supply what filter was used to trigger it.

# echo ">" > events/ext4/ext4_truncate_exit/filter


Thanks,
Sasha

2015-06-25 23:08:39

by Steven Rostedt

[permalink] [raw]
Subject: Re: [GIT PULL] tracing: Have filter check for balanced ops

On Thu, 25 Jun 2015 16:11:46 -0400
Sasha Levin <[email protected]> wrote:


> # echo ">" > events/ext4/ext4_truncate_exit/filter

Thanks. Seems that the WARN_ON is frivolous. We should just handle
cnt < 0 as a bad filter.

Can you run you tests with this patch. Thanks!

-- Steve

>From b4875bbe7e68f139bd3383828ae8e994a0df6d28 Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (Red Hat)" <[email protected]>
Date: Thu, 25 Jun 2015 18:02:29 -0400
Subject: [PATCH] tracing/filter: Do not WARN on operand count going below zero

When testing the fix for the trace filter, I could not come up with
a scenario where the operand count goes below zero, so I added a
WARN_ON_ONCE(cnt < 0) to the logic. But there is legitimate case
that it can happen (although the filter would be wrong).

# echo '>' > /sys/kernel/debug/events/ext4/ext4_truncate_exit/filter

That is, a single operation without any operands will hit the path
where the WARN_ON_ONCE() can trigger. Although this is harmless,
and the filter is reported as a error. But instead of spitting out
a warning to the kernel dmesg, just fail nicely and report it via
the proper channels.

Link: http://lkml.kernel.org/r/[email protected]

Reported-by: Vince Weaver <[email protected]>
Reported-by: Sasha Levin <[email protected]>
Cc: [email protected] # 2.6.33+
Signed-off-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace_events_filter.c | 4 +++-
1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 7f2e97ce71a7..2900d7723d97 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -1385,7 +1385,9 @@ static int check_preds(struct filter_parse_state *ps)
if (elt->op != OP_NOT)
cnt--;
n_normal_preds++;
- WARN_ON_ONCE(cnt < 0);
+ /* all ops should have operands */
+ if (cnt < 0)
+ break;
}

if (cnt != 1 || !n_normal_preds || n_logical_preds >= n_normal_preds) {
--
2.1.4