Initial analysis

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.