PANIC! UNIX System Crash Dump Analysis Handbook (Bk/CD-ROM)

This system was a fairly new SPARCstation 5, running SunOS 4.1.3_U1. (We'll verify that, leaving nothing to chance.) This means we need to analyze the crash on a comparable system: a sun4m architecture, running the same version of the kernel. Once we put the savecore files on the right machine, we can run adb and make sure we're working on the right system immediately.

Let's start out by checking the version of the OS we're dealing with.

sparc413: strings vmunix.1 grep SunOS SunOS Release 4.1.3_U1 (S5) #2: Thu Nov 24 10:35:22 PST 1994

So far, so good. We can now run adb with some degree of confidence that we're at least looking at the right version of the system. In the analysis, we should be able to find some verification that the system is correct by looking in the system message buffer.

sparc413: adb -k vmunix.1 vmcore.1 physmem 2fb1 *panicstr/s _sizestr+0x9b: Memory address alignment

The panic string printed on the console was "memory address alignment," which indicates that we have a bad pointer in the kernel someplace. A "data fault" message would indicate a similar problem; both of these messages mean that an attempt to follow a pointer resulted in an error. It's a different kind of error, but it still relates to having a bad value in that pointer to begin with. This type of error is detected by hardware, which means we should be able to get some information out of the kernel message buffer. One of the most useful is the PC value, identifying the actual address of the instruction that tried to use the invalid pointer. Let's check the contents of the message buffer. There are two ways to do this. One way is to use the msgbuf macro, which will print just the information at the time of the fault. The other way is to dump the whole thing, which means we'll have to isolate the point where the messages wrap around. We'll take the second option. The command starts printing after the header, which in SunOS 4.x is 16 bytes (0x10) long. (In Solaris 2, it got a little bit larger ”it's 20 bytes, 0x14.)

msgbuf+10/s 0xf0002010: VAC ENABLED SunOS Release 4.1.3_U1 (S5) #1: Mon Sep 19 15:06:35 PDT 1994 Copyright (c) 1983-1993, Sun Microsystems, Inc. cpu = SUNW,SPARCstation-5 mod0 = FMI,MB86904 (mid = 0) mem = 48836K (0x2fb1000) avail mem = 45682688 entering uniprocessor mode Ethernet address = 8:0:20:20:28:b0 espdma0 at SBus slot 5 0x8400000 esp0 at SBus slot 5 0x8800000 pri 4 (onboard) sd0 at esp0 target 3 lun 0 sd0: <SUN0535 cyl 1866 alt 2 hd 7 sec 80> sd1 at esp0 target 1 lun 0 sd1: <Seagate ST12400N cyl 2617 alt 2 hd 19 sec 84> SUNW,bpp0 at SBus slot 5 0xc800000 pri 3 (sbus level 2) ledma0 at SBus slot 5 0x8400010 le0 at SBus slot 5 0x8c00000 pri 6 (onboard) cgsix0 at SBus slot 3 0x0 pri 9 (sbus level 5) cgsix0: screen 1152x900, single buffered, 1M mappable, rev 11 SUNW,CS42310 at SBus slot 4 0xc000000 pri 9 (sbus level 5) zs0 at SBus slot 5 0x1100000 pri 12 (onboard) zs1 at SBus slot 5 0x1000000 pri 12 (onboard) SUNW,fdtwo0 at SBus slot 5 0x1400000 pri 11 (onboard) root on sd0a fstype 4.2 swap on sd0b fstype spec size 70000K dump on sd0b fstype spec size 69988K le0: AUI Ethernet syncing file systems... done rebooting... VAC ENABLED SunOS Release 4.1.3_U1 (SS5) #2: Thu Nov 24 10:35:22 PST 1994 Copyright (c) 1983-1993, Sun Microsystems, Inc. cpu = SUNW,SPARCstation-5 mod0 = FMI,MB86904 (mid = 0) mem = 48836K (0x2fb1000) avail mem = 45682688 entering uniprocessor mode Ethernet address = 8:0:20:20:28:b0 espdma0 at SBus slot 5 0x8400000 esp0 at SBus slot 5 0x8800000 pri 4 (onboard) sd0 at esp0 target 3 lun 0 sd0: <SUN0535 cyl 1866 alt 2 hd 7 sec 80> sd1 at esp0 target 1 lun 0 sd1: <Seagate ST12400N cyl 2617 alt 2 hd 19 sec 84> SUNW,bpp0 at SBus slot 5 0xc800000 pri 3 (sbus level 2) ledma0 at SBus slot 5 0x8400010 le0 at SBus slot 5 0x8c00000 pri 6 (onboard) cgsix0 at SBus slot 3 0x0 pri 9 (sbus level 5) cgsix0: screen 1152x900, single buffered, 1M mappable, rev 11 SUNW,CS42310 at SBus slot 4 0xc000000 pri 9 (sbus level 5) zs0 at SBus slot 5 0x1100000 pri 12 (onboard) zs1 at SBus slot 5 0x1000000 pri 12 (onboard) SUNW,fdtwo0 at SBus slot 5 0x1400000 pri 11 (onboard) root on sd0a fstype 4.2 swap on sd0b fstype spec size 70000K dump on sd0b fstype spec size 69988K le0: AUI Ethernet BAD TRAP : cpu=0 type=7 rp=fd002dc4 addr=0 mmu_fsr=0 rw=0 MMU sfsr=0: No Error regs at fd002dc4: psr=48001c3 pc=f001c770 npc=f001c774 y: 5800000 g1: 40007e2 g2: ff65cc0c g3: 0 g4: 0 g5: fd009000 g6: 0 g7: f0189400 o0: 805905c1 o1: 805908d9 o2: fd002e00 o3: ff65eb32 o4: 0 o5: fd009000 sp: fd002e10 ra: f0189400 pid -1, `': Memory address alignment rp=0xfd002dc4, pc=0xf001c770, sp=0xfd002e10, psr=0x48001c3, context=0x0 g1-g7: 40007e2, ff65cc0c, 0, 0, fd009000, 0, f0189400 Begin traceback... sp = fd002e10 Called from f001b8f0, fp=fd002e70, args=ff652a0c ff6492a4 0 5a9d4401 4 8059ffff Called from f0017e04, fp=fd002ee0, args=ff65d48c 1000 12 1e3fe ff6492a4 ff652a0c Called from f003b8dc, fp=fd002f40, args=ff649280 ff005000 14 2 20 ff641b8c Called from f0005eb8, fp=fd002fa0, args=0 8 f001779c 0 48001e7 f018d3f0 Called from f002e4ec, fp=fd008e98, args=48000e1 8 ff000008 0 40000e6 f0180c00 End traceback... panic on cpu 0: Memory address alignment syncing file systems... done low-memory static kernel pages additional static and sysmap kernel pages dynamic kernel data pages additional user structure pages segmap kernel pages segvn kernel pages current user process pages user stack pages total pages (1772 chunks) dumping to vp fb004c1c, offset 125800

Well, this is a fairly long message buffer, but it does contain some items of interest. We've underlined a few of them so we can touch on those specifically .

First, the fourth line of the message buffer output indicates the CPU type, and yes, this is a SPARCstation 5 like it's supposed to be. There seems to be only one CPU module present on this machine, so it's a uniprocessor, even though it is of the sun4m architecture family. Lots of devices probe out, but nothing really unusual appears to be there. On the second page, we see a reboot. Note that the version of the kernel changed here: It's possible that this was related to the problem (new software or a new configuration may have been introduced here), but we don't know how long it was up before the system crashed or what the changes were.

Right after the boot sequence, we find a BAD TRAP message. This is our panic. The next line indicates that the MMU Synchronous Fault Status Register did not detect any error: This was a problem that was detected before it got to the MMU. A data fault that resulted from a completely wild pointer would probably display some flag settings in this register, indicating a memory access or a mapping problem. Below these we see the value of the PC (Program Counter), which is the address of the failed instruction. Following the register contents, the traceback information appears. This is a stack traceback performed by the kernel trap code, indicating what routines were called to get to the function where the fault occurred. You will note that these are all hexadecimal addresses, which makes interpretation slightly difficult.

This message buffer appears to be quite clean; no "overlap" is apparent. The machine either hasn't been up long or hasn't had much written on the console.

One of the useful things to look at is a stack traceback, to see where the system died and how it got there.

$c _panic(0xf0168800,0xf01835f4,0x0,0x0,0xfd003,0xfd008e98) + b4 _badtrap(0x1c,0xfd002dc4,0x0,0x0,0x0,0xf0197c00) + 114 _trap(0x7, 0xfd002dc4 ,0x0,0x0,0x0,0xffffffff) + 1c8 fixfault(?) _in_pcbdetach(0x805908d9,0x805908d9,0xf018c400,0x63,0x89b,0x3c06915b)+5c _tcp_close(?) _tcp_respond(0xff652a0c,0xff6492a4,0x0,0x5a9d4401,0x4,0x8059ffff) + 7c _tcp_input(0xff65d48c,0x1000,0x12,0x1e3fe,0xff6492a4,0xff652a0c) + 1878 _ipintr(0xff649280,0xff005000,0x14,0x2,0x20,0xff641b8c)+ 668 _softint(0x0,0x8,0xf001779c,0x0,0x48001e7,0xf018d3f0) +64 softlvl1(?) _spl0(0x48000e1,0x8,0xff000008,0x0,0x40000e6,0xf0180c00) + 18 _idlework(0x0,0x1,0xfd00a800,0x0,0xf0429000,0x0) + 68 _main(0x44000e7,0xfb0042e0,0x1,0xe,0x80003,0xfb0042e0) + 3d4

Tracing from the bottom up, it appears that the system was idle; it came through the idlework() function. Following this, there was an interrupt ( softlvl1() , then softint() , and then ipintr() , an interrupt service routine for "ip"). There is no physical device that goes by this name , but looking ahead on the stack it seems like this belongs to TCP/IP.

We then find several routines that start with "tcp," another part of TCP/IP (the Transmission Control Protocol networking code in the kernel). Right after this it enters the function fixfault() , then goes through the kernel trap code. So far, this looks like it is network related: a message came in, and, in the process of responding to it, the system found a bad pointer.

We can find the exact location of the faulting instruction by looking at the PC value, which is saved by the kernel trap code in a regs structure. The second parameter of the trap() function in the stack trace is the address of this regs structure with values obtained from the CPU registers at the time of the trap. (The first parameter is the actual trap type number, in this case 7, identifying a memory address alignment problem.). There is a macro to display regs , so let's see where the bad instruction was.

0xfd002dc4$<regs 0xfd002dc4: psr pc npc 48001c3 f001c770 f001c774 0xfd002dd0: y g1 g2 g3 5800000 40007e2 ff65cc0c 0 0xfd002de0: g4 g5 g6 g7 0 fd009000 0 f0189400 0xfd002df0: o0 o1 o2 o3 805905c1 805908d9 fd002e00 ff65eb32 0xfd002e00: o4 o5 o6 o7 0 fd009000 fd002e10 f0189400

This gives us the values of the PC and nPC registers, all the globals , the Processor Status Register, and the output registers at the time of the trap. From here, we can extract the value of the PC and examine the instruction at that location. (The PC is also printed on the console by the trap function at the time of the crash, so we can double-check our address by getting the PC from the message buffer, which we underlined above.)

0xf001c770?i _tcp_respond+0x20: ld [%o5 + 0x1c], %o5

This looks a bit strange , since the stack traceback we got above from $c showed a couple of routines after tcp_respond() before the fault code showed up.

Just to be on the safe side, let's double-check this stack traceback with the stacktrace macro in adb . This will give us a more verbose version, but hopefully the same image of the stack as we have here. Maybe it will help to explain why $c seems to give more output than it should.

We'll take this in pieces. Normally, of course, this all runs together in one massive burst.

<sp$<stacktrace l0 l1 l2 l3 l4 l5 l6 l7 i0 i1 i2 i3 i4 i5 i6 i7

The first lines of output from the macro are just a set of headings, defining the registers placed in a stack frame. Locals ( %l0 “ %l7 ) come first, followed by inputs ( %i0 “ %i7 ).

Following this, the stacktrace macro will dump out the 16 registers stored in the beginning of a stack frame: 8 locals and 8 inputs.

0xfd002c40: fd009b84 fd009000 fd009400 f018ead8 f004898c f017d100 fd002c40 0 f0168800 f01835f4 0 0 fd003 fd008e98 fd002ca0 f00f7a1c 0xfd002c40: 0xfd009b84 0xfd009000 0xfd009400 _panic_regs _panic+0xb4 _olvl6 0xfd002c40 0 _ldtab_initialized+0x434_trap_type 0 0 0xfd003 0xfd008e98 0xfd002ca0 _badtrap+0x114

There are a couple of things to notice here. First, although you get two sets of numbers, they are the same stack frame. Note that the addresses on the left hand side are the same: both 0xfd002c40. This is the same set of data printed in two different ways. The first set of 16 numbers is just plain hexadecimal. The second set is printed symbolically or, if possible, as a variable name plus an offset. It's the same numbers, but sometimes it's easier to recognize significant addresses if you can see them as names , rather than as numbers .

You should also note here that the second set, when it uses names, may have trouble fitting everything on the line, especially for long names. In this case, the third line has only three numbers on it, so the fourth will appear as the first one on the next line, and the last one is on a line by itself. Just remember, the same amount of data is being printed, but the alignment may be off, so count the values, that is, go by number, not by position on the line.

You may recall from the discussion of stack frames that the %i6 register (the next to the last number in our display) is the old stack pointer, or the frame pointer. This gives us the location of the next frame on the stack, which will be displayed next in the same manner.

0xfd002ca0: 44001c1 f0056718 f00166a4 8 10 10 7 44007e3 1c fd002dc4 0 0 0 f0197c00 fd002d00 f00f7e54 0xfd002ca0: 0x44001c1 _sofree+0xbc _in_pcbdetach+0x10 8 0x10 0x10 7 0x44007e3 0x1c 0xfd002dc4 0 0 0 _fdkbuf+0x18 0xfd002d00 _trap+0x1c8

Here again, we see the same set of data displayed twice (the address on the left is the same), but the second set is printed symbolically. The address of this frame is the same as the old %i6 value.

The next frame:

0xfd002d00: 44001c2 f00166e8 0 10 20 48001c3 fd009b84 0 7 fd002dc4 0 0 0 ffffffff fd002d68 f0005608 0xfd002d00: 0x44001c2 _in_pcbdetach+0x54 0 0x10 0x20 0x48001c3 0xfd009b84 0 7 0xfd002dc4 0 0 0 -1 0xfd002d68 fixfault+0x5c

As expected, the next to the last address in the preceding register set is the location of the next frame. We're just following the chain.

You might also recall that the last value is the return PC address, or the location of the call to get to the current function. The first frame had a value of _ badtrap+0x114 ; the second had _trap+0x1c , and this current frame shows fixfault+0x5c. We are obviously backing through some trap-handling code. At some point we should expect to see a trap frame on the stack: the frame with the PC value in register %l1 . We know what the PC should be, since that was printed in the message buffer: down in tcp_respond() .

0xfd002d68: 48001c3 f001c770 f001c774 40 7 8 7 fd002d68 805908d9 805908d9 f018c400 63 89b 3c06915b fd002e10 f001cac0 0xfd002d68: 0x48001c3 _tcp_respond+0x20 _tcp_respond+0x24 0x40 7 8 7 0xfd002d68 0x805908d9 0x805908d9 _arptab+0x2660 0x63 0x89b 0x3c06915b 0xfd002e10 _tcp_close+0x7c

Well, what have we here? This looks like a normal stack frame, but the value in register %l1 has the PC value for the bad instruction, at just about the location where we might expect to see a trap frame on the stack. adb sometimes has trouble identifying a special trap frame, since it can look the same as anything else. You have to keep an eye out and recognize it from context, as we did here.

If this is the trap frame, then the next frame on the stack will have the set of registers in use by the code at the time the fault occurred.

0xfd002e10: 80590000 ff64ba80 8059ffff 805905c1 ffff0000 0 ffff0000 0 ff652a0c ff6492a4 0 5a9d4401 4 8059ffff fd002e70 f001b8f0 0xfd002e10: 0x80590000 0xff64ba80 0x8059ffff 0x805905c1 0xffff0000 0 0xffff0000 0 0xff652a0c 0xff6492a4 0 0x5a9d4401 4 0x8059ffff 0xfd002e70 _tcp_input+0x1878

Now we appear to be back on track. The return address here is inside tcp_input(), and the next stack frame, as we'll see, has a return address in ipint() . These follow the traceback information we got from the $c command. It looks like adb figured out there was a trap frame on the stack, possibly by recognizing the trap function name as a special return address, but it was off by one stack frame. The value in %l1 of the erroneous trap frame is indeed _in_pcbdetach+0x54 , which is our missing "return address." In this instance, the built-in command gave us misleading information, although it wasn't drastically wrong.

The stacktrace macro, although more work to decipher, gives us a dump of exactly what is currently on the stack and leaves the interpretation to us. We can validate or correct what we got from adb by using the easy method.

Let's quickly dump out the rest of the stack traceback and verify that it matches what we expect ” the output from $c .

0xfd002e70: 0 1 0 1f400 5864e802 0 ff649280 0 ff65d48c 1000 12 1e3fe ff6492a4 ff652a0c fd002ee0 f0017e04 0xfd002e70: 0 1 0 0x1f400 0x5864e802 0 0xff649280 0 0xff65d48c 0x1000 0x12 0x1e3fe 0xff6492a4 0xff652a0c 0xfd002ee0 _ipintr+0x668 0xfd002ee0: 805908d9 805908d9 1 f0189d30 18 2000 ffffbfff ffff ff649280 ff005000 14 2 20 ff641b8c fd002f40 f003b8dc 0xfd002ee0: 0x805908d9 0x805908d9 1 _loif 0x18 0x2000 0xffffbfff 0xffff 0xff649280 0xff005000 0x14 2 0x20 0xff641b8c 0xfd002f40 _softint+0x64 0xfd002f40: f018d000 30 8 6 1 4000 dc00 f01869d0 0 8 f001779c 0 48001e7 f018d3f0 fd002fa0 f0005eb8 0xfd002f40: _dk_time+0x2 0x30 8 6 1 0x4000 0xdc00 _leservice+0x18 0 8 _ipintr 0 0x48001e7 _softcalls+0x240 0xfd002fa0 softlvl1+0x18 0xfd002fa0: 44001c0 f002e554 f002e558 f0005ea0 0 f017e010 44 fd008df0 48000e1 8 ff000008 0 40000e6 f0180c00 fd008e98 f002e4ec 0xfd002fa0: 0x44001c0 _idlework+0xd0_idlework+0xd4softlvl1 0 _xlvl1+0x10 0x44 0xfd008df0 0x48000e1 8 0xff000008 0 0x40000e6 _wantmodules+0x23c 0xfd008e98 _idlework+0x68

We'll stop here, since it's clear that the stack matches what we saw before. This last frame is interesting, however. Remember, a system call is a trap, a fault is a trap, and an interrupt is also a trap. Thus, if we see an interrupt service routine on the stack, we should see a trap frame below it someplace to reflect the interrupt itself. In this case, right below the softlvl1() function, we note a return address from inside idlework() . We can also see, however, that the %l1 register contains an address from inside the same function! (As an additional bit of evidence, %l2 should contain the nPC register, which is normally the PC plus 4. In this case, it does contain the value in %l1 + 4.) This looks like a trap frame as well: the idlework() function was interrupted as it was cycling through a loop looking for something to do.