lkml.org 
[lkml]   [2014]   [Jun]   [7]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: tracing: NULL ptr deref in ring_buffer_wait
    On 05/08/2014 12:16 PM, Steven Rostedt wrote:
    > On Thu, 08 May 2014 11:31:41 -0400
    > Sasha Levin <sasha.levin@oracle.com> wrote:
    >
    >> On 05/05/2014 11:46 AM, Sasha Levin wrote:
    >>>>>>> [ 3589.407670] vfs_read (fs/read_write.c:430)
    >>>>>>> [ 3589.407670] SyS_read (fs/read_write.c:568 fs/read_write.c:560)
    >>>>>>> [ 3589.407670] tracesys (arch/x86/kernel/entry_64.S:746)
    >>>>>>> [ 3589.407670] Code: 85 cd 0c 00 00 48 c7 c1 5c e1 6d ac 48 c7 c2 af 89 6d ac 31 c0 be fa 0b 00 00 48 c7 c7 16 e1 6d ac e8 3c 68 f9 ff e9 a7 0c 00 00 <49> 81 7d 00 80 81 76 ae b8 00 00 00 00 44 0f 44 c0 eb 07 0f 1f
    >>>>>>> [ 3589.407670] RIP __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
    >>>>>>> [ 3589.407670] RSP <ffff88005c9d1c18>
    >>>>>>> [ 3589.407670] CR2: 00000000000001f0
    >>>>>
    >>>>> Is this easily reproducible?
    >>> Nope, only saw it once.
    >>
    >> And a second time today, I guess I could put a debug patch and see if that
    >> helps, if you had something in mind...
    >>
    >
    > All I can think of is to try this:
    >
    > -- Steve
    >
    > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
    > index c634868..7cacbad 100644
    > --- a/kernel/trace/ring_buffer.c
    > +++ b/kernel/trace/ring_buffer.c
    > @@ -558,6 +558,10 @@ void ring_buffer_wait(struct ring_buffer *buffer, int cpu)
    > work = &buffer->irq_work;
    > else {
    > cpu_buffer = buffer->buffers[cpu];
    > + if (unlikely(!cpu_buffer)) {
    > + printk("null cpu buffer, %d\n", cpu);
    > + BUG();
    > + }
    > work = &cpu_buffer->irq_work;
    > }
    >
    >

    Hi Steven,

    Yup, it took me *that* long to reproduce it again, but I can confirm that that
    BUG() gets hit (the printk shows cpu 30 like the BUG):

    [ 2410.677199] kernel BUG at kernel/trace/ring_buffer.c:563!
    [ 2410.679445] can: request_module (can-proto-4) failed.
    [ 2410.680298] invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
    [ 2410.680298] Dumping ftrace buffer:
    [ 2410.680298] (ftrace buffer empty)
    [ 2410.680298] Modules linked in:
    [ 2410.680298] CPU: 30 PID: 34851 Comm: trinity-c88 Not tainted 3.15.0-rc8-next-20140606-sasha-00021-ga9d3a0b-dirty #596
    [ 2410.680298] task: ffff8802c866b000 ti: ffff8802c7724000 task.ti: ffff8802c7724000
    [ 2410.680298] RIP: ring_buffer_wait (kernel/trace/ring_buffer.c:563)
    [ 2410.680298] RSP: 0018:ffff8802c7727de8 EFLAGS: 00010296
    [ 2410.680298] RAX: 0000000000000013 RBX: 0000000000000024 RCX: 0000000000000006
    [ 2410.680298] RDX: 0000000000000001 RSI: ffffffffad5030db RDI: ffffffffaa1d8952
    [ 2410.711484] RBP: ffff8802c7727e38 R08: 0000000000000000 R09: 0000000000000000
    [ 2410.711484] R10: 0000000000000001 R11: 0000000000000000 R12: ffff88003681e900
    [ 2410.711484] R13: ffff88006ce7d100 R14: 0000000000000000 R15: ffff8800530090fc
    [ 2410.721370] FS: 00007f8c14bad700(0000) GS:ffff8806cae00000(0000) knlGS:0000000000000000
    [ 2410.721370] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [ 2410.721370] CR2: 00007f8c11440000 CR3: 000000029dd18000 CR4: 00000000000006a0
    [ 2410.721370] DR0: 00000000006d6000 DR1: 00000000006d6000 DR2: 0000000000000000
    [ 2410.721370] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
    [ 2410.721370] Stack:
    [ 2410.721370] ffff880053008028 0000000000000000 ffff8802c866b000 ffffffffaa1bb600
    [ 2410.721370] ffff8802c7727e08 ffff8802c7727e08 ffff880053008000 ffff880053008028
    [ 2410.721370] ffff88006ce7d100 ffff8802c866b000 ffff8802c7727e48 ffffffffaa24af8a
    [ 2410.721370] Call Trace:
    [ 2410.721370] ? bit_waitqueue (kernel/sched/wait.c:291)
    [ 2410.721370] wait_on_pipe (kernel/trace/trace.c:1095)
    [ 2410.721370] tracing_wait_pipe.isra.19 (kernel/trace/trace.c:4280)
    [ 2410.721370] tracing_read_pipe (kernel/trace/trace.c:4326)
    [ 2410.721370] vfs_read (fs/read_write.c:430)
    [ 2410.721370] SyS_read (fs/read_write.c:568 fs/read_write.c:560)
    [ 2410.721370] tracesys (arch/x86/kernel/entry_64.S:542)
    [ 2410.721370] Code: ff ff 85 c0 75 5a eb 5d 66 90 48 8b 87 c8 00 00 00 48 63 d6 4c 8b 34 d0 4d 85 f6 75 15 48 c7 c7 6e 96 6f ae 31 c0 e8 7d 8f 2b 03 <0f> 0b 0f 1f 44 00 00 4d 8d ae d8 01 00 00 ba 01 00 00 00 48 8d
    All code
    ========
    0: ff (bad)
    1: ff 85 c0 75 5a eb incl -0x14a58a40(%rbp)
    7: 5d pop %rbp
    8: 66 90 xchg %ax,%ax
    a: 48 8b 87 c8 00 00 00 mov 0xc8(%rdi),%rax
    11: 48 63 d6 movslq %esi,%rdx
    14: 4c 8b 34 d0 mov (%rax,%rdx,8),%r14
    18: 4d 85 f6 test %r14,%r14
    1b: 75 15 jne 0x32
    1d: 48 c7 c7 6e 96 6f ae mov $0xffffffffae6f966e,%rdi
    24: 31 c0 xor %eax,%eax
    26: e8 7d 8f 2b 03 callq 0x32b8fa8
    2b:* 0f 0b ud2 <-- trapping instruction
    2d: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
    32: 4d 8d ae d8 01 00 00 lea 0x1d8(%r14),%r13
    39: ba 01 00 00 00 mov $0x1,%edx
    3e: 48 8d 00 lea (%rax),%rax

    Code starting with the faulting instruction
    ===========================================
    0: 0f 0b ud2
    2: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
    7: 4d 8d ae d8 01 00 00 lea 0x1d8(%r14),%r13
    e: ba 01 00 00 00 mov $0x1,%edx
    13: 48 8d 00 lea (%rax),%rax

    Thanks,
    Sasha


    \
     
     \ /
      Last update: 2014-06-08 06:01    [W:4.840 / U:0.008 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site