new kernel oops in recent kernels

Hi all,
testing latest kernels on SGI O2, I found this new kernel oops. It has been produced with kernel from linux-mips.org git of yesterday night. A very similar oops has been reported by others[0] using 2.6.22.

As you may see, the oops happens while booting the machine, when init run all scripts via rc. One of those scripts run hald-probe-storage, the process that actually create the oops.

I am not able to identify the cause nor to propose a solution, but I am willing to test any patch for this problem.

Thanks a lot,
Giuseppe

CPU 0 Unable to handle kernel paging request at virtual address 0000000000000000, epc == 0000000000000000, ra == 0000000000000000 Oops[#1]:
Cpu 0

$ 0   : 0000000000000000 ffffffff9001fce0 ffffffffffffff86 0000000000000028
$ 4   : 980000000fc01140 0000000000000080 0000000000024000 0000000000000000
$ 8   : 980000000fc54700 0000000000000001 0000000000008000 404000130a0808ff
$12   : 0000000000000008 ffffffff801b8db8 0000000000000000 ffffffff803f0000
$16   : 980000000ff2fa70 980000000c417bb8 980000000c417c20 980000000fdeb610
$20   : 000000007fffffff 980000000f9211a0 980000000fc26000 000000007fa51ecd
$24   : 0000000000000000 ffffffff80074290                                  
$28   : 980000000c414000 980000000c417bb0 0000000000400000 0000000000000000
Hi    : 0000000000000000
Lo    : 003d08dbda057200
epc   : 0000000000000000 0x0     Not tainted
ra    : 0000000000000000 0x0
Status: 9001fce3    KX SX UX KERNEL EXL IE 
Cause : 00000008
BadVA : 0000000000000000
PrId  : 00002321 (R5000)
Modules linked in: parport_pc lp parport ipv6 deflate zlib_deflate ctr twofish twofish_common camellia serpent blowfish des_generic cbc aes_generic xcbc sha25
6_generic sha1_generic crypto_null crypto_blkcipher dm_snapshot dm_mirror dm_mod ehci_hcd ohci_hcd r8169 usbcore sg evdev
Process hald-probe-stor (pid: 1937, threadinfo=980000000c414000, task=980000000ebf47d8)
Stack : 980000000c417be0 980000000c417de0 0800000000000000 980000000c417bb0
        00000008ffffff86 0000000000000000 0200000000000001 000006d600000000
        0000000000000000 980000000c417de0 980000000fdeb610 0000000000000001
        0000000000005326 ffffffff802460b0 0000000070023a00 000000000f9211a0
        ffffffff80490000 ffffffff8024bb84 980000000fc10e80 980000000f80bb28
        0000000000000000 980000000f9210e0 0000010100000001 00000000800d1618
        0000000000000004 980000000fc8f850 000000007fffffff 980000000fde4000
        0000000000005326 000000007fffffff 980000000c407540 980000000f9211a0
        980000000fc26000 000000007fa51ecd ffffffff80245c6c 980000000c407540
        0000000000000000 fffffffffffffdfd 0000000000005326 ffffffff801ad8bc
        ...
Call Trace:
[<ffffffff802460b0>] sr_drive_status+0x50/0xe8
[<ffffffff8024bb84>] cdrom_ioctl+0x5f4/0x1208
[<ffffffff80245c6c>] sr_block_ioctl+0x64/0xe8
[<ffffffff801ad8bc>] compat_blkdev_ioctl+0x7cc/0x18e0
[<ffffffff800d1870>] do_open+0x98/0x310
[<ffffffff800d1d60>] blkdev_open+0x0/0xc0
[<ffffffff800d1da8>] blkdev_open+0x48/0xc0
[<ffffffff8009c444>] __dentry_open+0x114/0x2e0
[<ffffffff8009c740>] do_filp_open+0x48/0x58
[<ffffffff8009c740>] do_filp_open+0x48/0x58
[<ffffffff800def8c>] compat_sys_ioctl+0xf4/0x440
[<ffffffff80019154>] handle_sys+0x114/0x130
[<ffffffff8001fcf3>] fpu_emulator_cop1Handler+0x362/0x2270

Code: (Bad address in epc)

[0]http://lists.debian.org/debian-mips/2008/03/msg00082.html

This is a bit strange. It's obviously O2 specific, which makes it a lot harder. Can you compile the kernel with CONFIG_DEBUG_INFO and reproduce (just in case this changes the symbol layout). Then ask gdb where sr_drive_status+0x50 (or what it moves to) is:

gdb vmlinux
b *(sr_drive_status+0x50)

should identify the file and line.

The signature implies that cdi->handle may be NULL, so you could put in a check for that as well.

Thanks,

James

Hi James,

Il giorno dom, 16/03/2008 alle 11.39 -0500, James Bottomley ha scritto:

[...]

[...]

I cannot find any CONFIG_DEBUG_INFO. Do you mean CONFIG_DEBUG_KERNEL?

Thanks,
Giuseppe

This from lib/Kconfig.debug:

config DEBUG_INFO
bool "Compile the kernel with debug info"
depends on DEBUG_KERNEL
help
If you say Y here the resulting kernel image will include debugging info resulting in a larger kernel image. This adds debug symbols to the kernel and modules (gcc -g), and is needed if you intend to use kernel crashdump or binary object tools like crash, kgdb, LKCD, gdb, etc on the kernel. Say Y here only if you plan to debug the kernel.

If unsure, say N.

It does depend on CONFIG_DEBUG_KERNEL according to the depends clause.

James

I'm not familiar with MIPS; is epc the program counter? If so, this would be a branch to 0. That's somewhat confusing as I don't see any function pointers used within sr_drive_status(). How accurate are MIPS backtraces?

It would be interesting to see a disassembly (objdump -dr drivers/scsi/sr_ioctl.o) of sr_drive_status from say 0x40 to 0x60.

And if that calls a function, it would be interesting to put in printks to figure out where we're dereferencing a null pointer.

Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Hi all,

Il giorno dom, 16/03/2008 alle 10.42 -0600, Matthew Wilcox ha scritto:

[...]

here it is:

(gdb) disassemble sr_drive_status+0x50
Dump of assembler code for function sr_drive_status:
0xffffffff80246060 <sr_drive_status+0>: daddiu sp,sp,-32
0xffffffff80246064 <sr_drive_status+4>: lui v0,0x7fff
0xffffffff80246068 <sr_drive_status+8>: sd s0,16(sp)
0xffffffff8024606c <sr_drive_status+12>: sd ra,24(sp)
0xffffffff80246070 <sr_drive_status+16>: ori v0,v0,0xffff
0xffffffff80246074 <sr_drive_status+20>: move s0,a0
0xffffffff80246078 <sr_drive_status+24>: bne a1,v0,0xffffffff802460e8 <sr_drive_status+136>
0xffffffff8024607c <sr_drive_status+28>: ld v1,24(a0)
0xffffffff80246080 <sr_drive_status+32>: ld a0,16(v1)
0xffffffff80246084 <sr_drive_status+36>: jal 0xffffffff80244c70 <sr_test_unit_ready>
0xffffffff80246088 <sr_drive_status+40>: daddiu a1,sp,4
0xffffffff8024608c <sr_drive_status+44>: bnez v0,0xffffffff802460a8 <sr_drive_status+72>
0xffffffff80246090 <sr_drive_status+48>: move a0,s0
0xffffffff80246094 <sr_drive_status+52>: li v0,4
0xffffffff80246098 <sr_drive_status+56>: ld ra,24(sp)
0xffffffff8024609c <sr_drive_status+60>: ld s0,16(sp)
0xffffffff802460a0 <sr_drive_status+64>: jr ra
0xffffffff802460a4 <sr_drive_status+68>: daddiu sp,sp,32
0xffffffff802460a8 <sr_drive_status+72>: jal 0xffffffff8024c838 <cdrom_get_media_event>
0xffffffff802460ac <sr_drive_status+76>: move a1,sp
0xffffffff802460b0 <sr_drive_status+80>: bnez v0,0xffffffff802460fc <sr_drive_status+156>
0xffffffff802460b4 <sr_drive_status+84>: lhu v0,0(sp)
0xffffffff802460b8 <sr_drive_status+88>: sll v0,v0,0x0
0xffffffff802460bc <sr_drive_status+92>: andi v0,v0,0xff
0xffffffff802460c0 <sr_drive_status+96>: andi v1,v0,0x2
0xffffffff802460c4 <sr_drive_status+100>: bnez v1,0xffffffff80246094 <sr_drive_status+52>
0xffffffff802460c8 <sr_drive_status+104>: andi v0,v0,0x1
0xffffffff802460cc <sr_drive_status+108>: beqz v0,0xffffffff80246098 <sr_drive_status+56>
0xffffffff802460d0 <sr_drive_status+112>: li v0,1
0xffffffff802460d4 <sr_drive_status+116>: ld ra,24(sp)

The thing about objdump -dr is that it gives you the name of the function that's being called. gdb apparently doesn't, or would need a different command from "disassemble".

Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

I think I was confused earlier. 156 is 0x9c, thus within the function. The backtrace must be incorrect; this is really 0x48 and thus a call to cdrom_get_media_event, which points the finger at cdi->ops->generic_packet being NULL.

Put a BUG_ON(!cdi->ops->generic_packet) in drivers/cdrom/cdrom.c right before the line that calls it (ie line 11 of cdrom_get_media_event). That should trigger and give a better backtrace. Then it's a simple (*) matter of figuring out why it's NULL.

* This is sarcasm.

Intel are signing my paycheques ... these opinions are still mine
"Bill, look, we understand that you're interested in selling us this
operating system, but compare it to ours.  We can't possibly take such
a retrograde step."

Hi all,
I wrote a message to linux-mips mailing list for investigating on the assembly code generated in sr_cdrom_status() since adding the suggested printk() stopped the oops. I supposed there is a problem with the compiler, but people there are investigating about problem with cache coherency.
You may follow the thread on public web archive, at
http://www.linux-mips.org/archives/linux-mips/2008-03/msg00079.html

I'll be back on this list after checking any problem with cache coherence and c compiler.

Thanks,
Giuseppe