[BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Ian Kumlien]

[-- Attachment #1: Type: text/plain, Size: 398 bytes --]

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

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Borislav Petkov]

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.

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Ian Kumlien]

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.

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Borislav Petkov]

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.

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Ian Kumlien]

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.

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Borislav Petkov]

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.

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Ian Kumlien]

[-- Attachment #1: Type: text/plain, Size: 4018 bytes --]

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

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [BUG] NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

[Borislav Petkov]

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.