Hello, Venkatesh blogging here again. Recently I had a collaboration request to determine which mystery component was writing to the application event log. This was the event-

Share this post :

Hi Debuggers,

Here is a short video (6 min.) of how to root cause CPU consumption issues on Vista/Server 2008 and higher operating systems with Xperf. Download the video from the 'Attachement link' below.

For this scenario, Xperf is an easy to implement and powerful replacement for previous actions like gathering a series of dumps during the CPU, kernrate data, perfmon, other profilers, etc.

Xperf allows one to quickly turn on profiling and see where the CPU time is being spent by using tracing already in the box!

-Tate

Note - Feel free to post questions here, or jump into a discussion about the video on our Twitter page ( @ntdebugging ).

Share this post :

We're now on Twitter @ http://twitter.com/ntdebugging. If you want to chime in with feedback or suggestions for future articles feel free to drop us a "tweet". I thought this was would give us a better venue to interact with you guys.

 Cheers,

Ron Stock

My name is Ryan Mangipano (ryanman) and I am a Sr. Support Escalation Engineer at Microsoft.  Today’s blog will consist of a complete walkthrough of my recent analysis of a stop 0x50 along with the steps that  led me to  identify that  this crash was caused by pool corruption. In this particular case, I found the answer before completing the actual debug.

To begin the analysis, I entered the !analyze –v command into the debugger and examined the output relating to the bugcheck.  This is always my first step since it usually provides  an overview of what type of problem occurred. In the output listed below, you can see that the system has bugchecked due to an attempt by kernel mode code to access the invalid address 0xffffff50. 

 PAGE_FAULT_IN_NONPAGED_AREA (50)

Invalid system memory was referenced.  This cannot be protected by try-except,

it must be protected by a Probe.  Typically the address is just plain bad or it

is pointing at freed memory.

Arguments:

Arg1: ffffff50, memory referenced.

Arg2: 00000000, value 0 = read operation, 1 = write operation.

Arg3: 80846dd1, If non-zero, the instruction address which referenced the bad memory

                address.

Arg4: 00000000, (reserved)

Before proceeding with our debugging, I would like to point out that invalid addresses such as the one listed above are often obtained when code subtracts values from a null pointer.  To illustrate that  this particular address 0xffffff50 could be obtained in such a manner, I have provided output from the .formats debugger command below.  Notice that the  hex vaule 0xffffff50  can be used to represent negative 176 as a decimal.  It is a relatively common situation to arrive at a negative value by subtracting values from a null pointer (which is zero).   Since addresses are actually unsigned, this is really just an invalid positive address. 

0: kd> .formats ffffff50

Evaluate expression:

  Hex:     ffffff50

  Decimal: -176

 

Let’s proceed with our investigation.  The output of !analyze –v also provided us with the following:

TRAP_FRAME:  f4009940 -- (.trap 0xfffffffff4009940)

 This provided a  trap frame address in the form of a DML (Debugger Markup Language)  link that can be clicked on to quickly enter the command into the debugger.

Passing .trap the address of a trap frame will show the register state when the trap was generated.  This will also set the context to the state when the trap was generated.  This information was saved into the trap frame by the trap handler that executed after  the trap occurred.

 The trap frame address listed above could have instead been obtained by dumping out the stack using the command  kv .  !analyze –v is very good at displaying  the correct trapframe, however I feel that it is a good practice to dump out the stack to verify that the trap frame you are entering is in fact the one that you are interested in. You can see in the output below that there are two trapframes listed. I am interested in the topmost one that matches the trap that led us to the bugcheck. I can see that analyze –v has listed the trapframe that we are interested in, so I entered it into the debugger.

0: kd> kv

ChildEBP RetAddr  Args to Child             

f40098d8 808692ab 00000050 ffffff50 00000000 nt!KeBugCheckEx+0x1b (FPO: [5,0,0])

f4009928 80836c2a 00000000 ffffff50 00000000 nt!MmAccessFault+0x813 (FPO: [4,10,4])

f4009928 80846dd1 00000000 ffffff50 00000000 nt!KiTrap0E+0xdc (FPO: [0,0] TrapFrame @ f4009940)

f40099b0 809426b2 a9131e08 00000012 861ce318 nt!ObReferenceObjectSafe+0x3 (FPO: [0,0,0])

f40099c8 808544d9 861ce318 0007d960 00000000 nt!PsGetNextProcess+0x6c (FPO: [1,1,0])

f4009a58 8094292f 01210048 0007d960 00000000 nt!ExpGetProcessInformation+0x36d (FPO: [SEH])

f4009d4c 80833bef 00000005 01210048 0007d960 nt!NtQuerySystemInformation+0x11e0 (FPO: [SEH])

f4009d4c 7c8285ec 00000005 01210048 0007d960 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f4009d64)

 

0: kd> .trap 0xfffffffff4009940

 

The output from the .trap command will be similar to the ouput from the r command. The  r command will dump out the registers and the current instruction that caused the error. Listed below are the output of the two commands:

0: kd> .trap 0xfffffffff4009940

ErrCode = 00000000

eax=861ce300 ebx=808b5be8 ecx=ffffff68 edx=ffffff50 esi=8747c8d0 edi=00000000

eip=80846dd1 esp=f40099b4 ebp=f40099c8 iopl=0         nv up ei pl nz ac pe cy

cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00010217

nt!ObReferenceObjectSafe+0x3:

80846dd1 8b0a            mov     ecx,dword ptr [edx]  ds:0023:ffffff50=????????

 

0: kd> r

Last set context:

eax=861ce300 ebx=808b5be8 ecx=ffffff68 edx=ffffff50 esi=8747c8d0 edi=00000000

eip=80846dd1 esp=f40099b4 ebp=f40099c8 iopl=0         nv up ei pl nz ac pe cy

cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00010217

nt!ObReferenceObjectSafe+0x3:

80846dd1 8b0a            mov     ecx,dword ptr [edx]  ds:0023:ffffff50=????????  ß This is the current instruction. We trapped on this instruction trying to dereference edx which contained ffffff50.

 

Next, we shall  dump out the stack and try to get a feel for what happened based on the function names listed in the stack. Remember that the functions at the bottom of the stack called the functions above them.  Here are the function names listed in the  top four stack frames along with my annotation. In this case I read the stack starting at the bottom and working my way up instead of the traditional way of starting at the bad value and backtracing to the problem.

0: kd> kcL4

·         nt!ObReferenceObjectSafe ß Finally, this function encountered the bad value and crashed. To observe this for yourself, please examine  the output of the 'r' command listed above.  You will notice that the current instruction at the time of the trap (the address in EIP) was unassembled. Above this instruction the function name and offset are listed  as nt!ObReferenceObjectSafe+0x3.  This means that the instruction we were executing when the trap occurred was located at offset 0x3 from the location that the symbol ObReferenceObjectSafe references.

·         nt!PsGetNextProcess ß Based on the function name here, it appears that we were trying to traverse the linked list of active processes on the system.

·         nt!ExpGetProcessInformation ß NtQuerySystemInformation() called this function. Based on the function name GetProcessInformation and the call listed above,  this was obviously an attempt to get information about the processes running on the system

·         nt!NtQuerySystemInformation ß We were trying to query system information

                Normally, my next step would typically be to unassemble the current function with  uf @$ip , locate the current instruction in the output by pasting the address in eip into the find diaglog box, and proceed to backtrace the source of the bad value until I had located the source. However, I have a bad habit of poking around for fun by dumping out various data while I am debugging. The  function names on the stack seemed to indicate that we were working with the list of processes. The address we died on suggested that we may have encountered a null pointer. I couldn't resist pausing a moment to dump out the list of processes on the system to see if we had encountered a null pointer while traversing the list of processes on the system. After all, I've reviewed dumps before that were that simple. Even if I found a null pointer in the list, I would still have to perform the actual debug and walk the assembly to prove it and identify how we crashed.  However, I felt it would be more exciting to work in the reverse of my normal  methods. Besides, it only takes a moment once you know what you are doing.

Let me pause a moment to provide a little background information here which will later prove relevant in understanding my method of thinking and comprehending what went wrong. In the nt!_EPROCESS  object there is a _LIST_ENTRY structure  located at offset 0x98 called ActiveProcessLinks. This forms a linked list of all the active NT!_EPROCESS structures on the system.  Let us first examine the _ LIST_ENTRY structure by reviewing the output below:

1: kd> dt nt!_LIST_ENTRY

   +0x000 Flink            : Ptr32 _LIST_ENTRY

   +0x004 Blink            : Ptr32 _LIST_ENTRY

As you can see above, a _LIST_ENTRY contains two pointers that create what is called a linked list. Blink represents a backwards link and Flink represents a forward link.  A double linked list may be traversed in either direction by following the pointer to the next or previous entry in the list. Linked lists are used heavily in operating system programming.  This particular  linked list contains a pointer to the previous _EPROCESS object’s ActiveProcessLinks field (blink) and the next _EPROCESS object’s ActiveProcessLinks field (flink).. The following command will display the activeprocesslinks field of the nt!_EPROCESS structure.

0: kd> dt nt!_EPROCESS activeprocesslinks

   +0x098 ActiveProcessLinks : _LIST_ENTRY  ß the +0x098 lets us know that this field is located 0x98 from the start of each  nt!_EPROCESS structure.  All of these EPROCESS structures on the system are linked together using the flink/blink method. This allows us to enumerate all of the processes on the system by following the links in either direction.

The first entry of a linked list is commonly referred to as the list head. The  list head is a _LIST_ENTRY structure that points to the first and last entry of the link list. Global variables are often used to store the location of the list head. Once you have the location of the head, you can then use it's flink/blink values to traverse the list in either direction.   Nt!PsActiveProcessHead is a global variable that points to the beginning of the list of Active Processes that we discussed in the previous paragraph. If you traverse this list starting at the head, you will end up in the activeprocesslinks field of each process on the system. This will allow code to find each _EPROCESS structure on the system by simply traversing this list. If you are an true geek like me and are  learning this for the first time, you are probably going to  fire up your debugger and dump out the list of active processes on your own system before you reach the end of this article.

Please note that by following the flink/blink you will arrive at offset 0x098 from this structure, not the start of the structure. So the complete list consists of a _LIST_ENTRY field present in each EPROCESS structure + the _LIST_ENTRY located at the memory referenced by the global variable nt!PsActiveProcessHead. You can use the 'x' examine symbols command to display this variable. I included the wildcards below only to demonstrate the ability to use wildcards with these commands.

0: kd> x nt!*PsActiveProcessHead*

808b5be8 nt!PsActiveProcessHead = <no type information>

0: kd> dt nt!*PsActiveProcessHead*

808b5be8  ntkrnlmp!PsActiveProcessHead

Back to our investigation.  At the point where we left off, we had not yet dug into the code to identify exactly what happened. We instead took an educated guess and decided to dump out the list of processes on the system. If it is found that we have a null value, this may very well allow us to work in reverse of our normal debugging.   Armed with the above background  information, we shall now dump out the list. If we get lucky, this will expedite the review of this memory dump by telling us what may have gone wrong before we even start digging into the code.

The beginning of the list sounds like a good place to start traversing  the entries. The value highlighted in the global variable above marks the address where the linked list starts. The following command will dump out this location and provide you with the flink and blink. The switch /c1 was used in order to limit the output to 1 column for easy blog annotation. For more information on the /c1 switch, type .hh dd into the debugger command interpreter and then press enter once the help file window appears.

0: kd> dd /c1 nt!PsActiveProcessHead L2

808b5be8  8a78c800  ß this is the forward link (flink)

808b5bec  85ddd510  ß this is the backwards link (blink)

                Now that we have the address that the list starts at, we need a way to dump it out. Windbg provides many ways  to automatically walk a linked list. You can use dt, !list, or the dl commands . In this case, let's use the  command 'dl' due to its simplicity . More information about this command may be obtained from the help file that is included with windbg.

0: kd> dl 0x8a78c800 ff 2   ß Here is an example of how to use this command to traverse the linked list starting at address 0x8a78c800. The value ff represents the maximum number of links to display. The value 0x8a78c800 was obtained from the flink field _LIST_ENTRY present at the global variable listed above. The value 2 represents the number of values to dump from each address. Since this linked list contains a forward link (flink) and backwards link (blink), we should pass in a value of 2 to dump both addresses.

As displayed below, I decided to use the global nt!PsActiveProcessHead instead of specifying an address to the command dl.  Here is the beginning of the output as displayed by the debugger.

0: kd> dl nt!PsActiveProcessHead ff 2

808b5be8  8a78c800 85ddd510 

8a78c800  89af0370 808b5be8  

888745a0  888492e0 89af0370

888492e0  89b17708 888745a0

89b17708  89b4e3d0 888492e0

... … Ommitting the rest of the output

                The plain output displayed above represents the type of output that you will see when entering the dl command into the debugger. In order to better illustrate the patterns and show the relationship between the flink and blink values,  I have bolded, underlined, highlighted, and commented various portions of the output and listed it below. Note the annotations that demonstrate how each member of the linked list points to the next and previous item. You can follow the list all the way down until you see we do in fact end up at a zeroed out address.

0: kd> dl nt!PsActiveProcessHead ff 2

808b5be8  8a78c800 85ddd510  <-- Notice that the dl command first displays  address  808b5be8 which is the address referenced by the symbol information for the global variable nt!PsActiveProcessHead that we provided. The next two values are the flink and the blink. I have highlighted the flink above. Notice how this flink is pointing to the next memory location listed below.

8a78c800  89af0370 808b5be8   <--  In this line of output, notice that the dl command has followed the flink to address 8a78c800  (which I have again highlighted)  and  is dumping out the new  flink and blink pair.  I have underlined the blink. Notice that the blink  points back to the address of the previous flink/blink pair.  

89af0370  888745a0 8a78c800  Notice the  patterns displayed, follow the output  all the way to the bottom, and see if you notice anything that may be a problem.

888745a0  888492e0 89af0370

888492e0  89b17708 888745a0

89b17708  89b4e3d0 888492e0

89b4e3d0  8883fe20 89b17708

8883fe20  89ab73e8 89b4e3d0

89ab73e8  887d7650 8883fe20

887d7650  888906a8 89ab73e8

888906a8  89483408 887d7650

89483408  88839d40 888906a8

… Ommitting output to reduce length. The links were all valid…

85ff6e20  8708be20 8663a278

8708be20  87176940 85ff6e20

87176940  861ce3b0 8708be20

861ce3b0  860010b8 87176940

860010b8  00000000 00000000   <-- Wait...This doesn't look correct. The blink should be 861ce3b0, not zero. The previous list entry's flink took us here to address 860010b8. It appears that our theory might just be correct. Observing this,  I suspected that memory location  860010b8 has been overwritten with zeros. It is also possible, however, that the value in the flink above was incorrect causing us to end up at some random address that contained zeros. To know for sure I dumped the list backwards to see if the next flink/blink pair had a blink pointing to 860010b8.

0: kd> dlb nt!PsActiveProcessHead ff 2ß This command dumps the list backwards. Below you can see the dlb command walking the linked list by starting at the list head and moving backwards (the list should make a circle). Don't be confused by the different patterns below. This is simply due to the fact that the list is being walked backward. The output displays the three value in the same order  address   flink  blink.

0: kd> dlb nt!PsActiveProcessHead ff 2

808b5be8  8a78c800 85ddd510 

85ddd510  808b5be8 85e58e20

85e58e20  85ddd510 8646ce20

8646ce20  85e58e20 85d92c08

85d92c08  8646ce20 8616ce20

… Ommitting output to reduce length. The links were all valid…

872ba380  86e456a0 86c8da10

86c8da10  872ba380 8692f708

8692f708  86c8da10 86d630b8

86d630b8  8692f708 8673eae0

8673eae0  86d630b8 87223a98

87223a98  8673eae0 860010b8  

860010b8  00000000 00000000    ß We arrived at the same address of 860010b8. So when walking the list both forward and backward we encounter pointers that take us to this address. This means that there should have been a valid flink/blink pair (which would be a valid nt!_EPROCESS activeprocesslinks _LIST_ENTRY ) at this address.  This memory appears to have instead been zeroed out. It’s flink pointer should be 87223a98 

When dumping the list out forward using dl, the line of output representing 860010b8 should have contained these values below, however it did not.

860010b8  87223a98  861ce3b0 

So what happed? In dumping out the area around the address, you can see it has been zeroed

0: kd> dd 860010b8-200 860010b8+200

86000eb8  00000000 00000000 00000000 00000000

86000ec8  00000000 00000000 00000000 00000000

86000ed8  00000000 00000000 00000000 00000000

86000ee8  00000000 00000000 00000000 00000000

… Ommitting output to reduce length. Entire range contained all zeros…

86001088  00000000 00000000 00000000 00000000

86001098  00000000 00000000 00000000 00000000

860010a8  00000000 00000000 00000000 00000000

860010b8  00000000 00000000 00000000 00000000

860010c8  00000000 00000000 00000000 00000000

860010d8  00000000 00000000 00000000 00000000

860010e8  00000000 00000000 00000000 00000000

… Ommitting output to reduce length. Entire range contained all zeros…

86001288  00000000 00000000 00000000 00000000

86001298  00000000 00000000 00000000 00000000

860012a8  00000000 00000000 00000000 00000000

860012b8  00000000

Out of curiosity, I ran the !address command to see what range this address falls into.

0: kd> !address 860010b8

  82b7e000 - 07c82000                          

          Usage       KernelSpaceUsageNonPagedPool

Next, we dump the pool information out. Note the corruption indication listed below.

0: kd> !pool 860010b8

Pool page 860010b8 region is Nonpaged pool

86001000 is not a valid large pool allocation, checking large session pool...

86001000 is freed (or corrupt) pool

Bad allocation size @86001000, zero is invalid

***

*** An error (or corruption) in the pool was detected;

*** Attempting to diagnose the problem.

***

*** Use !poolval 86001000 for more details.

***

 

0: kd> !poolval 86001000

Pool page 86001000 region is Nonpaged pool

Validating Pool headers for pool page: 86001000

Pool page [ 86001000 ] is __inVALID.

Analyzing linked list...

[ 86001000 --> 86001310 (size = 0x310 bytes)]: Corrupt region

Scanning for single bit errors...

None found

So now that we have opened the dump, set the trap frame, dumped the stack, then found  the answer. Now, we need to do the actual debug of the assembly code to both prove our theory and determine how this caused us to die. Let's revisit the activeprocesslinks field that we discussed before.

0: kd> dt nt!_EPROCESS activeprocesslinks

   +0x098 ActiveProcessLinks : _LIST_ENTRY  ß the linked list we were following is located 0x98 from the start of the nt!_EPROCESS.  The previous _LIST_ENTRY provided us with the address of this field by in the next process object. To get the start of the actual process object, we need to subtract 0x98 from that value. For example, if you were passed in a null address instead of a valid pointer and subtracted 0x98 you would get:

0: kd> ? 0x0-0x098 

Evaluate expression: -152 = ffffff68  ß If we start with a null value and backup 0x98 we get ffffff68 

As you can see below, that very value happens to be present in ECX. ECX should instead be the address of our process object. However,since our liked list pointer was null, we instead were following an invalid address. It’s all downhill from here:

0: kd> recx  ß What’s in ECX?

Last set context:

ecx=ffffff68   ß it’s the offset from the null pointer

 

Let’s keep digging to verify this by looking back in the assembly and walking through what happened in the final moments of the crash. To do this, I unassembled backwards using the ub command. Examination of the output of this command (listed below but limited to only one command for blog simplicity) will show that the code took the invalid address ffffff68 that should have been a pointer to the process object and subtracted 0x18. This gave the us the invalid address ffffff50 that we died on. The . represents the current instruction pointer and the L1 tells us to only display 1 unassembled assembly language instruction.

0: kd> ub . L1

nt!ObReferenceObjectSafe

80846dce 8d51e8          lea     edx,[ecx-18h]   ß we took the process object pointer in ecx and subtracted 0x18 from it and put it into edx to dereference

 

0: kd> redx

edx=ffffff50

 

0: kd> ? ffffff68-0x18

Evaluate expression: -176 = ffffff50

 

Next, we tried to dereference this invalid pointer. Note that @$ip is another way (just like .)to point to the instruction pointer.

0: kd> u @$ip L1

nt!ObReferenceObjectSafe+0x3:

80846dd1 8b0a            mov     ecx,dword ptr [edx]  ß edx contains the invalid value

You can also use the r command to dump out all of the registers and display this failed instruction as shown below.

0: kd> r

Last set context:

eax=861ce300 ebx=808b5be8 ecx=ffffff68 edx=ffffff50 esi=8747c8d0 edi=00000000

eip=80846dd1 esp=f40099b4 ebp=f40099c8 iopl=0         nv up ei pl nz ac pe cy

cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00010217

nt!ObReferenceObjectSafe+0x3:

80846dd1 8b0a            mov     ecx,dword ptr [edx]  ds:0023:ffffff50=????????  ß we trapped trying to dereference the bad address that edx was directing us to

So, why would we be backing up from this address? Each process object has an Object Header that precedes it. The following command ?? uses the current Expression Evaluator (C++ is the default) to run  the sizeof() function against  the nt!_OBJECT_HEADER symbol information and output the size of the an object header.

0: kd> ?? sizeof (nt!_OBJECT_HEADER)

unsigned int 0x20

You can dump out this header to see where the start of the process object is with the following command

0: kd> dt nt!_OBJECT_HEADER

   +0x000 PointerCount     : Int4B  ß the code was accessing the offset 0 of the Object Header which is the PointerCount field

   +0x004 HandleCount      : Int4B

   +0x004 NextToFree       : Ptr32 Void

   +0x008 Type             : Ptr32 _OBJECT_TYPE

   +0x00c NameInfoOffset   : UChar

   +0x00d HandleInfoOffset : UChar

   +0x00e QuotaInfoOffset  : UChar

   +0x00f Flags            : UChar

   +0x010 ObjectCreateInfo : Ptr32 _OBJECT_CREATE_INFORMATION

   +0x010 QuotaBlockCharged : Ptr32 Void

   +0x014 SecurityDescriptor : Ptr32 Void

   +0x018 Body             : _QUAD  ß The process object is located here at offset 0x18. This means that backing up 0x18 would put you at offset 0x0 of the object header which is the Pointer Count field.

 

So let’s see if we can locate any stack data to validate this. Dumping the stack again, I observe the address of the process object.

 

0: kd> kvL2

ChildEBP RetAddr  Args to Child             

f40099b0 809426b2 a9131e08 00000012 861ce318 nt!ObReferenceObjectSafe+0x3 (FPO: [0,0,0])

f40099c8 808544d9 861ce318 0007d960 00000000 nt!PsGetNextProcess+0x6c (FPO: [1,1,0])

 

Let’s dump out this process field. Wow! Look what we have here. The address of the zeroed list entry from above.

0: kd> dt nt!_EPROCESS 0x861ce318 ActiveProcessLinks

   +0x098 ActiveProcessLinks : _LIST_ENTRY [ 0x860010b8 - 0x87176940 ]

 

0: kd> dd 0x860010b8 L2

860010b8  00000000 00000000

So to summarize the problem, we crashed because a memory address that should have contained valid flink/blink pointers to a process object contained the invalid value 00000000.  We expected this value to be pointing to a valid nt!_EPROCESS  ActiveProcessLinks field instead of containing a null pointer (zero). After obtaining this null pointer, we then subtracted 0x098 which normally would have brought us to the start of the process object. Instead we ended up with invalid pointer 0xffffff68. Finally, we subtracted another 0x18 which should have brought us to the PointerCount  field of the object header. This gave us address 0xffffff50 instead of a valid object header address. We then dereferenced this invalid address which led us to the bugcheck.

This crash was due to pool corruption, as shown in the output of the !pool command above.  This blog has been a walkthrough of debugging a memory dump and identifying how pool corruption led up to a crash. Identification of the reason for the corruption is a separate matter. These types of issues are often difficult to troubleshoot due to the fact that any driver in kernel mode could have corrupted this memory region. To further complicate matters, the actual corruption of this memory may have taken place millions of CPU cycles before the time this code stumbled across the corrupted region leading up to the crash that caused this memory dump to be initiated. A memory dump is simply a snapshot of information relating to the state of a system during one particular moment in time.  

                In this case, in order to identify the source of the pool corruption we need to use Special Pool.  Special Pool will use guard pages to catch a buffer overrun or underrun and should provide us with a dump that shows the code that causes the corruption.  You can find more information on Special Pool in KB188831.  Also, in some situations memory corruption can be caused by a driver overflowing on a DMA transfer causing corruption to physical pages rather than virtual pages as we see in typical pool corruption.

                Usually, a debug such as this one would have started with analysis of the function at the top of the stack and worked  down the stack reading the assembly to definitively identify the source of the bad pointer. However in this case, we were lucky enough to find the answer right away and then validate it with conventional debugging methods by reversing in reverse.

Share this post :

Hi, my name is Todd Webb, I am an Escalation Engineer from the Global Escalation Services OEM Team.

I recently worked a case where we were trying to troubleshoot an issue and the system would hang with USB debugging enabled. This was a problem since USB debugging was the only kernel debugging option available on this particular hardware setup. I needed a quick and easy way to find the source of the problem without using many of the standard methods.  Basically I had to debug a debugger issue with no access to a debugger.  I knew the problem was likely USB related, but had no other information.  The method I used to troubleshoot this issue was to write some macros that would make a call to HalMakeBeep to generate audible indications of where we were in the code.  The primary reason for using this method was I could quickly and easily move the location in the code where I made the calls as I narrowed down where the problem occurred. 

The alternative would have been to add a bunch of logging and find some way to force a dump.  My initial assessment was this would be more time consuming and less flexible then the beep code method.  Others may have other methods to do this, but this just gives people another method of debugging driver start-up problems on systems that are not debuggable.

The main beep macro allows you to pass in a frequency and duration in milliseconds for a single beep.  Then based on the example below you can extend the single beep macro to create a series of beeps.

Here is an example of the macros I used:

//

// beep macros for troubleshooting without debugger

//

#define EHCI_BEEP1(f, d)                                              \

    {                                                                 \

        LARGE_INTEGER duration;                                       \

        duration.QuadPart = Int32x32To64(d, -10000);                  \

        HalMakeBeep(f);                                               \

        KeDelayExecutionThread(KernelMode, FALSE, &duration);         \

        HalMakeBeep(0);                                               \

        duration.QuadPart = Int32x32To64(500, -10000);                \

        KeDelayExecutionThread(KernelMode, FALSE, &duration);         \

    }

#define EHCI_BEEP2(f, d)                                              \

    {                                                                 \

        EHCI_BEEP1(f, d);                                             \

        EHCI_BEEP1(f, d);                                             \

    }

#define EHCI_BEEP3(f, d)                                              \

    {                                                                 \

        EHCI_BEEP2(f, d);                                             \

        EHCI_BEEP1(f, d);                                             \

    }

Here is an example of a long beep followed by three short beeps:

    //

    // debug - 1 long : 3 short

    //

    EHCI_BEEP1(600, 1000);

    EHCI_BEEP3(600, 500);

Share this post :

Trey Nash here again, and I would like to discuss a scenario we are all too familiar with.  You’ve worked your tail off for the past year, and for the past couple of months you even worked evenings and weekends.  Management rewarded your team with two weeks off in appreciation of your efforts.  But now that you’re back in the office, you’re hearing rumors percolating up from your tech support department that there are some cases where your application is crashing in the field for mysterious reasons.  What do you do?

The application happens to have been built with an unhandled exception filter registered via the AppDomain.UnhandledException event.  Therefore, you at least know that the application is failing with an InvalidCastException, but you cannot imagine why this is happening.

Wouldn’t it be nice if you could live debug on the affected system?  Unless you work on-site for your customer or your software is on a laptop and your customer is willing to send it to you, then I doubt you will get this opportunity.  What you need is a tool to capture the state of your application while it is failing.  Then the customer could capture this information and send it to you.

Enter ADPlus.  ADPlus is a free tool in the Debugging Tools for Windows package that scripts the CDB debugger allowing you to capture dumps for one or multiple processes on a system.  It also offers the following advantages:

·         ADPlus can monitor desktop applications, services, etc.

·         ADPlus can monitor multiple processes on the system.  When it collects a dump of those processes, it freezes and dumps them simultaneously.  This is essential for tracking down problems with inter-process communications.

·         ADPlus supports xcopy deployment meaning the customer does not need to install anything via Windows Installer, etc.  This minimizes configuration changes on the machine, and that is music to customers’ ears.  

With all of that said, let’s see how ADPlus can help you diagnose problems with .NET applications.

The Sample Application

In the rest of this post, I will reference the C# 3.0 sample application that I have put together to illustrate using ADPlus to capture an unhandled exception in a .NET application.  The code is listed below:

using System;

using System.Linq;

using System.Runtime.Serialization;

class A

{

    public void SaySomething() {

        Console.WriteLine( "Yeah, Peter...." );

        throw new BadDesignException();

    }

}

class B : A

{

}

class C

{

}

class EntryPoint

{

    static void Main() {

        DoSomething();

    }

    static void DoSomething() {

        Func<int, object> generatorFunc = (x) => {

            if( x == 7 ) {

                return new C();

            } else {

                return new B();

            }

        };

        var collection = from i in Enumerable.Range( 0, 10 )

                         select generatorFunc(i);

        // Let's iterate over each of the items in the collection

        //

        // ASSUMING THEY ARE ALL DERIVED FROM A !!!!

        foreach( var item in collection ) {

            A a = (A) item;

            try {

                a.SaySomething();

            }

            catch( BadDesignException ) {

                // Swallow these here. The programmer chose to

                // use exceptions for normal control flow which

                // is *very* poor design.

            }

        }

    }

}

public class BadDesignException : Exception

{

    public BadDesignException() { }

    public BadDesignException( string msg ) : base( msg ) { }

    public BadDesignException( string msg, Exception x ) : base( msg, x ) { }

    protected BadDesignException( SerializationInfo si,

                                  StreamingContext ctx )

        :base( si, ctx ) { }

}

You can compile this sample code easily by putting it in a file, such as test.cs, and then from either a Visual Studio Command Prompt or from a Windows SDK Command Shell, execute the following:

csc /debug+ test.cs

The notable section of the code to focus on is the foreach loop within the EntryPoint.Main() method.  In that foreach loop, we are iterating over a collection of objects where we are assuming that they all derive from type A.  Thus the code attempts to cast all instances to a reference of type A and since I have intentionally put an instance of type C within that collection, it will fail at some point with an exception of type System.InvalidCastException.

Capturing the Problem

Using ADPlus in crash mode, we can capture the exception in the customer’s environment.  To illustrate this in action, let’s launch ADPlus in crash mode and monitor the test.exe example application built above by using the following command line:

adplus -crash -o c:\temp\test -FullOnFirst -sc c:\temp\test\test.exe

ADPlus is easier to launch if you add the directory where the Debugging Tools for Windows was installed to your PATH environment variable.  The command line above assumes this has been done.  Now, let me explain the command line options that I used above.  I highly recommend that you become familiar with all of the ADPlus command line options.

·         -crash launches ADPlus in crash mode.  This is the mode you want to use if your application is failing because of an unhandled exception.

·         -o c:\temp\test tells ADPlus that I want the output to be placed in c:\temp\test, which is the directory in which I built the test.exe application.

·         -FullOnFirst is very important for managed applications..  This tells ADPlus to grab a full process dump on first chance exceptions.  It is essential that you capture full dumps for managed applications, otherwise, all of the necessary data regarding the execution engine and the managed heap will be absent from the dump making it impossible to debug effectively.

·         -sc c:\temp\test.exe is only one of the ways you can point ADPlus to an application to monitor.  In this case, we’re instructing ADPlus to tell the debugger to explicitly launch the application.  Had it been a service, or if the application you want to monitor is already running, we would probably have used –p to attach to its PID or –pn to attach to the process by name.  Notice that I provided the full path to the application.

After you launch ADPlus, you are presented with the following dialog unless you use the –quiet option.

Once the application is finished executing, go to the directory that you specified in the ADPlus –o command line option and you should see a subdirectory named similarly to what you see in the previous dialog snapshot.  For the instance of test.exe I just executed, that directory is named Crash_Mode__Date_05-11-2009__Time_21-12-54PM.  Under that directory, there are quite a few files that I have listed below:

C:\temp\test\Crash_Mode__Date_05-11-2009__Time_21-12-54PM>dir /b
ADPlus_report.txt
CDBScripts
PID-0__Spawned0__1st_chance_CPlusPlusEH__full_15ac_2009-05-11_21-13-01-332_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-55-482_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-56-527_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-57-370_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-58-103_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-58-867_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-12-59-663_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-13-00-505_0eac.dmp
PID-0__Spawned0__1st_chance_NET_CLR__full_15ac_2009-05-11_21-13-02-689_0eac.dmp
PID-0__Spawned0__1st_chance_Process_Shut_Down__full_15ac_2009-05-11_21-13-27-743_0eac.dmp
PID-0__Spawned0__2nd_chance_NET_CLR__full_15ac_2009-05-11_21-13-04-140_0eac.dmp
PID-0__Spawned0__Date_05-11-2009__Time_21-12-54PM.log
Process_List.txt

For each first chance exception, a dump file (.dmp) has been collected.  Notice that the dump files can tend to be very large because of the –FullOnFirst option.  You can subsequently load these dump files into either Windbg (or its variants) or the Visual Studio Debugger.  Personally, I prefer Windbg because I can then load the SOS extension along with the SOSEX extension and dig into the state of the application and the CLR.

Using the ADPlus default configuration as we have above, you can see that ADPlus generated dumps for one first-chance C++ exception, eight first-chance CLR exceptions, one second-chance CLR exception and one dump collected during process shut down.

What is Included in the Output

If you look in your Debugging Tools for Windows directory, you’ll notice that ADPlus is really just a very complex VBScript.  It generates quite a bit of useful information along with any problem dump files.  ADPlus_report.txt reports the configuration for ADPlus for this run.  This is handy if you need to know what it will do for a specific type of exception.

Process_list.txt is generated from executing tlist.exe, another tool that comes with Debugging Tools for Windows.

And finally, the CDBScripts subdirectory contains a .cfg file which is the exact debugger script ADPlus generated and subsequently fed to CDB to get the job done.  On my machine, when running against the sample application using the command line from the previous section, this file is named PID‑0__Spawned0.cfg.  If you’re ever curious or need to know exactly what ADPlus instructed the debugger to do, this file is the source.

I don’t recommend executing this debugger script in a live debugger as doing so could overwrite the data that you already have collected.  Instead, if you need to couple ADPlus with live debugging, you should use the –gs option which I will describe shortly.

Pinpointing a Specific Exception

You’ll notice that in the previous run of ADPlus, quite a few dump files were generated and each one was fairly large.  In reality, there are times where a first chance exception does not always indicate a fatal situation.  In Accelerated C# 2008, I go into detail regarding how it is poor design practice to implement any sort of control flow or otherwise reasonably expected behavior using exceptions.  This is because exceptions are supposed to be truly exceptional events!  For more juicy details on how expensive exceptions are, I invite you to read an excellent blog post by Tess Ferrandez on the topic. At any rate, you may encounter situations where you get a lot of dumps for first chance exceptions you are not interested in as this example shows..

To alleviate this situation, you can create an ADPlus configuration file coupled with the !StopOnException command provided by the SOS extension to instruct ADPlus to filter out only the exceptions you’re interested in.  To do this, I created a configuration file named filter.config with the following contents:

<ADPlus>

    <!-- Configuring ADPlus to log only exceptions we're interested in -->

  <Exceptions>

     <Config>

        <!-- This is for the CLR exception -->

       <Code> clr </Code>

       <Actions1> Log </Actions1>

       <CustomActions1> .loadby sos mscorwks; !StopOnException System.InvalidCastException 1; j ($t1 = 1) '.dump /ma /u c:\dumps\InvalidCastException.dmp; gn' ; 'gn'  </CustomActions1>

       <ReturnAction1> VOID  </ReturnAction1>

       <Actions2> Log </Actions2>

     </Config>

  </Exceptions>

</ADPlus>

The <CustomActions1> element is the element of interest in this configuration file.  This element allows you to specify which commands the debugger should execute on first chance exceptions.  Within this element, you can put any valid debugger commands (except windbg GUI-related commands).  If you need to execute multiple commands, as I have above, you simply separate them with semicolons.  In the <CustomActions1> element shown above, I first load the SOS extension using the .loadby command.  Then, I use the !StopOnException command in predicate mode to set the $t1 pseudo-register to 1 if the exception is of type System.InvalidCastException and 0 otherwise.  Then, the following j command is used to create a full dump if $t1 is 1 and do nothing otherwise.  The gn command in both paths of the j command tells the debugger to go unhandled so that the exception is propagated up rather than swallowed by the debugger.  If you were to go handled, thus swallowing the exception, the exception handlers in the code would never see it and the debugger would alter the behavior of the application.  And finally, note that the .dump command used to create the dump indicates the path where the dump will be stored.  In this case, I am placing it in the c:\dumps directory on my machine.

Now you can provide this configuration file to ADPlus using the following command:

adplus -crash -o c:\temp\test -FullOnFirst -c c:\temp\test\filter.config -sc c:\temp\test\test.exe

Notice that there are fewer dumps collected.  Along with the dump for the InvalidCastException, it also captures a C++ exception as well as when the application shuts down.  If you open the C++ exception dump in the debugger and inspect the stack, it shows that the CLR is in the process of generating the InvalidCastException.  The CLR catches the C++ exception and converts it into a managed exception.  The C++ exception dump was generated because I left the –FullOnFirst option in the previous command line.  You can eliminate the C++ exception dump by removing -FullOnFirst.

Using ADPlus during Live Debugging

I already hinted at the –gs ADPlus command line option earlier in this post.  This option allows you to create the debugger scripts ADPlus creates without actually running them in the debugger.  For example, if you execute the following command (I executed mine from my c:\temp\test directory):

adplus -crash -o c:\temp\test -FullOnFirst -c c:\temp\test\filter.config -gs livedebug

You will notice that ADPlus does not actually launch any debugger or your application.  Rather, it creates a subdirectory named livedebug.  When you go into that directory, you’ll notice it looks similar in layout to the crash directories created in the previous demonstration.  On my machine, I end up with the following two files:

C:\temp\test\livedebug\ADPlus_report.txt
C:\temp\test\livedebug\CDBScripts\PID-0__livedebug.cfg

The PID-0__livedebug.cfg file is actually a debugger script file containing debugger commands.  All we have to do now is launch our test application in the debugger and then execute this script.  Within my c:\temp\test directory, I can launch the debugger using the following command:

windbg test.exe

Once inside the debugger, I can invoke the ADPlus debugger script by executing the following $$< command:

$$<C:\temp\test\livedebug\CDBScripts\PID-0__livedebug.cfg

Once you execute the $$< command, you will notice that the script takes over and performs the same actions as ADPlus does when run conventionally from the command line.

As a further experiment, edit the filter.config file and remove the gn commands.  Now the debugger will wait for user input after executing the custom commands rather than continuing execution of the application.  This could be handy if you want the opportunity to perform debugging by hand if ADPlus encounters a certain situation.

First Chance vs. Second Chance Exceptions

