[uml-devel] Diagnosed and repeatable kernel mode panic in schedule() for 2.6!

[BlaisorBlade <blaisorblade_spam@yahoo.it>]

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

While searching the archives, I noticed that this command:

while /bin/true ; do /bin/true ; done

created some problems (task_struct leak and OOM) time ago (at least until 
2.6.0-test2, more or less). See "Re: [uml-devel] oops and memory leak with 
uml-patch-2.5.67-1".

I've rerun this command under a 2.6.2 with my patch collection (but with the 
/proc/meminfo bug, i.e. MemTotal = 0) and host 2.4.24-skas (which contains 
the Ingo Molnar's fixlet about LDT loading) and got, instead, this:

Kernel panic: Kernel mode fault at addr 0x1f, ip 0x400d1397
Kernel panic: kernel BUG at kernel/exit.c:793!

And then the kernel exited (even if it tried to trigger some other panics, see 
the end of the attached output). If anyone is able to reproduce the bug, then 
he can go straight debugging, if he doesn't want to read this. I think I 
cannot give you the binary, since I have a 56k modem and it's 6,7Mega even 
compressed (stripping debug symbols is useless for debug). However I could 
try stripping the config and such things, if you absolutely can't reproduce 
it.

The second message is of interest because the BUG line of interest reads as:
  schedule();
  BUG();

and this is fairly interesting. But this report is all a fun: the kernel 
continues to run after a panic call because the call suddenly exited without 
a return (search this message for "sudden"), the runqueue datas are 
inconsistent (maybe because of the memory leak in the above message), we 
don't know where the "array" value comes from (a compiler bug? An error 
in the debugging info? A reused variable? Do you need the gdb disassemble of 
schedule?). Also, since the problems appear in schedule(), this could relate 
with the hang after the "NET: Registered protocol family 2" message, since 
that comes from a not-working wait queue.

Note: in that moment about 10/20 processes were running.

I was able to reproduce both ones under gdb, and I've attached the whole 
debugging session output; here I summarize it, since that output is way too 
long and this is the offending code, inside schedule():

        idx = sched_find_first_bit(array->bitmap);
        queue = array->queue + idx;
        next = list_entry(queue->next, task_t, run_list);

        if (next->activated > 0) { //THIS IS THE LINE!

With gdb, I got this:
(gdb) where
#0  panic (fmt=0xa018f8e0 "Kernel mode fault at addr 0x%lx, ip 0x%lx") at 
include/asm/thread_info.h:49
#1  0xa0018ac8 in segv (address=31, ip=1074598807, is_write=0, 
is_user=1074598807, sc=0xa1e59148)
    at arch/um/kernel/trap_kern.c:167
#2  0xa0018e97 in segv_handler (sig=11, regs=0xa1e59148) at 
arch/um/kernel/trap_user.c:67
#3  0xa001e573 in sig_handler_common_skas (sig=11, sc_ptr=0x58) at 
arch/um/kernel/skas/trap_user.c:33
#4  0xa0018fa0 in sig_handler (sig=0, sc=
      {gs = 0, __gsh = 0, fs = 0, __fsh = 0, es = 43, __esh = 0, ds = 43, 
__dsh = 0, edi = 2694560988, esi = 2716176348, ebp = 2694560956, esp = 
2694560884, ebx = 3, edx = 2687144876, ecx = 4294967267, eax = 140, trapno = 
14, err = 4, eip = 2684545927, cs = 35, __csh = 0, eflags = 66179, 
esp_at_signal = 2694560884, ss = 43, __ssh = 0, fpstate = 0x0, oldmask = 
369106944, cr2 = 31})
    at arch/um/kernel/trap_user.c:103
#5  <signal handler called>
#6  schedule () at kernel/sched.c:1677
#7  0xa0014584 in interrupt_end () at arch/um/kernel/process_kern.c:138
#8  0xa001d498 in userspace (regs=0xa1e59148) at 
arch/um/kernel/skas/process.c:174
#9  0xa001dd54 in fork_handler (sig=10) at 
arch/um/kernel/skas/process_kern.c:103
#10 <signal handler called>
#11 0xa01559dd in syscall () at include/linux/slab.h:92
#12 0xa002cd76 in os_usr1_process (pid=26614) at arch/um/os-Linux/process.c:96
#13 0xa001d53f in new_thread (stack=Cannot access memory at address 0x8
) at arch/um/kernel/skas/process.c:197
Previous frame inner to this frame (corrupt stack?)

(gdb) print next
$2 = (task_t *) 0xffffffe3
(gdb) print &next->activated
$3 = (int *) 0x1f (the address in the fault message)

(gdb) print array
$4 = (prio_array_t *) 0x3

(gdb) print rq
No symbol "rq" in current context.

Contents of this_rq are in the attached debug session log.

Also, in the panic call, I discovered that current->pid was 99, and that is 
the father of the true processes:

root [~: slack90: 6 (0)] # ps -ef
...
root        99     1  0  1997 tty1     00:00:01 -bash
root       100     1  0  1997 tty6     00:00:00 -bash
root       383    99  0  1997 tty1     00:00:00 /bin/true

About array = 0x3, I would point to someone else getting the same problem:
"[uml-devel] wait queues broken?" (but there, array was NULL).

While going on in the panic call, all of a sudden (maybe after 
local_irq_enable, which on UML is unblock_signals() ) I got to this point, 
and then to the BUG() call above (missing details are in the attached 
output):

(gdb) next
69                      sys_sync();
(gdb) next
thread_wait (sw=0xa001d578, fb=0xa09bb554) at 
arch/um/kernel/skas/process.c:210
210     }
(gdb) where
#0  thread_wait (sw=0xa001d578, fb=0xa09bb554) at 
arch/um/kernel/skas/process.c:210
#1  0xa001dd07 in fork_handler (sig=10) at 
arch/um/kernel/skas/process_kern.c:94
#2  <signal handler called>
#3  0xa01559dd in syscall () at include/linux/slab.h:92
Previous frame inner to this frame (corrupt stack?)

Then, it seems that running notifier_chan_list called some function that 
sleeped and that the calls to scheduled panicked and then tended to loop 
infinitely (at least, until I debugged it; when doing continue, finally the 
program exited).

Hope you have fun figuring it out!
-- 
Paolo Giarrusso, aka Blaisorblade
Linux registered user n. 292729







[-- Attachment #2: debugOutput.bz2 --]
[-- Type: application/x-bzip2, Size: 12034 bytes --]