Hi,
Due to unexplained dns problems, I'll be using google plus to post the
photo of the bug output.
https://plus.google.com/photos/110698868656495230656/albums/5816005854482735041
I'm sorry but my knowledge is limited and current caffeine level is low,
so I'm offloading to someone who has these things handled ;)
--
Ian Kumlien -- http://demius.net || http://pomac.netswarm.net
On Thu, Nov 29, 2012 at 12:20:02AM +0100, Ian Kumlien wrote:
> Hi,
>
> Due to unexplained dns problems, I'll be using google plus to post the
> photo of the bug output.
>
> https://plus.google.com/photos/110698868656495230656/albums/5816005854482735041
>
> I'm sorry but my knowledge is limited and current caffeine level is low,
> so I'm offloading to someone who has these things handled ;)
Hmm, this looks strange, were you doing any system tracing or similar?
How reproducible is this? If you can reliably reproduce it, can you
make a much more readable screen photo of it so that one can read all
register values and the "Code:" section in the backtrace is complete and
also readable?
Thanks.
--
Regards/Gruss,
Boris.
On Thu, Nov 29, 2012 at 10:26:21AM +0100, Borislav Petkov wrote:
> On Thu, Nov 29, 2012 at 12:20:02AM +0100, Ian Kumlien wrote:
> > Hi,
> >
> > Due to unexplained dns problems, I'll be using google plus to post the
> > photo of the bug output.
> >
> > https://plus.google.com/photos/110698868656495230656/albums/5816005854482735041
> >
> > I'm sorry but my knowledge is limited and current caffeine level is low,
> > so I'm offloading to someone who has these things handled ;)
>
> Hmm, this looks strange, were you doing any system tracing or similar?
I think that chrome does traceing all the time as a part of it's sandbox
- this is most likely chrome monitoring flash...
> How reproducible is this? If you can reliably reproduce it, can you
> make a much more readable screen photo of it so that one can read all
> register values and the "Code:" section in the backtrace is complete and
> also readable?
I can't say, it's the first kernel bug i have in quite a while - I guess
time will tell.
It seems like google plus worsened the image quality and i had another
picture to go by as well, so i peiced them together in to the following
information - Now if i just had the energy to disable the wraparound in
vim....
---
BUG: unable to handle kernel NULL pointer dereference at
0000000000000063
IP: [<ffffffff8100b64b>] syscall_trace_enter+0x15e/0x191
PGD 0
Oops: 0000 [#1] PREEMPT SMP
Modules linked in: snd_usb_audio snd_usbmidi_lib nouveau mxm_wmi wmi
i2x_algo_bit ttm drm_kms_helper drm
CPU 0
Pid: 24590, comm: chrome Not tainted 3.7.0-rc7 #50 System manufacturer
System Product Name/A8N32-SLI-Deluxe
RIP: 0010:[<ffffffff8100b64b>] [<ffffffff8100b64b>]
syscall_trace_enter+0x15e/0x191
RSP: 0018:ffff8800058e3f38 EFLAGS: 00010206
RAX: 0000000000000081 RBX: ffff8800058e3f58 RCX: 0000000000000063
RDX: 00007fe1f2fbde18 RSI: 00000000000000ca RDI: 00007fe1f2fbde18
RBP: 0000000000000000 R08: 0000000000000001 R09: 00007fe23f9fcb10
R10: 00007fe23f9fcb10 R11: 0000000000000206 R12: 0000000000000032
R13: 00007fe23f9fd9c0 R14: 00007fe25d743710 R15: 0000000000000007
FS: 00007fe23f9fd700(0000) GS:ffff88013fc00000(0000)
knlGS:00000000f5c88740
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000063 CR3: 0000000083a84000 CR4: 00000000000007f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process chrome (pid: 24590, threadinfo ffff8800058e2000, task
ffff88003dacd3b0)
Stack:
00007fe1f2fbde10 0000000000000001 0000000000000032 ffffffff8160646c
0000000000000007 00007fe25d743710 00007fe23f9fd9c0 0000000000000032
0000000000000001 00007fe1f2fbde10 0000000000000206 00007fe23f9fcb10
Call Trace:
[<ffffffff8160646c>] ? tracesys+0x7e/0xe2
Code: 53 28 48 85 ff 74 29 83 3f 00 75 24 eb 37 65 48 8b 0c 25 80 b8 00
00 48 8b 89 c0 04 00 00 4c 8b 4b 38 48 8b 53 70 48 85 c9 74 08 <83> 39
00 74 1f 48 83 ca ff 48 85 ed 75 04 48 8b 53 78 5b 5d 48
RIP [<ffffffff8100b64b>] syscall_trace_eneter+0x15e/0x191
RSP <ffff8800058e3f38>
CR2: 0000000000000063
---
> Thanks.
>
> --
> Regards/Gruss,
> Boris.
On Thu, Nov 29, 2012 at 01:27:08PM +0100, Ian Kumlien wrote:
> I think that chrome does traceing all the time as a part of it's
> sandbox - this is most likely chrome monitoring flash...
Ah, ok.
> BUG: unable to handle kernel NULL pointer dereference at
> 0000000000000063
> IP: [<ffffffff8100b64b>] syscall_trace_enter+0x15e/0x191
> PGD 0
> Oops: 0000 [#1] PREEMPT SMP
> Modules linked in: snd_usb_audio snd_usbmidi_lib nouveau mxm_wmi wmi
> i2x_algo_bit ttm drm_kms_helper drm
> CPU 0
> Pid: 24590, comm: chrome Not tainted 3.7.0-rc7 #50 System manufacturer
> System Product Name/A8N32-SLI-Deluxe
> RIP: 0010:[<ffffffff8100b64b>] [<ffffffff8100b64b>]
> syscall_trace_enter+0x15e/0x191
> RSP: 0018:ffff8800058e3f38 EFLAGS: 00010206
> RAX: 0000000000000081 RBX: ffff8800058e3f58 RCX: 0000000000000063
> RDX: 00007fe1f2fbde18 RSI: 00000000000000ca RDI: 00007fe1f2fbde18
> RBP: 0000000000000000 R08: 0000000000000001 R09: 00007fe23f9fcb10
> R10: 00007fe23f9fcb10 R11: 0000000000000206 R12: 0000000000000032
> R13: 00007fe23f9fd9c0 R14: 00007fe25d743710 R15: 0000000000000007
> FS: 00007fe23f9fd700(0000) GS:ffff88013fc00000(0000)
> knlGS:00000000f5c88740
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000000000063 CR3: 0000000083a84000 CR4: 00000000000007f0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> Process chrome (pid: 24590, threadinfo ffff8800058e2000, task
> ffff88003dacd3b0)
> Stack:
> 00007fe1f2fbde10 0000000000000001 0000000000000032 ffffffff8160646c
> 0000000000000007 00007fe25d743710 00007fe23f9fd9c0 0000000000000032
> 0000000000000001 00007fe1f2fbde10 0000000000000206 00007fe23f9fcb10
> Call Trace:
> [<ffffffff8160646c>] ? tracesys+0x7e/0xe2
> Code: 53 28 48 85 ff 74 29 83 3f 00 75 24 eb 37 65 48 8b 0c 25 80 b8 00
> 00 48 8b 89 c0 04 00 00 4c 8b 4b 38 48 8b 53 70 48 85 c9 74 08 <83> 39
> 00 74 1f 48 83 ca ff 48 85 ed 75 04 48 8b 53 78 5b 5d 48
> RIP [<ffffffff8100b64b>] syscall_trace_eneter+0x15e/0x191
> RSP <ffff8800058e3f38>
> CR2: 0000000000000063
Right, so I can get the code now where it happens, but it is pretty
unreliable to map it to what my compiler generates here (of course,
different compilers and hardware):
Code: 53 28 48 85 ff 74 29 83 3f 00 75 24 eb 37 65 48 8b 0c 25 80 b8 00 00 48 8b 89 c0 04 00 00 4c 8b 4b 38 48 8b 53 70 48 85 c9 74 08 <83> 39 00 74 1f 48 83 ca ff 48 85 ed 75 04 48 8b 53 78 5b 5d 48
All code
========
0: 53 push %rbx
1: 28 48 85 sub %cl,-0x7b(%rax)
4: ff 74 29 83 pushq -0x7d(%rcx,%rbp,1)
8: 3f (bad)
9: 00 75 24 add %dh,0x24(%rbp)
c: eb 37 jmp 0x45
e: 65 48 8b 0c 25 80 b8 mov %gs:0xb880,%rcx
15: 00 00
17: 48 8b 89 c0 04 00 00 mov 0x4c0(%rcx),%rcx
1e: 4c 8b 4b 38 mov 0x38(%rbx),%r9
22: 48 8b 53 70 mov 0x70(%rbx),%rdx
26: 48 85 c9 test %rcx,%rcx
29: 74 08 je 0x33
2b:* 83 39 00 cmpl $0x0,(%rcx) <-- trapping instruction
2e: 74 1f je 0x4f
30: 48 83 ca ff or $0xffffffffffffffff,%rdx
34: 48 85 ed test %rbp,%rbp
37: 75 04 jne 0x3d
39: 48 8b 53 78 mov 0x78(%rbx),%rdx
3d: 5b pop %rbx
3e: 5d pop %rbp
3f: 48 rex.W
So we oops when we try to deref 0x63 which is, of course, not a valid
pointer. The question is, what exactly is that thing in rcx. It looks
like a percpu variable to me but I'm not sure.
Can you do:
make arch/x86/kernel/ptrace.lst
and send me that file, privately is fine too.
Thanks.
--
Regards/Gruss,
Boris.
On Thu, Nov 29, 2012 at 03:22:20PM +0100, Borislav Petkov wrote:
> On Thu, Nov 29, 2012 at 01:27:08PM +0100, Ian Kumlien wrote:
> > I think that chrome does traceing all the time as a part of it's
> > sandbox - this is most likely chrome monitoring flash...
>
> Ah, ok.
[ --8<--8<-- ]
> Right, so I can get the code now where it happens, but it is pretty
> unreliable to map it to what my compiler generates here (of course,
> different compilers and hardware):
Yeah i know... =)
> Code: 53 28 48 85 ff 74 29 83 3f 00 75 24 eb 37 65 48 8b 0c 25 80 b8 00 00 48 8b 89 c0 04 00 00 4c 8b 4b 38 48 8b 53 70 48 85 c9 74 08 <83> 39 00 74 1f 48 83 ca ff 48 85 ed 75 04 48 8b 53 78 5b 5d 48
> All code
> ========
> 0: 53 push %rbx
> 1: 28 48 85 sub %cl,-0x7b(%rax)
> 4: ff 74 29 83 pushq -0x7d(%rcx,%rbp,1)
> 8: 3f (bad)
> 9: 00 75 24 add %dh,0x24(%rbp)
> c: eb 37 jmp 0x45
> e: 65 48 8b 0c 25 80 b8 mov %gs:0xb880,%rcx
> 15: 00 00
> 17: 48 8b 89 c0 04 00 00 mov 0x4c0(%rcx),%rcx
> 1e: 4c 8b 4b 38 mov 0x38(%rbx),%r9
> 22: 48 8b 53 70 mov 0x70(%rbx),%rdx
> 26: 48 85 c9 test %rcx,%rcx
> 29: 74 08 je 0x33
> 2b:* 83 39 00 cmpl $0x0,(%rcx) <-- trapping instruction
> 2e: 74 1f je 0x4f
> 30: 48 83 ca ff or $0xffffffffffffffff,%rdx
> 34: 48 85 ed test %rbp,%rbp
> 37: 75 04 jne 0x3d
> 39: 48 8b 53 78 mov 0x78(%rbx),%rdx
> 3d: 5b pop %rbx
> 3e: 5d pop %rbp
> 3f: 48 rex.W
>
> So we oops when we try to deref 0x63 which is, of course, not a valid
> pointer. The question is, what exactly is that thing in rcx. It looks
> like a percpu variable to me but I'm not sure.
>
> Can you do:
>
> make arch/x86/kernel/ptrace.lst
>
> and send me that file, privately is fine too.
Done, =)
> Thanks.
>
> --
> Regards/Gruss,
> Boris.
On Thu, Nov 29, 2012 at 05:24:03PM +0100, Ian Kumlien wrote:
> > Can you do:
> >
> > make arch/x86/kernel/ptrace.lst
> >
> > and send me that file, privately is fine too.
>
> Done, =)
Ok, thanks. Here it is:
ffffffff8100b627: 83 3f 00 cmpl $0x0,(%rdi)
ffffffff8100b62a: 75 24 jne ffffffff8100b650 <syscall_trace_enter+0x163>
ffffffff8100b62c: eb 37 jmp ffffffff8100b665 <syscall_trace_enter+0x178>
ffffffff8100b62e: 65 48 8b 0c 25 00 00 mov %gs:0x0,%rcx
ffffffff8100b635: 00 00
ffffffff8100b633: R_X86_64_32S current_task
extern void __audit_seccomp(unsigned long syscall, long signr, int code);
extern void __audit_ptrace(struct task_struct *t);
static inline int audit_dummy_context(void)
{
void *p = current->audit_context;
ffffffff8100b637: 48 8b 89 c0 04 00 00 mov 0x4c0(%rcx),%rcx
regs->orig_ax,
regs->bx, regs->cx,
regs->dx, regs->si);
#ifdef CONFIG_X86_64
else
audit_syscall_entry(AUDIT_ARCH_X86_64,
ffffffff8100b63e: 4c 8b 4b 38 mov 0x38(%rbx),%r9
ffffffff8100b642: 48 8b 53 70 mov 0x70(%rbx),%rdx
return !p || *(int *)p;
ffffffff8100b646: 48 85 c9 test %rcx,%rcx
ffffffff8100b649: 74 05 je ffffffff8100b650 <syscall_trace_enter+0x163>
ffffffff8100b64b: 83 39 00 cmpl $0x0,(%rcx)
ffffffff8100b64e: 74 1f je ffffffff8100b66f <syscall_trace_enter+0x182>
regs->di, regs->si,
regs->dx, regs->r10);
#endif
out:
return ret ?: regs->orig_ax;
ffffffff8100b650: 48 83 ca ff or $0xffffffffffffffff,%rdx
ffffffff8100b654: 48 85 ed test %rbp,%rbp
ffffffff8100b657: 75 04 jne ffffffff8100b65d <syscall_trace_enter+0x170>
ffffffff8100b659: 48 8b 53 78 mov 0x78(%rbx),%rdx
}
ffffffff8100b65d: 5b pop %rbx
ffffffff8100b65e: 5d pop %rbp
ffffffff8100b65f: 48 89 d0 mov %rdx,%rax
ffffffff8100b662: 41 5c pop %r12
ffffffff8100b664: c3 retq
We're calling audit_syscall_entry() for a 64-bit task (chrome) and we
check whether the audit context of the task is not a dummy one.
We fail at the second check in
return !p || *(int *)p;
when we're trying to deref the ->audit_context pointer of current and
then check it for being 0 in audit_syscall_entry. It turns out it is
some random crap, as we saw already: RCX=0000000000000063.
>From looking at the code, task audit contexts get normally allocated
at fork time and dealloc'd at task exit time so your process should
actually have a valid task context.
The only explanation I have is that it could be some random corruption
which f*cked up the ->audit_context pointer but I might be wrong. Btw,
do you have CONFIG_AUDITSYSCALL enabled in your kernel?
I'd say right now we could watch this and if it is reproducible, then
we can involve some more brain power and skills into it. If it has been
only a single occurrence, then we'll write it on the random corruption's
tab.
Thanks.
--
Regards/Gruss,
Boris.
On tor, 2012-11-29 at 20:25 +0100, Borislav Petkov wrote:
> On Thu, Nov 29, 2012 at 05:24:03PM +0100, Ian Kumlien wrote:
> > > Can you do:
> > >
> > > make arch/x86/kernel/ptrace.lst
> > >
> > > and send me that file, privately is fine too.
> >
> > Done, =)
>
> Ok, thanks. Here it is:
>
> ffffffff8100b627: 83 3f 00 cmpl $0x0,(%rdi)
> ffffffff8100b62a: 75 24 jne ffffffff8100b650 <syscall_trace_enter+0x163>
> ffffffff8100b62c: eb 37 jmp ffffffff8100b665 <syscall_trace_enter+0x178>
> ffffffff8100b62e: 65 48 8b 0c 25 00 00 mov %gs:0x0,%rcx
> ffffffff8100b635: 00 00
> ffffffff8100b633: R_X86_64_32S current_task
> extern void __audit_seccomp(unsigned long syscall, long signr, int code);
> extern void __audit_ptrace(struct task_struct *t);
>
> static inline int audit_dummy_context(void)
> {
> void *p = current->audit_context;
> ffffffff8100b637: 48 8b 89 c0 04 00 00 mov 0x4c0(%rcx),%rcx
> regs->orig_ax,
> regs->bx, regs->cx,
> regs->dx, regs->si);
> #ifdef CONFIG_X86_64
> else
> audit_syscall_entry(AUDIT_ARCH_X86_64,
> ffffffff8100b63e: 4c 8b 4b 38 mov 0x38(%rbx),%r9
> ffffffff8100b642: 48 8b 53 70 mov 0x70(%rbx),%rdx
> return !p || *(int *)p;
> ffffffff8100b646: 48 85 c9 test %rcx,%rcx
> ffffffff8100b649: 74 05 je ffffffff8100b650 <syscall_trace_enter+0x163>
> ffffffff8100b64b: 83 39 00 cmpl $0x0,(%rcx)
> ffffffff8100b64e: 74 1f je ffffffff8100b66f <syscall_trace_enter+0x182>
> regs->di, regs->si,
> regs->dx, regs->r10);
> #endif
>
> out:
> return ret ?: regs->orig_ax;
> ffffffff8100b650: 48 83 ca ff or $0xffffffffffffffff,%rdx
> ffffffff8100b654: 48 85 ed test %rbp,%rbp
> ffffffff8100b657: 75 04 jne ffffffff8100b65d <syscall_trace_enter+0x170>
> ffffffff8100b659: 48 8b 53 78 mov 0x78(%rbx),%rdx
> }
> ffffffff8100b65d: 5b pop %rbx
> ffffffff8100b65e: 5d pop %rbp
> ffffffff8100b65f: 48 89 d0 mov %rdx,%rax
> ffffffff8100b662: 41 5c pop %r12
> ffffffff8100b664: c3 retq
>
> We're calling audit_syscall_entry() for a 64-bit task (chrome) and we
> check whether the audit context of the task is not a dummy one.
>
> We fail at the second check in
>
> return !p || *(int *)p;
>
> when we're trying to deref the ->audit_context pointer of current and
> then check it for being 0 in audit_syscall_entry. It turns out it is
> some random crap, as we saw already: RCX=0000000000000063.
Yep, actually gathered that from the disassembly =)
> From looking at the code, task audit contexts get normally allocated
> at fork time and dealloc'd at task exit time so your process should
> actually have a valid task context.
Weird, and this should be allocated automatically?
> The only explanation I have is that it could be some random corruption
> which f*cked up the ->audit_context pointer but I might be wrong. Btw,
> do you have CONFIG_AUDITSYSCALL enabled in your kernel?
grep CONFIG_AUDITSYSCALL .config
CONFIG_AUDITSYSCALL=y
> I'd say right now we could watch this and if it is reproducible, then
> we can involve some more brain power and skills into it. If it has been
> only a single occurrence, then we'll write it on the random corruption's
> tab.
Uhmmm oki
> Thanks.
>
--
Ian Kumlien -- http://demius.net || http://pomac.netswarm.net
On Fri, Nov 30, 2012 at 12:56:08AM +0100, Ian Kumlien wrote:
> > From looking at the code, task audit contexts get normally allocated
> > at fork time and dealloc'd at task exit time so your process should
> > actually have a valid task context.
>
> Weird, and this should be allocated automatically?
Yes, during task creation in copy_process we do audit_alloc and in
do_exit() we do audit_free.
> > The only explanation I have is that it could be some random corruption
> > which f*cked up the ->audit_context pointer but I might be wrong. Btw,
> > do you have CONFIG_AUDITSYSCALL enabled in your kernel?
>
> grep CONFIG_AUDITSYSCALL .config
> CONFIG_AUDITSYSCALL=y
Ok.
> > I'd say right now we could watch this and if it is reproducible, then
> > we can involve some more brain power and skills into it. If it has been
> > only a single occurrence, then we'll write it on the random corruption's
> > tab.
>
> Uhmmm oki
Right, so thinking purely hypothetically I can imagine that there might
be some small window where we're in the process of freeing the audit
context during task exit and we issue a syscall which gets traced and we
end up in the audit_syscall_entry but AFAICT when we free the context,
we do get it and do tsk->audit_context = NULL which cannot explain the
funny ECX value. Hmm, strange.
But it doesn't bring a whole lot in us conjecturing what has happened if
this cannot be reliably reproduced so please watch your box and be on
alert for similar oopses and the steps you've made to cause them.
Thanks.
--
Regards/Gruss,
Boris.