Throughout this post, I have been focusing on first chance exceptions for the sake of illustration.  However, many times, you are only interested in the truly unhandled exceptions.  In that case, you would want to capture only second chance exceptions.  You certainly would want to capture first chance exceptions if you needed to capture the state at the exact point the exception was thrown and before the OS searches for any handlers.  Additionally, if you suspect that the application you are debugging may be handling an exception inappropriately (maybe even blindly swallowing it), then you certainly want to catch first chance exceptions in that case.

Conclusion

In this blog post I have introduced you to ADPlus and the utility it provides when troubleshooting problems in the field.  ADPlus lends itself well to capturing exceptional situations in the field since it requires no configuration changes on the affected machine thus making it an easy pill for your customers to swallow.  You may also find this very useful when working with your Quality Assurance team during the development phase.  For example, how many times have you encountered a situation where a problem only presents itself on a dusty old rarely-used machine in the back corner of a random QA engineer’s office?  How many times, in such situations, have you felt like the only way to trouble shoot the problem effectively is to install the Visual Studio debugger and start working on that machine?  Furthermore, what if the problem only happens on that dusty old machine about once a week.  ADPlus can help you avoid that madness by providing an easy mechanism for capturing full process dumps on the troubled machine so you can then take those dumps to your trusty development machine for further debugging and analysis.

Have fun out there!

Share this post :

Recently I was working with a customer who had a file server experiencing high CPU in the WMIprvse.exe process. We received multiple user dumps and noted that someone or something was running the same query again and again. We needed to figure out what was running the query in a tight loop, causing the high CPU.

Figure 1 - Task Manager on FileServer

I dumped out all the services in the various svchost.exe processes. You can do this from a command prompt by running the tasklist /svc command. In my instance, I found that the WinMgmt service was running in svchost, PID  452 (PID number will vary). Someone had to be making RPC calls to this svchost.exe process to run the WMI queries. It could be some local process on the machine; it could even be a process on a remote machine.

At this point I requested user dumps of PID 452 from the customer.  This would allow me to determine who was making the RPC calls to svchost.exe to run the WMI queries.  While the customer was uploading the dumps, we decided to get a Network Monitor trace to see if the RPC calls were coming over the network.

 

Immediately, I could see a lot of RPC traffic to the svchost.exe process(PID=452).

 

Figure 2 - Network Monitor Output from the FileServer. Notice the Source and destination ports and IP addresses. IP addresses are hidden by the aliases

Looking at the RPC payload, I could see the text of the WMI query. You can see this in the Hex Details Pane. The query that was running in a loop was “Select * from Win32_Process”. Looks like I found the source of the WMI queries.

 

At this point, we got the source IP for the RPC packets. We logged into the machine, and brought up the Task Manager.

 

Figure 3 - Task Manager on Remote Machine(Machine1)

Immediately we saw that there was some script running inside a Wscript.exe process.  At this point I was pretty sure that this script was the culprit. The customer was not sure what this was, and was not comfortable terminating the process.  To prove my suspicion, I had him open a command prompt and run the following command, netstat –ano.

 

Figure 4 - Netstat output from Remote Machine

 

From the output in Fig. 4, I could see a TCP connection created by PID 3532 (wscript.exe). Looking at the local and foreign addresses from the above output, they matched up exactly to what we were seeing in the Network Monitor trace.

 

In the above case, we already had our suspicions on the wscript.exe process; however, sometimes it might not be that easy. In that case, we could have used the netstat output to look at all connections to the file server (157.59.123.121). If there were multiple connections, then we can also narrow it down by the port number. Based on that, we could have found the PID responsible.

 

The customer called me later in the day, and told me that they had recently updated their scripts. One of their scripts had a bug which was running WMI scripts in a tight loop. Fixing the script caused the problem to go away.

 

Had the query being coming from a local process, I would have had to debug the svchost.exe process, and figure out who was making the WMI calls. However, since we could see the traffic on netmon, we didn’t need to use the debugger. Interesting way to get to the root of the problem without using a debugger!

 

 

Share this post :

Hi, my name is Anurag Sarin, and I'm an Escalation Engineer from the Platforms Global Escalation Services 24x7 Team, located in Bangalore, India.

Break on exception

Let's say Windows Media Player reports “RPC Server is unavailable” when a user clicks "File\Open" and attempts to browse to a remote computer. In this situation the ‘sxe’ command is your friend. This command ‘sets an exception’ from the debugger. When this is set the target breaks into the debugger before any other error handlers are activated

By the way, RPC_S_SERVER_UNAVAILABLE is win32 error 1722 (0x06ba) with the description “RPC Server is unavailable” and is a common networking issue.

 

This is how WinError.h in Windows SDK documents it

 

//

// MessageId: RPC_S_SERVER_UNAVAILABLE

//

// MessageText:

//

// The RPC server is unavailable.

//

#define RPC_S_SERVER_UNAVAILABLE         1722L

Here are the steps to catch the “RPC Server is unavailable” exception. 

1. Attach the debugger to the process with the RPC_S_SERVER_UNAVAILABLE error.  In our example we’ll attach to wmplayer.exe.

2. Break into debugger to set or verify the symbol path.

3. Reload the symbols.

.reload

4. Clear any previously set exceptions.

sdx  *

5. Set the exception on 1722 (0x06ba) i.e. RPC_S_SERVER_UNAVAILABLE “RPC Server is unavailable”.

sxe 06ba

6. Let the process run until we hit the exception. You may hit a different exception before the one you’re looking for in which case you hit 'g' to continue execution.

g

7. This is the output from the debugger on a Vista RTM machine.

From the stack above, you can clearly see that seven frames below the top is what ‘was’ happening just ‘before’ the dll got loaded. How do I get to the point just ‘after’ the module gets loaded? Well one way is to use ‘gu’ twelve times. Note: The purpose of this is to show you how to use the various exception related commands.