Re: tracing: NULL ptr deref in ring_buffer_wait

[Sasha Levin <sasha.levin@oracle.com>]

On 05/05/2014 10:47 AM, Steven Rostedt wrote:
> On Sun, 04 May 2014 20:47:59 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> Hi all,
>>
>> While fuzzing with trinity inside a KVM tools guest running latest -next
>> kernel I've stumbled on the following:
> 
> Do you have any idea what was going on? CPU hotplug maybe?

I don't know what exactly was happening, but a CPU hotplug is very
possible.

>> [ 3589.386869] BUG: unable to handle kernel NULL pointer dereference at 00000000000001f0
>> [ 3589.389326] IP: __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
> 
> Could you tell me what that line is? From what I see with next/master:
> 
> 3069:	if (!prove_locking || lock->key == &__lockdep_no_validate__)
> 3070:		check = 0;

Right, that's 'lock' being dereferenced.

Usually I see that when a NULL lock was passed to a locking function.

> I wonder if somehow the ring buffer wait queue lock didn't get
> initialized properly for lockdep. That is, the lock->key is bad? But
> the bad offset is 0x1f0 which is 496 but lock->key is the first thing

Note that ring_buffer_wait() has:

        if (cpu == RING_BUFFER_ALL_CPUS)
                work = &buffer->irq_work;
        else {
                cpu_buffer = buffer->buffers[cpu];
                work = &cpu_buffer->irq_work;
        }


        prepare_to_wait(&work->waiters, &wait, TASK_INTERRUPTIBLE);


So if we enter the 'else' case here, and 'cpu_buffer' is NULL, then &cpu_buffer->irq_work
would have the right offset in this case. So I suspect it all started from this being
NULL.

>> [ 3589.390099] PGD 44bf8067 PUD 392d1067 PMD ac4c2067 PTE 0
>> [ 3589.390099] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>> [ 3589.390099] Dumping ftrace buffer:
>> [ 3589.390099]    (ftrace buffer empty)
>> [ 3589.390099] Modules linked in:
>> [ 3589.395496] CPU: 37 PID: 28180 Comm: trinity-c168 Not tainted 3.15.0-rc3-next-20140502-sasha-00020-g3183c20 #432
>> [ 3589.396585] task: ffff8802c77d3000 ti: ffff88005c9d0000 task.ti: ffff88005c9d0000
>> [ 3589.396585] RIP: __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
>> [ 3589.396585] RSP: 0018:ffff88005c9d1c18  EFLAGS: 00010002
>> [ 3589.396585] RAX: 0000000000000086 RBX: ffff8802c77d3000 RCX: 0000000000000000
>> [ 3589.396585] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000000001f0
>> [ 3589.396585] RBP: ffff88005c9d1d08 R08: 0000000000000001 R09: 0000000000000001
>> [ 3589.396585] R10: ffff8802c77d3000 R11: 0000000000000001 R12: 0000000000000000
>> [ 3589.396585] R13: 00000000000001f0 R14: 0000000000000000 R15: 0000000000000000
>> [ 3589.396585] FS:  00007f1cfe809700(0000) GS:ffff88017ce00000(0000) knlGS:0000000000000000
>> [ 3589.407670] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> [ 3589.407670] CR2: 00000000000001f0 CR3: 000000005cba3000 CR4: 00000000000006a0
>> [ 3589.407670] DR0: 00000000006de000 DR1: 0000000000000000 DR2: 0000000000000000
>> [ 3589.407670] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
>> [ 3589.407670] Stack:
>> [ 3589.407670]  0000000000000025 ffff88017cfd8380 00000000001d8380 0000000000000025
>> [ 3589.407670]  ffff88005c9d1c68 ffffffffa81a5df8 0002fa098d2fe980 0000000000000000
>> [ 3589.407670]  0002fa098d2fe980 0000000000000001 ffffffffaf415f20 0000000000015ee0
>> [ 3589.407670] Call Trace:
>> [ 3589.407670] ? sched_clock_cpu (kernel/sched/clock.c:311)
>> [ 3589.407670] ? __lock_acquire (kernel/locking/lockdep.c:3189)
>> [ 3589.407670] lock_acquire (arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3602)
>> [ 3589.407670] ? prepare_to_wait (kernel/sched/wait.c:177)
> 
> This is the q->lock, which is the first item in the queue_head. The
> dep_map is a bit further but not 496 bytes.
> 
>> [ 3589.407670] ? _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:109 kernel/locking/spinlock.c:159)
>> [ 3589.407670] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
>> [ 3589.407670] ? prepare_to_wait (kernel/sched/wait.c:177)
>> [ 3589.407670] ? get_parent_ip (kernel/sched/core.c:2485)
>> [ 3589.407670] ? mutex_unlock (kernel/locking/mutex.c:220)
>> [ 3589.407670] prepare_to_wait (kernel/sched/wait.c:177)
>> [ 3589.407670] ? __mutex_unlock_slowpath (arch/x86/include/asm/paravirt.h:809 kernel/locking/mutex.c:713 kernel/locking/mutex.c:722)
>> [ 3589.407670] ring_buffer_wait (kernel/trace/ring_buffer.c:587)
> 
> Now, perhaps buffer was NULL when passed in. This code is mostly
> dealing with offsets and if buffer is NULL it wont bug till it did that
> q->lock grab.
> 
>> [ 3589.407670] ? bit_waitqueue (kernel/sched/wait.c:291)
>> [ 3589.407670] wait_on_pipe (kernel/trace/trace.c:1095)
> 
> this passes in iter->trace_buffer->buffer.
> 
>> [ 3589.407670] tracing_buffers_read (kernel/trace/trace.c:5162)
> 
> The iter->trace_buffer is set up in tracing_buffers_open() with:
> 
> 	info->iter.trace_buffer = &tr->trace_buffer;
> 
> I have no idea how trace_buffer->buffer could have been NULL here?
> 
> Although, with cpu hotplug, a cpu_buffer may not be allocated until
> that cpu is booted up. But it shouldn't allow you to trace that buffer
> before hand.
> 
> Hmm, if a cpu is not up yet, perhaps you can read it. But if this was
> the case, the ring_buffer_read_page() would have failed.
> 
>> [ 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.


Thanks,
Sasha