* 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 a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox