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

Let's examine a Stream. This exercise should be something you can do on your own system. The only exercise requirement is that you be able to run adb on your kernel.

In order to do this on a running system, we need to first make sure that there is something in a Stream to look at. To ensure this, we're going to run a program that generates a lot of output and then press Control-S to stop the printing ”the output will be backed up in the queues for this Stream. Then, we have to actually locate the queues. This part is going to provide some nice practice in following pointers through the operating system (which was Solaris 2.3 for the example). The user structure contains a table of open files (what your file descriptors refer to). These point to file table entries. These in turn contain pointers to the vnode of the open file, which contains a pointer to the Stream head. From there we can find the queues. Trivial, isn't it?

Well, let's start. Bring up a terminal window that will be our test site. The type of window doesn't matter, but the shell you run in it should probably not be the C shell (since it does some rather odd things with file descriptors). For the example, our default was csh ; we just started up sh as a subshell and ran the commands from there. Once you have the Bourne shell, run the tty command, which will identify the terminal name . This is necessary to be able to identify the proper process in a ps output list. You may also wish to echo $$, the process ID of the shell itself.

% sh $ tty /dev/pts/3 $ echo $$

Now, in this window, start up a command that generates a lot of output, and press Control-S quickly to prevent the command from completing. We used sleep 5;ls -l /dev for the sample. As long as the output device (the Stream going to the window) is blocked, the characters will be backed up inside the queues in this Stream and we should be able to find the output and recognize it.

In another window, preferably one with a scroll bar (because you will be backing up over a lot of output), let's look around. First, you need to be able to find the process table entry for the command you just started, or the shell that ran it.

# ps -lft pts/3 S chris 1028 1025 63 1 20 fc13e800 206 fc13e9c8 Nov 29 pts/3 0:02 csh S chris 2236 1028 20 1 20 fc1d3000 162 ff603a46 19:35:39 pts/3 0:00 sh

The last line is the line of interest; it's the shell. Note that no ls is listed ” it finished already and exited, even though all its output is still pending.

We'll have to start up adb on the kernel to see if we can find anything. Use the ADDR field from the ps output (fc1d3000) as the address of the process (the proc structure pointer). There are other ways to find this value, but this is the easiest .

# adb -k /dev/ksyms /dev/mem physmem 4f0d

Now, dump out the process table entry. We're just doing this to verify the fact that this is a real proc structure, and that the values in it do match what we expect to find.

fc1d3000$<proc 0xfc1d3000: lbolt cid exec as 0 0 ff3df408 fc1e43b0 0xfc1d3010: uid 1847 lock 0xfc1d3014: owner 0 0xfc1d3014: lock type waiters 0 0 0 0xfc1d301c: crlock 0xfc1d301c: owner 0 0xfc1d301c: lock type waiters 0 0 0 0xfc1d3024: cred swapcnt stat wcode wdata ff8ff780 0 2 0 0 0xfc1d3034: ppid link parent 1028 0 fc13e800 0xfc1d3040: child sibling next nextofkin 0 0 fc1ef000 fc13e800 0xfc1d3050: orphan nextorph pglink sessp 0 0 0 ff40f380 0xfc1d3060: pipd pgidp ff82d830 ff82d830 ...

We'll stop listing it here; you will see a bit more output. Let's take the ppid field, which should contain the PID number of the parent process. It seems to be 1028, and if we look back at the ps output, we see that the parent process ID is in fact this number. Good so far. Now, the pipd label from the macro is actually, if you look at the process structure definition, referring to the pidp , or PID structure pointer. (Check the proc structure in the header file /usr/include/sys/proc.h .) There is a macro to dump out PID structures, so let's check.

ff82d830$<pid 0xff82d830: bits pid 300003d 2236 0xff82d838: pglink link fc1d3000 0

And we see that the pid value is 2236, which does match our process ID. (This particular pid structure appears to contain a pointer back to the same process table entry. This is really a pointer to the process group leader , which happens to be the same process in this instance.) Next, look at the user structure for this process by using the proc2u macro, which needs the address of the process table entry again as a starting location.

0xfc1d3000$<proc2u 0xfc1d31b0: execid execsz tsize 32581 12a 0 0xfc1d31bc: dsize start ticks cv 0 2ee0c88b 2bed603 0 ... 0xfc1d3260: psargs sh ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ 0xfc1d32b0: comm sh ^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@ ... flist 0xfc1d3594: ofile ff601640 ff601640 ff601640 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 ...

We've extracted just the interesting pieces here. First, the psargs/comm fields contain the process name and full command line. Both of these contain sh, along with a lot of nulls. Are we running the shell in that window? Yes, we are. This matches.

Look at the ofile table: this is the list of open files. We see that the first three entries, corresponding to file descriptors 0, 1, and 2 (standard input, standard output, and standard error) are all set and are all the same. They are in fact " clones " or duplicates of one another, all referring to the same device. In other words, everything is pointing to pts/3, the pseudo-tty associated with the window. No big surprise, but it's nice to see confirmation of what we expect. Now, each one of these table entries is a pointer to a file table structure. Take the address and run the file macro on it.

ff601640$<file hwc_debug+0x633c: next prev flag count ff40ebc0 ff82d900 3 8 hwc_debug+0x6348: vnode offset ff457004 0 cb8a hwc_debug+0x6354: cred ff8ff780

(Be careful with some of this adb output. Note here that the labels are pushed out to the right because the address that's printed is quite long. In this case, it looks like they are over the wrong column. Go by number rather than the actual printed position).

The output indicates that the vnode referenced by this file table entry is out at address 0xff457004. Let's display that.

ff457004$<vnode 0xff457004: flag refcnt vfsmnt vop 0 2 0 spec_vnodeops 0xff45701c: vfsp stream pages f00c81fc ff5ff700 0 0xff457028: type maj<<2 min data 4 60 3 ff457000 0xff457034: filocks 0

These numbers and addresses look good. There is a reference count of 2, which seems reasonable; at least it's not some ridiculously large number or negative. (Why 2? This number corresponds to the number of "open" requests actually issued for this particular vnode. One was from the shelltool ; to find the other, we'd have to look through every file table entry to find another occurrence of this vnode, and trace that back to a process.) We see that the operation structure pointer for this vnode refers to spec_vnodeops , indicating that this is a "special file" or a device. Again, something we would expect: this is a pseudo-terminal .

There is a "stream" pointer listed as well. Looking at the v node structure definition ( /usr/include/sys/vnode.h ), this can be seen as:

struct stdata *v_stream; /* associated stream */

So we want to look at an stdata structure, actually. Looking in the adb macro directory, we find something that has exactly that name, so let's use it and dump this data out.

ff5ff700$<stdata hwc_debug+0x43fc: wrq iocblk vnode strtab ff603a54 0 ff81cc04 ff2fe87c hwc_debug+0x440c: flag iocid iocwait 4010282 2459f 0 hwc_debug+0x4414: sidp s_pgidp wroff ff600b90 ff82d830 0 hwc_debug+0x4420: rerror werror pushcnt 0 0 3 hwc_debug+0x442c: sigflags siglist eventflags 0 0 0 hwc_debug+0x4438: eventlist 0 hwc_debug+0x443c: list dummy events 0 0 0 hwc_debug+0x4448: mark closetime rtime 0 5dc 0

Again, the labels are a bit off, but the first pointer is labeled wrq . If we check the definition of the stdata structure ( /usr/include/sys/strsubr.h ), this appears to be a queue pointer for the write side:

struct queue *sd_wrq; /* write queue */

Since we're looking at output, let's follow this. Again checking in the macro directory, we find a queue macro.

ff603a54$<queue 0xff603a54: qinfo first last next f00b4e98 0 0 ff82ee54 0xff603a64: link ptr count flag 0 ff5ff700 4020 0xff603a74: minpsz maxpsz hiwat lowat 0 0 0 0 0xff603a84: bandp nband 0 0

The queue structure is defined in the stream.h header file. This one appears to be empty: the first data block and last data block pointers are null, and the number of bytes on the queue (in count ) is zero. There is a next queue, which refers to the queue structure for the next module in the Stream, so let's follow the chain.

ff82ee54$<queue 0xff82ee54: qinfo first last next ff263eb0 0 0 ff82d254 0xff82ee64: link ptr count flag 0 ff87f640 0 822 0xff82ee74: minpsz maxpsz hiwat lowat 0 ffffffff 12c c8 0xff82ee84: bandp nband 0 0

This again appears to be empty. Let's stop for a moment here and see where we are in the Stream. Looking in the queue structure again, the first pointer in the struct, labeled qinfo in the macro output, is a qinit pointer. A macro exists, so let's check it out.

ff263eb0$<qinit ttycompatwinit: ttycompatwinit: putp srvp qopen qclose ff2621d8 0 ff262040 ff262164 ttycompatwinit: ttycompatwinit: minfo mstat ff2621d8 0

OK, except for one thing: notice that the label on the second line is exactly the same as the label on the first one, and the data appears to be the same as well. This is not right. In fact, if we look at the macro itself, it appears to be erroneous.

Example 25-4 The qinit macro

% cat qinit ./"putp"16t"srvp"16t"qopen"16t"qclose"n4X4+ ./"minfo"16t"mstat"n2X %

If you think back to the adb chapter, you may recall that adb will remember the last place you started displaying data as "dot." The second line uses the value of dot again as a starting point, and displays the same data as the first line, using a different format! This line should read:

+/"minfo"16t"mstat"n2X

If your macro looks like the broken one, you might consider fixing it.

Note

The macros are generally reliable, but we want to emphasize the need for caution, checking everything, and never making any assumptions when dealing with broken kernels .

However, we will check the qinit structure and dump it out manually. Again from stream.h we can find the definition of the structure.

Example 25-5 The queue information structure as defined in /usr/include/sys/stream.h

/* * queue information structure */ struct qinit { int (*qi_putp)(); /* put procedure */ int (*qi_srvp)(); /* service procedure */ int (*qi_qopen)(); /* called on startup */ int (*qi_qclose)(); /* called on finish */ int (*qi_qadmin)(); /* for future use */ struct module_info *qi_minfo; /* module information structure */ struct module_stat *qi_mstat; /* module statistics structure */ };

What we want to look at is probably the module_info structure, because this one contains the name of the module itself.

Example 25-6 The module information structure as defined in /usr/include/sys/stream.h

/* * Module information structure */ struct module_info { ushort mi_idnum; /* module id number */ char *mi_idname; /* module name */ long mi_minpsz; /* min packet size accepted */ long mi_maxpsz; /* max packet size accepted */ ulong mi_hiwat; /* hi-water mark */ ulong mi_lowat; /* lo-water mark */ };

There's no macro for this one, so we'll have to dump this out manually as well. (Note: there are a lot of "mod"-something macros in the adb library directory, but none of them are appropriate. Most of them deal with loadable modules in the kernel, not with Streams data.)

Looking back at the qinit structure, we see five pointers to functions followed by two pointers to structures. Dump these out, first five, and then two on another line.

ff263eb0/5XnXX ttycompatwinit: ttycompatwinit: ff2621d8 0 ff262040 ff262164 0 ff263e98

The first structure pointer (the next to the last value dumped) should be a pointer to a module_info structure. This has an unsigned short as the first element followed by a long pointer. Warning! The compiler, when it generates space for this structure on a SPARC machine, will make sure the second element, the pointer, starts on an even 4-byte boundary. It inserts two extra bytes of padding after the short ID number field. We will need to dump the short for the ID field, another short that we ignore completely, and the full word, the one we want, beyond that. (This is one place where a good macro would help. Incidently, adbgen would automatically take care of that needed padding.)

ff263e98/xxX ttycompatmoinfo: ttycompatmoinfo: 2a 0 ff263ef8

This should be a string pointer, so we can display what it points to with the s command:

ff263ef8/s ttcoinfo+0x2c: ttcompat

And we see that we are looking at the ttcompat module, which is indeed something we should expect to see on a tty stream.

After that little detour , let's go back to our empty queue and follow on to the next one.

ff82d254$<queue 0xff82d254: qinfo first last next ff25b958 0 0 ff602354 0xff82d264: link ptr count flag 0 ff8c2a40 0 822 0xff82d274: minpsz maxpsz hiwat lowat 0 ffffffff 1 0 0xff82d284: bandp nband 0 0

This again is empty. Let's grab that qinit pointer and see what it is.

ff25b958/X ldtermwinit: ldtermwinit: ff258fac

It's pointing to a global structure labeled ldtermwinit ”the init structure for the write side of the ldterm module, which seems appropriate. We won't do more, but feel free to make sure the name is ldterm if you want to. Move on to the next queue structure in the stream.

ff602354$<queue hwc_debug+0x7050: qinfo first last next ff2a1220 fc1caf80 fc17ad00 ff602e54 hwc_debug+0x7060: link ptr count flag 0 ff40b5c0 26272 82a hwc_debug+0x7070: minpsz maxpsz hiwat lowat 0 200 0 0 hwc_debug+0x7080: bandp nband 0 0

Now, this one looks significantly different. We have a real first pointer, a last pointer, and a fairly large count field of over 26,000 bytes. Looking at the queue structure definition again, the first pointer and last pointer should be indicating msgb structures. We don't see an msgb macro, but we do find one for an mblk . If you look a couple of lines down in the stream.h header file, you may see a declaration ”

typedef struct msgb mblk_t;

” that is a clue that the mblk macro applies here. You might also dump the macro contents out and look at them, checking the headers, types, and offsets against the structure contents to make sure they match. Let's use it.

fc1caf80$<mblk 0xfc1caf80: next prev cont fc1aaa00 0 0 0xfc1caf8c: rptr wptr datap fc1cafc0 fc1cafcb fc1cafa0 0xfc1caf98: band flag 0 0

According to the msgb structure definition, rptr and wptr are character pointers to data in the buffer, so we should be able to see some output. Note again that this is not null- terminated , so using the s (string) adb format to dump it out may produce extra garbage characters at the end. The wptr value indicates the point at which a write would be started, so data should lie before this, starting at the read pointer. Subtracting the two pointers gives a value of 0xb, or 11 characters to look at. We'll use the adb format command c , which just prints one character, but give it a repeat count so we get the entire string.

fc1cafc0,b/c 0xfc1cafc0: total 326

Promising. Definitely promising . This is indeed something we might see as the first line of output from an ls -l command. This doesn't look like 11 characters, though. Let's print them out with the uppercase C command, which displays nonprinting characters in coded form:

fc1cafc0,b/C 0xfc1cafc0: total 326^M^J

A ^M code (Control-M) happens to be a carriage return in ASCII, and a Control-J is a linefeed . This is something that ldterm, one of the standard serial I/O STREAMS modules, does to lines of output: turn the newline into a return/linefeed pair.

Move on to the next message block in the list, following that next pointer from our mblk:

fc1aaa00$<mblk 0xfc1aaa00: next prev cont fc214280 fc1caf80 fc216480 0xfc1aaa0c: rptr wptr datap fc1aaa40 fc1aaa80 fc1aaa20 0xfc1aaa18: band flag 0 0

Looking at the data, we see:

fc1aaa40,40/c 0xfc1aaa40: lrwxrwxrwx 1 root 29 Nov 28 11:36 arp -> ../devices/p

This is a truncated line. However, there is a continuation pointer in the mblk header, which also points to another mblk .

fc216480$<mblk 0xfc216480: next prev cont 0 0 0 0xfc21648c: rptr wptr datap fc2164c0 fc2164d3 fc2164a0 0xfc216498: band flag 0 0

We have a little bit of data (0x13 bytes), so let's see what's there.

fc2164c0,13/c 0xfc2164c0: seudo/clone@0:arp

This, when tacked on to the previous output, says that the arp entry is a symbolic link pointing to

../devices/pseudo/clone@0:arp

which is correct. Let's go on to one more line of output (the next message) and see what we have.

fc214280$<mblk 0xfc214280: next prev cont fc1aab00 fc1aaa00 fc1aac00 0xfc21428c: rptr wptr datap fc2142c0 fc214300 fc2142a0 0xfc214298: band flag 0 0 fc2142c0,40/c 0xfc2142c0: lrwxrwxrwx 1 root 12 Nov 28 11:39 audio -> /dev/sound fc1aac00$<mblk 0xfc1aac00: next prev cont 0 0 0 0xfc1aac0c: rptr wptr datap fc1aac40 fc1aac44 fc1aac20 0xfc1aac18: band flag 0 0 fc1aac40,4/c 0xfc1aac40: /0 fc1aac40,4/C 0xfc1aac40: /0^M^J

Here again, the line is split into two messages, but putting them together results in pretty good-looking output.

So, we've followed a trail of pointers through a lot of structures in the kernel and found what we had hoped to find: the output that was supposed to come to our suspended window. This should be good practice for looking at Streams in crash dumps, as well as chasing pointers through various structures in the kernel. Be sure, until you become familiar with the various macros and the structures they dump, to do some double-checking: Make sure the macro is the right one, and maybe even verify the value of one or two of the fields manually. And remember, you learn best by doing; use those macros and adb commands until you become familiar with them, and your debugging sessions will proceed quickly and smoothly.