From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933054AbaEEOrS (ORCPT ); Mon, 5 May 2014 10:47:18 -0400 Received: from cdptpa-outbound-snat.email.rr.com ([107.14.166.226]:26573 "EHLO cdptpa-oedge-vip.email.rr.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S933028AbaEEOrO (ORCPT ); Mon, 5 May 2014 10:47:14 -0400 Date: Mon, 5 May 2014 10:47:12 -0400 From: Steven Rostedt To: Sasha Levin Cc: Frederic Weisbecker , Ingo Molnar , LKML , Dave Jones Subject: Re: tracing: NULL ptr deref in ring_buffer_wait Message-ID: <20140505104712.11c63a5d@gandalf.local.home> In-Reply-To: <5366DFBF.6090204@oracle.com> References: <5366DFBF.6090204@oracle.com> X-Mailer: Claws Mail 3.9.3 (GTK+ 2.24.22; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-RR-Connecting-IP: 107.14.168.142:25 X-Cloudmark-Score: 0 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Sun, 04 May 2014 20:47:59 -0400 Sasha Levin 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 > [ 3589.407670] CR2: 00000000000001f0 Is this easily reproducible? Thanks, -- Steve