tracing: NULL ptr deref in ring_buffer_wait

DISCUSSION Sasha Levin 2 participants 7 messages May 5, 2014 – Jun 9, 2014

Subsystems (2)

Tracing Tracing ring buffer

lore

Share & tools

lore

Steven Rostedt

maintainer

2014-05-05 14:47 UTC #1 lore raw

Quoted 4 lines · On Sun, 04 May 2014 20:47:59 -0400 Sasha Levin <[email protected]> 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?

Quoted 4 lines


[ 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.

Quoted 20 lines

[ 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:

Quoted 8 lines

[ 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.

Quoted 8 lines

[ 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.

Quoted 2 lines

[ 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.

Quoted 1 line

[ 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.

Quoted 7 lines

[ 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

Sasha Levin

author

2014-05-05 15:46 UTC #2 lore raw

Quoted 9 lines · Steven Rostedt

Quoted 4 lines · On Sun, 04 May 2014 20:47:59 -0400 Sasha Levin <[email protected]> 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.

Quoted 7 lines

Quoted 2 lines
[ 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.

Quoted 3 lines

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.

Quoted 73 lines

Quoted 20 lines

[ 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:

Quoted 8 lines

[ 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.

Quoted 8 lines

[ 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.

Quoted 2 lines

[ 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.

Quoted 1 line

[ 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.

Quoted 7 lines

[ 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

Quoted 1 line

Is this easily reproducible?

Nope, only saw it once.

Thanks,
Sasha

Sasha Levin

author

2014-05-08 15:32 UTC #3 lore raw

Quoted 10 lines · Sasha Levin

Quoted 9 lines

Quoted 7 lines

[ 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

Steven Rostedt

maintainer

2014-05-08 16:16 UTC #4 lore raw

Quoted 9 lines · On Thu, 08 May 2014 11:31:41 -0400 Sasha Levin <[email protected]> wrote:

Quoted 8 lines · Sasha Levin

Quoted 8 lines

Quoted 7 lines

[ 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

Quoted 6 lines

Quoted 2 lines
Quoted 1 line
Quoted 1 line
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

kernel/trace/ring_buffer.c +4 -0

index c634868..7cacbad 100644
@@ -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;
 	}

Sasha Levin

author

2014-06-08 03:41 UTC #5 lore raw

Quoted 29 lines · Steven Rostedt

Quoted 9 lines · On Thu, 08 May 2014 11:31:41 -0400 Sasha Levin <[email protected]> wrote:
Quoted 8 lines · Sasha Levin
Quoted 8 lines
Quoted 8 lines
Quoted 7 lines
Quoted 7 lines
[ 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
Quoted 6 lines
Quoted 2 lines
Quoted 1 line
Quoted 1 line
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
kernel/trace/ring_buffer.c +0 -0
index c634868..7cacbad 100644

kernel/trace/ring_buffer.c void ring_buffer_wait(struct ring_buffer *buffer, int cpu) · line 567

Quoted 10 lines

kernel/trace/ring_buffer.c +4 -0

@@ -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

Steven Rostedt

maintainer

2014-06-09 20:32 UTC #6 lore raw

Quoted 29 lines · On Sat, 07 Jun 2014 23:41:21 -0400 Sasha Levin <[email protected]> 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

Quoted 8 lines

[ 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

include/linux/ring_buffer.h +1 -1

index d69cf63..49a4d6f 100644
@@ -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);

kernel/trace/ring_buffer.c +4 -1

index c634868..7c56c3d 100644
@@ -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;
 }
 
 /**

kernel/trace/trace.c +16 -6

index 16f7038..56422f1 100644
@@ -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;