2014-01-30 04:16:33

by Dave Jones

[permalink] [raw]
Subject: FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))

WARNING: CPU: 3 PID: 796 at kernel/trace/ftrace.c:1655 __ftrace_hash_rec_update.part.38+0x20a/0x240()
CPU: 3 PID: 796 Comm: trinity-main Not tainted 3.13.0+ #100
0000000000000009 000000003628f1c9 ffff8802395dfc48 ffffffffb1737a8a
0000000000000000 ffff8802395dfc80 ffffffffb106d28d 0000000000000000
0000000000000001 ffff880221165000 0000000000000000 ffff8801db17c9d8
Call Trace:
[<ffffffffb1737a8a>] dump_stack+0x4e/0x7a
[<ffffffffb106d28d>] warn_slowpath_common+0x7d/0xa0
[<ffffffffb106d3ba>] warn_slowpath_null+0x1a/0x20
[<ffffffffb112128a>] __ftrace_hash_rec_update.part.38+0x20a/0x240
[<ffffffffb1122fff>] ftrace_shutdown+0x1ff/0x330
[<ffffffffb11234f0>] unregister_ftrace_function+0x20/0x40
[<ffffffffb1141a57>] perf_ftrace_event_register+0x87/0x130
[<ffffffffb11418bc>] perf_trace_destroy+0x2c/0x50
[<ffffffffb114cec9>] tp_perf_event_destroy+0x9/0x10
[<ffffffffb114e4b5>] __free_event+0x25/0xb0
[<ffffffffb114e5b7>] free_event+0x77/0x100
[<ffffffffb114e6a4>] perf_event_release_kernel+0x64/0x90
[<ffffffffb114ecdf>] put_event+0xdf/0x130
[<ffffffffb114ec30>] ? put_event+0x30/0x130
[<ffffffffb114ed40>] perf_release+0x10/0x20
[<ffffffffb11c9c4a>] __fput+0xea/0x2c0
[<ffffffffb11c9e6e>] ____fput+0xe/0x10
[<ffffffffb1090a24>] task_work_run+0xb4/0xe0
[<ffffffffb106e835>] do_exit+0x2e5/0xb40
[<ffffffffb174ac7f>] ? ftrace_call+0x5/0x2f
[<ffffffffb107007c>] do_group_exit+0x4c/0xc0
[<ffffffffb1070104>] SyS_exit_group+0x14/0x20
[<ffffffffb174b1e4>] tracesys+0xdd/0xe2
---[ end trace f3c5dcf3f350edcc ]---


1655 if (FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))
1656 return;


This old friend came back. I first reported this back in July, and we aparently never
got to the bottom of it.

Dave


2014-01-30 05:00:47

by Steven Rostedt

[permalink] [raw]
Subject: Re: FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))

Are you running as root? If not, you found another way to get perf to start function tracing.

-- Steve


Dave Jones <[email protected]> wrote:
>WARNING: CPU: 3 PID: 796 at kernel/trace/ftrace.c:1655
>__ftrace_hash_rec_update.part.38+0x20a/0x240()
>CPU: 3 PID: 796 Comm: trinity-main Not tainted 3.13.0+ #100
> 0000000000000009 000000003628f1c9 ffff8802395dfc48 ffffffffb1737a8a
> 0000000000000000 ffff8802395dfc80 ffffffffb106d28d 0000000000000000
> 0000000000000001 ffff880221165000 0000000000000000 ffff8801db17c9d8
>Call Trace:
> [<ffffffffb1737a8a>] dump_stack+0x4e/0x7a
> [<ffffffffb106d28d>] warn_slowpath_common+0x7d/0xa0
> [<ffffffffb106d3ba>] warn_slowpath_null+0x1a/0x20
> [<ffffffffb112128a>] __ftrace_hash_rec_update.part.38+0x20a/0x240
> [<ffffffffb1122fff>] ftrace_shutdown+0x1ff/0x330
> [<ffffffffb11234f0>] unregister_ftrace_function+0x20/0x40
> [<ffffffffb1141a57>] perf_ftrace_event_register+0x87/0x130
> [<ffffffffb11418bc>] perf_trace_destroy+0x2c/0x50
> [<ffffffffb114cec9>] tp_perf_event_destroy+0x9/0x10
> [<ffffffffb114e4b5>] __free_event+0x25/0xb0
> [<ffffffffb114e5b7>] free_event+0x77/0x100
> [<ffffffffb114e6a4>] perf_event_release_kernel+0x64/0x90
> [<ffffffffb114ecdf>] put_event+0xdf/0x130
> [<ffffffffb114ec30>] ? put_event+0x30/0x130
> [<ffffffffb114ed40>] perf_release+0x10/0x20
> [<ffffffffb11c9c4a>] __fput+0xea/0x2c0
> [<ffffffffb11c9e6e>] ____fput+0xe/0x10
> [<ffffffffb1090a24>] task_work_run+0xb4/0xe0
> [<ffffffffb106e835>] do_exit+0x2e5/0xb40
> [<ffffffffb174ac7f>] ? ftrace_call+0x5/0x2f
> [<ffffffffb107007c>] do_group_exit+0x4c/0xc0
> [<ffffffffb1070104>] SyS_exit_group+0x14/0x20
> [<ffffffffb174b1e4>] tracesys+0xdd/0xe2
>---[ end trace f3c5dcf3f350edcc ]---
>
>
>1655 if (FTRACE_WARN_ON((rec->flags &
>~FTRACE_FL_MASK) == 0))
>1656 return;
>
>
>This old friend came back. I first reported this back in July, and we
>aparently never
>got to the bottom of it.
>
> Dave

--
Sent from my Android phone with K-9 Mail. Please excuse my brevity.

2014-01-30 05:32:43

by Dave Jones

[permalink] [raw]
Subject: Re: FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))

On Wed, Jan 29, 2014 at 11:50:43PM -0500, Steven Rostedt wrote:
> Are you running as root? If not, you found another way to get perf to start function tracing.

Good point. In this case, I was trying some new experimental trinity code
that starts as root, generates fd's, then drops privs before doing syscalls.

So the "generate fds" part did some perf_event_open's as root, yeah.

While that's less scary from a security pov than it was last time, it's still
something that aparently needs fixing.

Dave

2014-01-30 13:55:36

by Steven Rostedt

[permalink] [raw]
Subject: Re: FTRACE_WARN_ON((rec->flags & ~FTRACE_FL_MASK) == 0))

On Thu, 30 Jan 2014 00:32:32 -0500
Dave Jones <[email protected]> wrote:

> On Wed, Jan 29, 2014 at 11:50:43PM -0500, Steven Rostedt wrote:
> > Are you running as root? If not, you found another way to get perf to start function tracing.
>
> Good point. In this case, I was trying some new experimental trinity code
> that starts as root, generates fd's, then drops privs before doing syscalls.
>
> So the "generate fds" part did some perf_event_open's as root, yeah.
>
> While that's less scary from a security pov than it was last time, it's still
> something that aparently needs fixing.
>

OK, then I'm not as worried (phew!). But you are correct, this needs to
be fixed. How do I run just perf commands from trinity? I do not think
this occurs from any other systemcall needing to be run.

Peter, Jiri,

Although we fixed the bug that let a normal user enable function
tracing from perf, we never figured out why perf screws up the function
tracing filter accounting. That will happen if you either use a
uninitialized ftrace hash, or modify the hash without using the ftrace
API. If it is the latter, it is probably done by some kind of use after
free.

-- Steve