* tracing: NULL ptr deref in ring_buffer_wait
@ 2014-05-05 0:47 Sasha Levin
2014-05-05 14:47 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Sasha Levin @ 2014-05-05 0:47 UTC (permalink / raw)
To: Steven Rostedt, Frederic Weisbecker, Ingo Molnar; +Cc: LKML, Dave Jones
Hi all,
While fuzzing with trinity inside a KVM tools guest running latest -next
kernel I've stumbled on the following:
[ 3589.386869] BUG: unable to handle kernel NULL pointer dereference at 00000000000001f0
[ 3589.389326] IP: __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
[ 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)
[ 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)
[ 3589.407670] ? bit_waitqueue (kernel/sched/wait.c:291)
[ 3589.407670] wait_on_pipe (kernel/trace/trace.c:1095)
[ 3589.407670] tracing_buffers_read (kernel/trace/trace.c:5162)
[ 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
Thanks,
Sasha
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-05-05 0:47 tracing: NULL ptr deref in ring_buffer_wait Sasha Levin
@ 2014-05-05 14:47 ` Steven Rostedt
2014-05-05 15:46 ` Sasha Levin
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2014-05-05 14:47 UTC (permalink / raw)
To: Sasha Levin; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
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?
>
>
> [ 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;
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
in that structure, which would mean the lock pointer itself is 0x1f0.
> [ 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?
Thanks,
-- Steve
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-05-05 14:47 ` Steven Rostedt
@ 2014-05-05 15:46 ` Sasha Levin
2014-05-08 15:31 ` Sasha Levin
0 siblings, 1 reply; 7+ messages in thread
From: Sasha Levin @ 2014-05-05 15:46 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-05-05 15:46 ` Sasha Levin
@ 2014-05-08 15:31 ` Sasha Levin
2014-05-08 16:16 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Sasha Levin @ 2014-05-08 15:31 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
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...
[ 1157.707702] BUG: unable to handle kernel NULL pointer dereference at 00000000000001f0
[ 1157.710068] IP: __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
[ 1157.710068] PGD 243db1067 PUD 25b047067 PMD 0
[ 1157.710068] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 1157.710068] Dumping ftrace buffer:
[ 1157.710068] (ftrace buffer empty)
[ 1157.710068] Modules linked in:
[ 1157.710068] CPU: 14 PID: 30503 Comm: trinity-c247 Tainted: G W 3.15.0-rc4-next-20140507-sasha-00004-g14be78b-dirty #450
[ 1157.710068] task: ffff880002ec0000 ti: ffff880240ec8000 task.ti: ffff880240ec8000
[ 1157.710068] RIP: __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
[ 1157.710068] RSP: 0000:ffff880240ec9ab8 EFLAGS: 00010002
[ 1157.710068] RAX: 0000000000000086 RBX: ffff880002ec0000 RCX: 0000000000000000
[ 1157.710068] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000000001f0
[ 1157.710068] RBP: ffff880240ec9ba8 R08: 0000000000000001 R09: 0000000000000001
[ 1157.710068] R10: ffff880002ec0000 R11: 0000000000000001 R12: 0000000000000000
[ 1157.710068] R13: 00000000000001f0 R14: 0000000000000000 R15: 0000000000000000
[ 1157.710068] FS: 00007f33d790b700(0000) GS:ffff88036ac00000(0000) knlGS:0000000000000000
[ 1157.710068] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 1157.710068] CR2: 00000000000001f0 CR3: 0000000243fb6000 CR4: 00000000000006a0
[ 1157.710068] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1157.710068] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[ 1157.710068] Stack:
[ 1157.710068] ffff880240ec9ac8 ffffffffa30be274 ffff880240ec9ad8 ffffffffa307c7e5
[ 1157.710068] ffff880240ec9b08 ffffffffa31a7a05 000000000000000e ffff88036add8380
[ 1157.710068] 00000000001d8380 000000000000000e ffff880240ec9b38 ffffffffa31a7ce8
[ 1157.710068] Call Trace:
[ 1157.710068] ? kvm_clock_read (arch/x86/include/asm/preempt.h:90 arch/x86/kernel/kvmclock.c:86)
[ 1157.710068] ? sched_clock (arch/x86/include/asm/paravirt.h:192 arch/x86/kernel/tsc.c:305)
[ 1157.710068] ? sched_clock_local (kernel/sched/clock.c:214)
[ 1157.710068] ? sched_clock_cpu (kernel/sched/clock.c:311)
[ 1157.710068] ? __lock_acquire (kernel/locking/lockdep.c:3189)
[ 1157.710068] lock_acquire (arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3602)
[ 1157.710068] ? prepare_to_wait (kernel/sched/wait.c:177)
[ 1157.710068] ? _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:109 kernel/locking/spinlock.c:159)
[ 1157.710068] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
[ 1157.710068] ? prepare_to_wait (kernel/sched/wait.c:177)
[ 1157.710068] ? get_parent_ip (kernel/sched/core.c:2485)
[ 1157.710068] ? mutex_unlock (kernel/locking/mutex.c:220)
[ 1157.710068] prepare_to_wait (kernel/sched/wait.c:177)
[ 1157.710068] ? __mutex_unlock_slowpath (arch/x86/include/asm/paravirt.h:809 kernel/locking/mutex.c:713 kernel/locking/mutex.c:722)
[ 1157.710068] ring_buffer_wait (kernel/trace/ring_buffer.c:587)
[ 1157.710068] ? bit_waitqueue (kernel/sched/wait.c:291)
[ 1157.710068] wait_on_pipe (kernel/trace/trace.c:1095)
[ 1157.710068] tracing_wait_pipe.isra.19 (kernel/trace/trace.c:4235)
[ 1157.710068] tracing_read_pipe (kernel/trace/trace.c:4281)
[ 1157.710068] ? tracing_splice_read_pipe (kernel/trace/trace.c:4250)
[ 1157.710068] do_loop_readv_writev (fs/read_write.c:708)
[ 1157.710068] ? tracing_splice_read_pipe (kernel/trace/trace.c:4250)
[ 1157.710068] compat_do_readv_writev (fs/read_write.c:1020)
[ 1157.710068] ? get_parent_ip (kernel/sched/core.c:2485)
[ 1157.710068] ? mutex_lock_nested (arch/x86/include/asm/preempt.h:98 kernel/locking/mutex.c:570 kernel/locking/mutex.c:587)
[ 1157.710068] ? __fdget_pos (fs/file.c:714)
[ 1157.710068] ? __fdget_pos (fs/file.c:714)
[ 1157.710068] ? __fget_light (include/linux/rcupdate.h:428 include/linux/fdtable.h:80 fs/file.c:684)
[ 1157.710068] compat_readv (fs/read_write.c:1053)
[ 1157.710068] compat_SyS_readv (fs/read_write.c:1071 fs/read_write.c:1061)
[ 1157.710068] ia32_do_call (arch/x86/ia32/ia32entry.S:430)
[ 1157.710068] Code: 85 cd 0c 00 00 48 c7 c1 d4 12 6e a7 48 c7 c2 2f bb 6d a7 31 c0 be fa 0b 00 00 48 c7 c7 8e 12 6e a7 e8 6c 66 f9 ff e9 a7 0c 00 00 <49> 81 7d 00 40 f8 96 a9 b8 00 00 00 00 44 0f 44 c0 eb 07 0f 1f
[ 1157.710068] RIP __lock_acquire (kernel/locking/lockdep.c:3070 (discriminator 1))
[ 1157.710068] RSP <ffff880240ec9ab8>
[ 1157.710068] CR2: 00000000000001f0
Thanks,
Sasha
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-05-08 15:31 ` Sasha Levin
@ 2014-05-08 16:16 ` Steven Rostedt
2014-06-08 3:41 ` Sasha Levin
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2014-05-08 16:16 UTC (permalink / raw)
To: Sasha Levin; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
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;
}
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-05-08 16:16 ` Steven Rostedt
@ 2014-06-08 3:41 ` Sasha Levin
2014-06-09 20:32 ` Steven Rostedt
0 siblings, 1 reply; 7+ messages in thread
From: Sasha Levin @ 2014-06-08 3:41 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: tracing: NULL ptr deref in ring_buffer_wait
2014-06-08 3:41 ` Sasha Levin
@ 2014-06-09 20:32 ` Steven Rostedt
0 siblings, 0 replies; 7+ messages in thread
From: Steven Rostedt @ 2014-06-09 20:32 UTC (permalink / raw)
To: Sasha Levin; +Cc: Frederic Weisbecker, Ingo Molnar, LKML, Dave Jones
On Sat, 07 Jun 2014 23:41:21 -0400
Sasha Levin <sasha.levin@oracle.com> wrote:
> 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)
Found it.
Let me guess, if you ls /sys/kernel/debug/tracing/per_cpu, you'll see
more CPUs than you have on the box. I have a box like this, and when I
cat the trace_pipe from one of the CPUs that don't exist, I trigger the
bug.
This patch should fix the bug.
-- Steve
diff --git a/include/linux/ring_buffer.h b/include/linux/ring_buffer.h
index d69cf63..49a4d6f 100644
--- a/include/linux/ring_buffer.h
+++ b/include/linux/ring_buffer.h
@@ -97,7 +97,7 @@ __ring_buffer_alloc(unsigned long size, unsigned flags, struct lock_class_key *k
__ring_buffer_alloc((size), (flags), &__key); \
})
-void ring_buffer_wait(struct ring_buffer *buffer, int cpu);
+int ring_buffer_wait(struct ring_buffer *buffer, int cpu);
int ring_buffer_poll_wait(struct ring_buffer *buffer, int cpu,
struct file *filp, poll_table *poll_table);
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index c634868..7c56c3d 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -543,7 +543,7 @@ static void rb_wake_up_waiters(struct irq_work *work)
* as data is added to any of the @buffer's cpu buffers. Otherwise
* it will wait for data to be added to a specific cpu buffer.
*/
-void ring_buffer_wait(struct ring_buffer *buffer, int cpu)
+int ring_buffer_wait(struct ring_buffer *buffer, int cpu)
{
struct ring_buffer_per_cpu *cpu_buffer;
DEFINE_WAIT(wait);
@@ -557,6 +557,8 @@ void ring_buffer_wait(struct ring_buffer *buffer, int cpu)
if (cpu == RING_BUFFER_ALL_CPUS)
work = &buffer->irq_work;
else {
+ if (!cpumask_test_cpu(cpu, buffer->cpumask))
+ return -ENODEV;
cpu_buffer = buffer->buffers[cpu];
work = &cpu_buffer->irq_work;
}
@@ -591,6 +593,7 @@ void ring_buffer_wait(struct ring_buffer *buffer, int cpu)
schedule();
finish_wait(&work->waiters, &wait);
+ return 0;
}
/**
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 16f7038..56422f1 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1085,13 +1085,13 @@ update_max_tr_single(struct trace_array *tr, struct task_struct *tsk, int cpu)
}
#endif /* CONFIG_TRACER_MAX_TRACE */
-static void wait_on_pipe(struct trace_iterator *iter)
+static int wait_on_pipe(struct trace_iterator *iter)
{
/* Iterators are static, they should be filled or empty */
if (trace_buffer_iter(iter, iter->cpu_file))
- return;
+ return 0;
- ring_buffer_wait(iter->trace_buffer->buffer, iter->cpu_file);
+ return ring_buffer_wait(iter->trace_buffer->buffer, iter->cpu_file);
}
#ifdef CONFIG_FTRACE_STARTUP_TEST
@@ -4378,6 +4378,7 @@ tracing_poll_pipe(struct file *filp, poll_table *poll_table)
static int tracing_wait_pipe(struct file *filp)
{
struct trace_iterator *iter = filp->private_data;
+ int ret;
while (trace_empty(iter)) {
@@ -4399,10 +4400,13 @@ static int tracing_wait_pipe(struct file *filp)
mutex_unlock(&iter->mutex);
- wait_on_pipe(iter);
+ ret = wait_on_pipe(iter);
mutex_lock(&iter->mutex);
+ if (ret)
+ return ret;
+
if (signal_pending(current))
return -EINTR;
}
@@ -5327,8 +5331,12 @@ tracing_buffers_read(struct file *filp, char __user *ubuf,
goto out_unlock;
}
mutex_unlock(&trace_types_lock);
- wait_on_pipe(iter);
+ ret = wait_on_pipe(iter);
mutex_lock(&trace_types_lock);
+ if (ret) {
+ size = ret;
+ goto out_unlock;
+ }
if (signal_pending(current)) {
size = -EINTR;
goto out_unlock;
@@ -5538,8 +5546,10 @@ tracing_buffers_splice_read(struct file *file, loff_t *ppos,
goto out;
}
mutex_unlock(&trace_types_lock);
- wait_on_pipe(iter);
+ ret = wait_on_pipe(iter);
mutex_lock(&trace_types_lock);
+ if (ret)
+ goto out;
if (signal_pending(current)) {
ret = -EINTR;
goto out;
^ permalink raw reply related [flat|nested] 7+ messages in thread
end of thread, other threads:[~2014-06-09 20:32 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-05-05 0:47 tracing: NULL ptr deref in ring_buffer_wait Sasha Levin
2014-05-05 14:47 ` Steven Rostedt
2014-05-05 15:46 ` Sasha Levin
2014-05-08 15:31 ` Sasha Levin
2014-05-08 16:16 ` Steven Rostedt
2014-06-08 3:41 ` Sasha Levin
2014-06-09 20:32 ` Steven Rostedt
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.