Re: [PATCH 07/18 v3] tracing: Add TRACE_DEFINE_ENUM() macro to map enums to their values

[Andrey Ryabinin <a.ryabinin@samsung.com>]

On 04/17/2015 06:59 AM, Sasha Levin wrote:
> On 04/16/2015 11:21 PM, Steven Rostedt wrote:
>> On Wed, 15 Apr 2015 20:58:31 -0400
>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>
>>>> On 04/15/2015 10:05 AM, Steven Rostedt wrote:
>>>>>> On Wed, 15 Apr 2015 09:22:37 -0400
>>>>>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>>>>>
>>>>>>>> Hey Steven,
>>>>>>>>
>>>>>>>> I'm seeing the following when booting:
>>>>>>>>
>>>>>>>> [   10.678876] BUG: KASan: out of bounds access in trace_event_enum_update+0xb1d/0xb70 at addr ffffffffa6c4dc68
>>>>>>
>>>>>> Thanks for the report. Mind sending me over your config, and which git
>>>>>> commit was your HEAD. I can't seem to find 7858a62 from your output.
>>>>
>>>> It reproduces on the latest -next kernel. I've attached my config.
>>>>
>> What version of gcc is required to run KASan, the highest version I
>> have to build kernels with is 4.9.0
>>
>> I have no idea what event caused the issue :-/
> 
> 4.9.2+ is needed for KASan.
> 

Actually, detection of out of bounds accesses to stack and global variables works
only with gcc 5+
And this is out-of-bounds access to global variable print_fmt_9p_client_req.

Line numbers in report is ambiguous, so I did following change to reduce compiler's optimization
and get more clear line numbers.

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 7da1dfe..40c31b6 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1726,7 +1726,7 @@ static char *enum_replace(char *ptr, struct trace_enum_map *map, int len)
        return ptr + elen;
 }

-static void update_event_printk(struct ftrace_event_call *call,
+__attribute__((optimize("O0"))) static noinline void update_event_printk(struct ftrace_event_call *call,
                                struct trace_enum_map *map)
 {
        char *ptr



This ended up in this splat (which has more sane line numbers):

[    0.123688] ==================================================================
[    0.123688] BUG: KASan: out of bounds access in update_event_printk+0x6fe/0x720 at addr ffffffff821654a8
[    0.123688] Read of size 1 by task swapper/0/1
[    0.123688] Address belongs to variable print_fmt_9p_client_req+0x848/0x880
[    0.124000] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.0.0+ #269
[    0.124000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.7.5.1-0-g8936dbb-20141113_115728-nilsson.home.kraxel.org 04/01/2014
[    0.124000]  ffffffff82165720 ffff8801f4d17be8 ffffffff81cc0d35 000000000000003f
[    0.124000]  ffff8801f4d17c80 ffff8801f4d17c68 ffffffff8139cafc ffff8801f4d17c28
[    0.124000]  ffffffff8139c39d 0000000000000292 ffffffff81397c5c ffff8801f4d17c38
[    0.124000] Call Trace:
[    0.124000] dump_stack (lib/dump_stack.c:52)
[    0.124000] kasan_report_error (mm/kasan/report.c:132 mm/kasan/report.c:193)
[    0.124000] ? kasan_slab_alloc (mm/kasan/kasan.c:325)
[    0.124000] ? kmem_cache_alloc (mm/slub.c:2522)
[    0.124000] __asan_report_load1_noabort (mm/kasan/report.c:248)
[    0.124000] ? update_event_printk (kernel/trace/trace_events.c:1736 (discriminator 1))
[    0.124000] update_event_printk (kernel/trace/trace_events.c:1736 (discriminator 1))
[    0.124000] trace_event_enum_update (kernel/trace/trace_events.c:1819)
[    0.124000] ? tracefs_create_file (fs/tracefs/inode.c:413)
[    0.124000] tracer_init_tracefs (kernel/trace/trace.c:4122 kernel/trace/trace.c:6750 kernel/trace/trace.c:6848)
[    0.124000] ? set_tracepoint_printk (kernel/trace/trace.c:6825)
[    0.124000] do_one_initcall (init/main.c:788)
[    0.124000] ? try_to_run_init_process (init/main.c:777)
[    0.124000] ? parse_args (kernel/params.c:218)
[    0.124000] kernel_init_freeable (init/main.c:853 init/main.c:861 init/main.c:880 init/main.c:1001)
[    0.124000] ? __switch_to (arch/x86/include/asm/paravirt.h:25 arch/x86/kernel/process_64.c:410)
[    0.124000] ? rest_init (init/main.c:928)
[    0.124000] kernel_init (init/main.c:933)
[    0.124000] ? rest_init (init/main.c:928)
[    0.124000] ret_from_fork (arch/x86/kernel/entry_64.S:631)
[    0.124000] ? rest_init (init/main.c:928)
[    0.124000] Memory state around the buggy address:
[    0.124000]  ffffffff82165380: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    0.124000]  ffffffff82165400: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    0.124000] >ffffffff82165480: 00 00 00 00 00 fa fa fa fa fa fa fa 00 00 00 00
[    0.124000]                                   ^
[    0.124000]  ffffffff82165500: fa fa fa fa 00 00 00 00 fa fa fa fa 00 00 00 00
[    0.124000]  ffffffff82165580: fa fa fa fa 00 00 00 00 00 00 00 00 00 00 00 00
[    0.124000] ==================================================================

And kasan is not needed to debug this further.
Just stick WARN_ON(ptr > call->print_fmt + strlen(call->print_fmt)) into the 'for' loop in update_event_printk().



> 
> Thanks,
> Sasha
>