Skip to contentSkip to conversation

NULL pointer dereference in 3.7-rc7 (syscall_trace_enter)

BUG Ian Kumlien 2 participants 8 messages Nov 28, 2012 – Nov 30, 2012

lore
Share & tools
lore
#1 lore raw
Quoted 9 lines · Ian Kumlien

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.

Signature · 2 lines
Regards/Gruss,
    Boris.
author
#2 lore raw
Quoted 6 lines · Borislav Petkov
Quoted 5 lines · Ian Kumlien

Hi,

Due to unexplained dns problems, I'll be using google plus to post the photo of the bug output.

Quoted 6 lines
Quoted 4 lines

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

Quoted 4 lines

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

---

Quoted 5 lines

Thanks.

Signature · 2 lines
Regards/Gruss,
    Boris.
#3 lore raw
Quoted 2 lines · Ian Kumlien

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.

Quoted 33 lines
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
Quoted 5 lines

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.

Signature · 2 lines
Regards/Gruss,
    Boris.
author
#4 lore raw
Quoted 5 lines · Borislav Petkov
Quoted 2 lines · Ian Kumlien

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

Quoted 3 lines

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... =)

Quoted 30 lines
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.

Quoted 5 lines

Can you do:

make arch/x86/kernel/ptrace.lst

and send me that file, privately is fine too.

Done, =)

Quoted 5 lines

Thanks.

Signature · 2 lines
Regards/Gruss,
    Boris.
#5 lore raw
Quoted 7 lines · Ian Kumlien
Quoted 5 lines

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.

Quoted 1 line

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.

Signature · 2 lines
Regards/Gruss,
    Boris.
author
#6 lore raw
Quoted 57 lines · Borislav Petkov
Quoted 7 lines · Ian Kumlien
Quoted 5 lines

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.

Quoted 7 lines

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 =)

Quoted 3 lines

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?

Quoted 3 lines

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

Quoted 4 lines

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

Quoted 2 lines

Thanks.

Signature · 1 line
Ian Kumlien  -- http://demius.net || http://pomac.netswarm.net
#7 lore raw
Quoted 5 lines · Ian Kumlien
Quoted 3 lines

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.

Quoted 6 lines
Quoted 3 lines

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.

Quoted 6 lines
Quoted 4 lines

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.

Signature · 2 lines
Regards/Gruss,
    Boris.