捉虫日记 0005: kernel panic, no oops, no stack dumped
1 Phenomenon
Update emma3p to 2.6.26, kernel hang after mounting rootfs, following is the log:
........................
8139too Fast Ethernet driver 0.9.28
eth0: RealTek RTL8139 at 0xb4001100, 12:34:56:78:9a:bb, IRQ 147
mice: PS/2 mouse device common for all mice
TCP cubic registered
NET: Registered protocol family 17
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
eth0: link up, 100Mbps, full-duplex, lpa 0xC5E1
Sending DHCP requests ., OK
IP-Config: Got DHCP answer from 192.168.29.11, my address is 192.168.29.243
IP-Config: Complete:
device=eth0, addr=192.168.29.243, mask=255.255.255.0, gw=192.168.29.1,
host=nec_emmap3p-1, domain=tuxlab.wrs.com, nis-domain=swamp,
bootserver=192.168.29.11, rootserver=192.168.29.11, rootpath=/export/pxeboot/vlm-boards/14726/rootfs
Looking up port of RPC 100003/2 on 192.168.29.11
Looking up port of RPC 100005/1 on 192.168.29.11
VFS: Mounted root (nfs filesystem).
Freeing unused kernel memory: 168k freed
Kernel panic - not syncing: Attempted to kill init!
Rebooting in 50 seconds..
2 Analysis
[4/7/08]: Added printk to investigate the issue function and found that the issue function is run_init_process("/sbin/init"), following is the log:
........................
Looking up port of RPC 100003/2 on 192.168.29.11
Looking up port of RPC 100005/1 on 192.168.29.11
VFS: Mounted root (nfs filesystem).
kernel_init: before init_post
Freeing unused kernel memory: 168k freed
before unlock_kernel()
before mark_rodata_ro()
before numa_default_policy()
before run_init_process("/sbin/init")
Kernel panic - not syncing: Attempted to kill init!
Rebooting in 50 seconds..
Backport KGDBoS to 2.6.26 and use it to trace the kernel. I found that init process(pid=1) received a SIGTRAP signal but I did not determine who send this signal and why it send this signal?
[7/7/08]: Add dump_stack() into panic() [within kernel/panic.c:62], and get following log:
........................ Call Trace: [<8004936c>] dump_stack+0x8/0x34 [<80069490>] panic+0x30/0x1c0 [<8006e790>] do_exit+0x774/0x7fc [<8006e864>] do_group_exit+0x4c/0x100 [<8007c2dc>] get_signal_to_deliver+0x268/0x4f8 [<800457dc>] do_notify_resume+0x90/0x458 [<800420c0>] work_notifysig+0xc/0x14 Kernel panic - not syncing: Attempted to kill init! Rebooting in 50 seconds..EMMA3P ET10068 restart.
Check the [kernel/signal.c] and found that someone can call following function to send a signal:
send_sig()
force_sig()
So, I add extra code like following:
int send_sig(int sig, struct task_struct *p, int priv)
{
printk("<0> xxxxxx In send_sig signum = %d xxxxxxx\n", sig);
printk("<0> current pid is %d, target pid is %d\n", current->pid, p->pid);
dump_stack();
return send_sig_info(sig, __si_special(priv), p);
}
void force_sig(int sig, struct task_struct *p)
{
printk("<0> xxxxxx In force_sig signum = %d xxxxxxx\n", sig);
printk("<0> current pid is %d, target pid is %d\n", current->pid, p->pid);
dump_stack();
force_sig_info(sig, SEND_SIG_PRIV, p);
}
and then got following log:
........................ xxxxxx In force_sig signum = 4 xxxxxxx current pid is 1, target pid is 1 Call Trace: [<8004936c>] dump_stack+0x8/0x34 [<8007adfc>] force_sig+0x48/0x68 [<80041ec4>] ret_from_exception+0x0/0x10 ........................
There is no log message about send_sig. So the flow is that:
Signal send: exception ---> ret_from_execption ---> ... ---> force_sig(SIGILL, init_tast_struct) ==> In this point, current->thread_info->regs is NULL!
Signal processing: exception ---> work_notifysig ---> do_notify_resume() ---> do_signal() ---> get_signal_to_deliver() ---> ... ---> panic()
So, add following function beforce the get_signal_to_deliver():
show_registers(regs);
dump_tlb_all();
then, we can get following log message:
Cpu 0
$ 0 : 00000000 fffffff8 321fdfb8 00000000
$ 4 : ffff902c 00000020 320bbae4 00000006
$ 8 : 320ad548 81010100 320bbae4 00000000
$12 : 7ffec568 00000000 2aaa8950 00000050
$16 : 32201b58 32200000 321ff0a0 32376524
$20 : 7ffecc34 00000002 32380000 00000002
$24 : 0000536d 32080988
$28 : 32207960 7ffeca58 32370000 32120c78
Hi : 00000000
Lo : 00000019
epc : 32120a2c 0x32120a2c Not tainted
ra : 32120c78 0x32120c78
Status: 80008413 USER EXL IE
Cause : 2000002c -----------> CpErr=2, ExcCode = 11(CpU), CU2 is unavailable
PrId : 00005610 (R9721)
Modules linked in:
Process init (pid: 1, threadinfo=8a018000, task=8a017b40, tls=2aab0a80)
Stack : 00000000 00000000 00000000 00000000 32207960 00000000 2aaa8950 2aaa8940
320b0000 00000000 00000000 320801b4 00000168 32375ba8 00000000 32376524
7ffecc34 00000002 32380000 00000002 32370000 321247dc 00000000 32376524
7ffecc34 00000002 32207960 32370000 32386fdc 3210c750 00000000 00000000
00000000 00000000 320801cc 00000000 32207960 320801d4 32386fdc ffffffff
...
Call Trace:
(Bad stack address)
Code: ac620000 8f84948c 8f828728 <7c03e83b> 00832021 2623170c ac830000 8f8586c4 8f8486c4
Index: 0 pgmask=4kb va=320b2000 asid=01
[pa=00000000 c=0 d=0 v=0 g=0] [pa=00544000 c=3 d=0 v=1 g=0]
......
Index: 58 pgmask=4kb va=32120000 asid=01
[pa=0051b000 c=3 d=0 v=1 g=0] [pa=00000000 c=0 d=0 v=0 g=0]
Index: 59 pgmask=4kb va=32128000 asid=01
[pa=00502000 c=3 d=0 v=1 g=0] [pa=00501000 c=3 d=0 v=1 g=0]
......
That's to say cpu execute a CU2 instruction (machine code is 7c03e83b) at virtual addr 0x32120a2c which is mapped to phy addr 0x0051ba2c !! So far, there is no CU2 instruction in MIPS ISA. This is absurd!! I think the init process's address space is destroyed by some other guys.
[7/7/08 21:00]: Add watchpoint at 0x0051ba28 get following log:
Got watch at 801ff5b8
Cpu 0
$ 0 : 00000000 90008400 3927ab84 00000001
$ 4 : 8a1e9514 8051ba1c 000000c8 00000000
$ 8 : 2442fd1c ac620000 8f84948c 8f828728
$12 : 7c03e83b 00832021 2623170c ac830000
$16 : 000005c8 00000000 8a04b8b8 00000000
$20 : 000005c8 00ff00ff 8051b55c 80303684
$24 : 00000000 00000000
$28 : 8a018000 8a019b80 804034b4 80265f20
Hi : 00000000
Lo : 00000b80
epc : 801ff5b8 csum_partial_copy_nocheck+0x90/0x3f8 Not tainted
ra : 80265f20 skb_copy_and_csum_bits+0x80/0x368
Status: 90008403 KERNEL EXL IE
Cause : 0000005c
PrId : 00005610 (R9721)
Modules linked in:
Process init (pid: 1, threadinfo=8a018000, task=8a017b40, tls=2aab0a80)
Stack : 8a0cc594 8030a784 803023c4 8a019ca0 8a0cc6e0 803f0000 8a0cc594 803f0000
8a04b8b8 00000000 000005c8 00000aa4 8a04b8b8 000005c8 00000b90 00ff00ff
8051b55c 80303684 804034b4 802660f4 802ff2bc 802ff2bc 89c0bde8 800a7600
00000000 8019d6dc 0000055c 00001000 8a04baf8 0000bc40 0000006c 8a019c90
00001000 8a0cc558 00000064 8a019c90 8a14d08c 80303684 804034b4 803036c8
...
Call Trace:
[<801ff5b8>] csum_partial_copy_nocheck+0x90/0x3f8
[<80265f20>] skb_copy_and_csum_bits+0x80/0x368
[<802660f4>] skb_copy_and_csum_bits+0x254/0x368
[<803036c8>] xdr_skb_read_and_csum_bits+0x44/0xbc
[<803032d4>] xdr_partial_copy_from_skb+0xd4/0x290
[<803034fc>] csum_partial_copy_to_xdr+0x6c/0x17c
[<80306964>] xs_udp_data_ready+0x118/0x264
[<8026249c>] sock_queue_rcv_skb+0x100/0x1ac
[<802c3080>] udp_queue_rcv_skb+0xd8/0x37c
[<802c3bd4>] __udp4_lib_rcv+0x8b0/0xab8
[<8029aa88>] ip_local_deliver_finish+0x124/0x2e8
[<8029a514>] ip_rcv_finish+0x144/0x594
[<8026f040>] netif_receive_skb+0x328/0x56c
[<80249888>] rtl8139_poll+0x2ac/0x584
[<8027280c>] net_rx_action+0x16c/0x32c
[<80070f18>] __do_softirq+0xc8/0x194
[<80071098>] do_softirq+0xb4/0xe4
[<80071714>] irq_exit+0x64/0x74
[<80041ec0>] ret_from_irq+0x0/0x4
It seems like that rtl8139 driver use this area as its skb buffer !!!
[7/8/08]: Build a minimize kernel only include platform and serial. network, pci and other subsystem are diabled. Use initrd as the rootfs.
The issue always exist.
Watchpoint catch the point at __copy_user. This function is for copy the data from souce addr to target addr. So setup a watchpoint at souce address. Watchpoint always catch the point at __copy_user and the dumped stack has no obviously useful information.
Try a lot of times and found that the code is always <7c03e83b>.
[7/8/08 20:00]: Try to backtrace the kernel evolvement from 2.6.26-rc6
2.6.24-stable: issue exist
2.6.24-rc1: issue exist
2.6.23.17: all is ok!
diff the 2.6.24-rc1 and 2.6.23.17 and found a great deal of changes between these two versions.
[7/9/08]: Try to exclude the cache causes.
And found that sinc 2.6.24, kernel remove the CONFIG_MIPS_UNCACHED and add a comman line argument 'cca'. So we can specify the cca=2 to make the kernel run in uncachable mode.
With uncachable the issue is always exist.
[7/9/08 19:20]: objdump INITRD/lib/libc.so.6 and found the code <7c03e83b>. It's rdhwr $29!!
Trace the exception process function do_cpu and found that rdhwr simulation is failed for nec emma3p. When rdhwr simulation is failed the do_cpu will force send a SIGILL signal and this make the kernel try to kill the init process!
3 Solution
Make the simulation properly.
