Kernel crash in interrupt handler: nested interrupt breaks saved %eip?

DISCUSSION Nikita V. Youshchenko 1 participant 2 messages Jul 8, 2004 – Jul 9, 2004 1 message not in the archive

lore

Share & tools

lore

Nikita V. Youshchenko

author

2004-07-08 19:51 UTC #0 lore raw

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hello.

Recently I've got a server crash (complete hang). Server has it's console on serial port, so crash log was available:

root@zigzag:/home/nikita/adm> ksymoops -m /boot/System.map-2.6.6-1-k7-smp < crash_log
ksymoops 2.4.9 on i686 2.6.6-1-k7-smp. Options used
-V (default)
-k /proc/ksyms (default)
-l /proc/modules (default)
-o /lib/modules/2.6.6-1-k7-smp/ (default)
-m /boot/System.map-2.6.6-1-k7-smp (specified)

Error (regular_file): read_ksyms stat /proc/ksyms failed
ksymoops: No such file or directory
No modules in ksyms, skipping objects
No ksyms, skipping lsmod

Unable to handle kernel paging request at virtual address 2c031041
*pde = 00000000
Oops: 0002 [#1]
CPU:    1
EIP:    0060:[<c02262a2>]    Tainted: P

Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010286 (2.6.6-1-k7-smp)
eax: c207c000 ebx: 00000001 ecx: 00000011 edx: c207c000
esi: c0336e98 edi: 0000000a ebp: c03629e0 esp: c207df38
ds: 007b es: 007b ss: 0068

Stack: 00000068 00000001 c0124566 c0336e98 00000046 c207c000 00000013 
c012459d
       c207c000 c01089f8 00000013 c0332cc0 00000001 c0332cd8 f6d3d21c 
c207c000
       00000000 00000000 00000000 c0106bb8 c207c000 c0104030 c207c000 
00000000
Call Trace:
 [<c0124566>] __do_softirq+0xa6/0xb0
 [<c012459d>] do_softirq+0x2d/0x30
 [<c01089f8>] do_IRQ+0x138/0x190
 [<c0106bb8>] common_interrupt+0x18/0x20
 [<c0104030>] default_idle+0x0/0x40
 [<c010405c>] default_idle+0x2c/0x40
 [<c01040e3>] cpu_idle+0x33/0x40
 [<c0120681>] printk+0x1a1/0x1f0
Code: 10 8b 40 10 03 2c 85 20 50 36 c0 a1 80 99 2c c0 89 44 24 08

Quoted 7 lines

Quoted 7 lines
EIP; c02262a2 <net_rx_action+12/100> <=====
eax; c207c000 <__crc_sysfs_remove_dir+37704/567b6a> edx; c207c000 <__crc_sysfs_remove_dir+37704/567b6a> esi; c0336e98 <softirq_vec+18/100>
ebp; c03629e0 <per_cpu__softnet_data+0/240> esp; c207df38 <__crc_sysfs_remove_dir+3963c/567b6a>

Trace; c0124566 <__do_softirq+a6/b0>
Trace; c012459d <do_softirq+2d/30>
Trace; c01089f8 <do_IRQ+138/190>
Trace; c0106bb8 <common_interrupt+18/20>
Trace; c0104030 <default_idle+0/40>
Trace; c010405c <default_idle+2c/40>
Trace; c01040e3 <cpu_idle+33/40>
Trace; c0120681 <printk+1a1/1f0>

Code; c02262a2 <net_rx_action+12/100>
00000000 <_EIP>:
Code; c02262a2 <net_rx_action+12/100> <=====
0: 10 8b 40 10 03 2c adc %cl,0x2c031040(%ebx) <=====
Code; c02262a8 <net_rx_action+18/100>
6: 85 20 test %esp,(%eax)
Code; c02262aa <net_rx_action+1a/100>
8: 50 push %eax
Code; c02262ab <net_rx_action+1b/100>
9: 36 c0 a1 80 99 2c c0 shlb $0x89,%ss:0xc02c9980(%ecx)
Code; c02262b2 <net_rx_action+22/100>
10: 89
Code; c02262b3 <net_rx_action+23/100>
11: 44 inc %esp
Code; c02262b4 <net_rx_action+24/100>
12: 24 08 and $0x8,%al

<0>Kernel panic: Fatal exception in interrupt

I tried to debug this. Server runs debian's 2.6.6-1-k7-smp kernel; vmlinux file is not available. So (after reboot) I just attached gdb to /proc/kcore.

First I tried to examine __do_softirq() function near 0xc0124566 address. The assembly code near that point is:

0xc0124561:     mov    %esi,(%esp)
0xc0124564:     call   *(%esi)
0xc0124566:     jmp    0xc0124507

Comparing this with function source, it definitly corresponds to the h->action(h) call inside

	do {
		if (pending & 1)
			h->action(h);
		h++;
		pending >>= 1;
	} while (pending);

'h' variable is in %esi register, and %esi value in the crash log points to 4th element of softirq_vec array; 'action' pointer of that element really points to net_rx_action() function mentioned in the crash log.

The assembly of the start of that function is

0xc0226290:     push   %ebp
0xc0226291:     mov    $0xffffe000,%eax
0xc0226296:     mov    $0xc03629e0,%ebp
0xc022629b:     push   %edi
0xc022629c:     and    %esp,%eax
0xc022629e:     push   %esi
0xc022629f:     push   %ebx
0xc02262a0:     sub    $0x10,%esp
0xc02262a3:     mov    0x10(%eax),%eax
0xc02262a6:     add    0xc0365020(,%eax,4),%ebp

The crash address - 0xc02262a2 - is inside a multi-byte instruction. Processor tried to read from that address and executed instruction
adc %cl,0x2c031040(%ebx)
that caused invalid memory access and the crash.

So the question is - how could invalid address (0xc02262a2) get into %eip.

Interrupts at the beginning of net_rx_action() on this code path are enabled - this is after local_irq_enable() in __do_softirq(), but before local_irq_disable() in net_rx_action().

So I think that an interrupt happened at that time, and %eip was broken inside the handler.

(other possible reasons I could think of are hardware fault and stack breakage inside net_rx_action(); both seem to be much less probable:
hardware is in every day use and works stable; crash happened after days of stable operation - so the probable reason is a RARE event such as an interrupt at exact point; register values look like only several few first instructions of net_rx_action() have been executed, it's almost impossible to get these values if it was overwritten %eip in the stack in nested calls).

Some time ago I was playing with home-written RTAI-like realtime kernel extension, and while debugging it found code in the kernel that alters saved %eip value under some conditions (e.g. to restart an instruction). Due to bug in my code, that happened at unwanted time, causing user-level process resume with invalid %eip and mystorious segfaults in the middle of instructions.

Of course I'm not sure, but it looks like something similar caused the crash I'm writing about. Somewhere in the nested interrupt handler it was not detected correctly that a nested interrupt from code handling another interrupt is hapenning, and saved %eip was altered.

At this point I fell I can't go forward - I'm not that familiar with lowlevel kernel code. So I'm looking for some help ...

All that is about debian's 2.6.6-1-k7-smp kernel, installed as a debian package on a server that has 2 AMD CPUs and a Tyan motherboard. Kernel pre-emption is enabled in the debian kernel; complete system.map is available at http://zigzag.lvk.cs.msu.su/~nikita/System.map-2.6.6-1-k7-smp
I may provide detailed system information if needed.

Nikita Youshchenko
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (GNU/Linux)

iD8DBQFA7aWwsTbPknTfAB4RAnkqAJ9Ee8NWFHmzdV8E/DCxHITDNsZScQCfV1fK 7EI2aXIsIjjDNQMa2HWHq2g=
=D0cC
-----END PGP SIGNATURE-----

A message that is not in the archive (sent off-list or not yet received): [email protected]

Nikita V. Youshchenko

author

2004-07-09 11:35 UTC #2 lore raw

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Quoted 3 lines

Quoted 1 line
EIP: 0060:[<c02262a2>] Tainted: P
                               ^^^^^^^^^^
What was that? Your lsmod please?

That's caused by vmware bodules; I don't think they affect the situation.

Quoted 5 lines

Quoted 2 lines
So I think that an interrupt happened at that time, and %eip was broken inside the handler.
You can istrument your kernel to check for that on every interrupt and printk a KERN_NOTICE message if eip was changed.

What's the correct place for those? do_IRQ()? Or probably some other places also (APIC timer interrupt handler? exception handler?)

Unpleasant situation is that the problem is on a production server, which should be operational 24/7 ... However, probably I'll try to install an instrumented kernel in the next kernel upgrade.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (GNU/Linux)

iD8DBQFA7oLLsTbPknTfAB4RAhGvAJ9n9246V7cMntgPnwmKBI/pcR0XGACeMnSY fuIaVh1yCssaJC0PWdHd7sE=
=/8fI
-----END PGP SIGNATURE-----