Nynaeve

Often times, one type of problem that you might want to track down in a debugger (aside from a crash) is a particular function failing in a certain way. In the case of most Win32 functions, you’ll often get some sort of (hopefully meaningful) last error code. Sometimes you might need to know why that error is returned, or where it originated from (in the case of a last error value that is propagated up through several functions).

One way you might approach this is with a conditional breakpoint, but the SetLastError path is typically frequently hit, so this is often be problematic in terms of performance, even in user mode debugging on the local computer.

On Windows Vista, there is an undocumented hook inside of NTDLL (which is now responsible for the bulk of the logic behind SetLastError) that allows you to configure a program to break into the debugger when a particular error code is being set as the last error. This is new to Vista, and as it is not documented (at least not anywhere that I can see), it might not be around indefinitely.

For the moment, however, you can set ntdll!g_dwLastErrorToBreakOn to a non-zero value (via the ed command in the debugger) to ask NTDLL to execute a breakpoint when it sees that last error value being set. Obviously, this won’t catch things that modify the field in the TEB directly, but anything using SetLastError or RtlSetLastWin32Error will be checked against this value (in the context of the debuggee).

For example, you might see something like this if you ask NTDLL to break on error 5 (ERROR_ACCESS_DENIED) and then try to open a file or directory that you don’t have access to:

0:002> ed ntdll!g_dwLastErrorToBreakOn 5
0:002> g

[...] Perform an operation to cause ERROR_ACCESS_DENIED

(1864.2774): Break instruction exception
  - code 80000003 (first chance)
ntdll!DbgBreakPoint:
00000000`76d6fdf0 cc              int     3
0:004> k
Call Site
ntdll!DbgBreakPoint
ntdll! ?? ::FNODOBFM::`string'+0x377b
kernel32!BaseSetLastNTError+0x16
kernel32!CreateFileW+0x325
SHELL32!CEnumFiles::InitAndFindFirst+0x7a
SHELL32!CEnumFiles::InitAndFindFirstRetry+0x3e
SHELL32!CFileSysEnum::_InitFindDataEnum+0x5e
SHELL32!CFileSysEnum::Init+0x135
SHELL32!CFSFolder::EnumObjects+0xd3
SHELL32!_GetEnumerator+0x189
SHELL32!CEnumThread::_RunEnum+0x6d
SHELL32!CEnumThread::s_EnumThreadProc+0x13
SHLWAPI!WrapperThreadProc+0xfc
kernel32!BaseThreadInitThunk+0xd
ntdll!RtlUserThreadStart+0x1d

(The debugger is slightly confused about symbol names in NTDLL due to the binary being reorganized into function chunks, but “ntdll! ?? ::FNODOBFM::`string’+0x377b” is part of ntdll!RtlSetLastWin32Error.)

Sometimes, it can be useful to add “debugger knobs” like this to your program that can be used to enable special diagnostics behavior that might be useful while debugging something. Several other components provide options like this; for example, there’s a global variable in NTDLL named ntdll!ShowSnaps that you can set to 1 in order to enable a large volume of debug print spew about the symbol import resolution process when the loader is resolving imported modules and symbols.

(Incidentally, debugger-settable global variables like ntdll!ShowSnaps are a good example of a correct way of using debug prints in release builds, though there are certainly many other good ways to do so.)

Update: Andrew Rogers points out that g_dwLastErrorToBreakOn existed on Srv03 as well, though it was resident in kernel32 (kernel32!g_dwLastErrorToBreakOn) and not NTDLL in that timeframe. As the last error logic was finally moved entirely to NTDLL in the Vista timeframe, so was the last error breakpoint hook.

Update: Pavel Lebedinsky points out that I neglected to mention that as a consequence of the internal BaseSetLastNTError routine in kernel32 on Srv03 not going through kernel32!SetLastError, the functionality available in Srv03 is generally much less useful (only catches things external to kernel32) than in Vista. Which, to be clear, is more my fault in not making this point known and not Andrew getting it wrong.

One of the things that was changed around the Windows XP era or so in the driver development world was the introduction of the DbgPrintEx routine. This routine was introduced to combat the problem of debug spew from all sorts of different drivers running together by allowing debug prints to be filtered by a “component id”, which is supposed to be unique per class of driver. By allowing a user to filter which debug prints are being displayed by driver, on the host-side instead of the debugger side, a better debugging experience can be provided when the system is fairly “crowded” as far as debug prints go. This is especially common on checked builds of the operating system.

Additionally, DbgPrintEx provides an additional mechanism to filter output host-side – a severity level. The way the filtering system works is that each component has an associated set of allowed severity levels, such that only a message with a severity level that is “allowed” will actually be transmitted to the debugger when the DbgPrintEx call is made. This allows debug prints to be filtered on a (component, severity) basis, such that especially verbose debug prints can be turned off at runtime without requiring a rebuild or patching the binary on the fly (which might be a problem if the binary in question is the kernel itself and you’re running a 64-bit build). In order to edit the allowed severity of a component at runtime, you typically modify one of the nt!Kd_<component>_Mask global variables in the kernel with the debugger, setting the global corresponding to the desired component to the desired severity mask.

With respect to older drivers, the old DbgPrint call still works, but it is essentially repackaged into a DbgPrintEx call, with hardcoded (default) component and severity values. This means that you’ll still be able to get output from DbgPrint, but (obviously) you can’t take advantage of the extra host-side filtering. Host-side filtering is much preferable to .ofilter-style filtering (which occurs debugger-side), as debug prints that are transferred “over the wire” to the debugger incur a significant performance penalty – the system is essentially suspended while the transfer occurs, and if you have a large amount of debug print spew, this can quickly make the system unusably slow.

Windows Vista takes this whole mechanism one step further and turns off plain DbgPrint calls by default, by setting the default severity level for the DbgPrint-assigned component value such that DbgPrint calls are not transmitted to the debugger. This can be overridden at runtime by modifying Kd_DEFAULT_Mask, but it’s an extra step that must be taken (and one that may be confusing if you don’t know about the default behavior change in Vista, as your debug prints will seemingly just never work).

However, just because DbgPrintEx now provides a way to filter debug prints host-side, that doesn’t mean that you can just go and turn on all your debug prints for release builds by default. Among other things, it’s possible that someone else is using the same component id as your driver (remember, component ids are for classes of devices, such as “network driver”, or “video driver”). Furthermore, DbgPrintEx calls still do incur some overhead, even if they aren’t transmitted to the debugger on the other end (however as long as the debug print is masked off by the allowed severities mask for your component, the overhead is fairly minimal).

Still, the problem of limited component ids remains a significant enough one that you don’t want to turn on debug prints always, or if someone else with the same component id wants to debug their driver, they’ll have all of your debug print spew mixed in with their own.

Also, there is an option to turn on all debug prints, which can sometimes come in handy, and if every driver in the system has debug prints on by default, this often results in a lot of badness. This can be accomplished by specifying a global severity mask via the nt!Kd_WIN2000_Mask global, which is checked before any component specific masks. (If Kd_WIN2000_Mask allows the debug print, it is short-circuited to being allowed without considering component-specific masks. This makes things easier if you want to grab certain severities of debug print messages from many components at the same time, without having to go and manually poke around with severity levels on every component you’re intersted in.)

Unfortunately, this is already a problem on Vista RTM (even free builds) – there are a couple of in-box Microsoft drivers that are guilty of this sort of thing, making Kd_WIN2000_Mask less than useful on Vista. Specifically, cdrom.sys likes to print debug messages like this every second:

Will not retry; Sense/ASC/ASCQ of 02/3a/00

That’s hardly the worst of it, though. Try starting a manifested program on Vista with all debug print severities turned on in Kd_WIN2000_Mask and you’ll get pages of debug spew (no, I’m not kidding – try it with iexplore.exe and you’ll see what I mean). In that respect, shame on the SxS team for setting a bad example with polluting the world with debug prints that are useless to most of us (and to a lesser extent, cdrom.sys also gets a “black lump of coal”, so to speak). Maybe these two components will be fixed for Srv08 RTM or Vista SP1 RTM, if we’re lucky.

So, take this opportunity to check and make sure that none of your drivers ship with DbgPrints turned on by default – even if you do happen to use DbgPrintEx. Somebody who has to debug a problem on a computer with your driver is installed will be all the more happier as a result.

Previously, I introduced several ways to use the debugger to log API calls. Beyond what was described in that article, there are some other, more complicated examples that are worth reviewing. Additionally, there are certain limitations that should be considered when using the debugger instead of a dedicated API logging program.

Although logging breakpoints like I’ve previously described (i.e. displaying function input parameters and return values) are certainly handy, you’ve probably already come up with a couple of scenarios where breakpoints in the style like I’ve provided won’t give you what you need to track down a problem.

The most notable example of this is when you need to examine an out parameter that is filled by a function call, after the function call is made. This provides a problem, as it’s generally not reliable to access the function parameters on the stack after the function call has returned (in both stack and register based calling conventions in use on Windows, the called function is free to modify the parameter locations as it sees fit, and this is actually fairly common with optimizations enabled). As a result, what we really need is the ability to save some state across the function call, so that we can access some of the function’s arguments after the function returns.

Fortunately, this is doable within the debugger, albeit in a rather roundabout way. The key here is the usage of so-called user-defined pseudo-registers, which are conceptually extra platform-independent storage locations (accessed like regular registers in terms of the expression evaluator, hence the term pseudo-register). These pseudo-registers are essentially just variables in the conventional programming sense, although there are a limited number of them available (20 in the current release). As a result, there are some limitations on what can be accomplished using them, but for most circumstances, 20 is enough. If you find yourself needing to track more state than that, you should strongly consider writing a debugger extension in C instead of using the debugger script language.

(As an aside, at Driver DevCon a couple of years ago, I remember sitting in on a WinDbg-oriented session in which the presenter was at one point going over a large program written in the (then-relatively-new) expanded debugger scripting language, with additional support for conditionals and error handling. I still can’t but help think of debugger-script programs as combining the ugliest parts of Perl with cmd.exe-style batch scripts (although to be fair, the debugger expression evaluator is a bit more powerful than batch scripts, and it was also never originally intended to be used for more than simple expressions). To be honest, I would still strongly recommend against writing highly complex debugger-script programs where possible; they are something of a maintenance nightmare, among other things. For such circumstances, writing a debugger extension (or a program to drive the debugger entirely) is a better choice. I digress, however; back to the subject of call logging.)

The debugger’s user-defined pseudo-register facility provides an effective (if perhaps slightly awkward) means of storing state, and this can be used to save parameter values across a function call. For example, we might want to log all calls to ReadFile, such that we want a dump of the file data being read in. To accomplish this task, we’ll need to dump the contents of the output buffer (and use the bytes transferred count, another out parameter). This could be accomplished like so (in this case, for brevitiy, I am assuming that the program is using ReadFile in synchronous I/O mode):

0:000> bp kernel32!ReadFile "r @$t0 = poi(@esp+8) ; r @$t1 = poi(@esp+10) ; g @$ra ; .if (@eax != 0) { .printf \"Read %lu bytes: \\n\", dwo(@$t1) ; db @$t0 ldwo(@$t1) } .else { .echo Read failed! ; !gle } ; g "

The output of this command might be like so:

Read 22 bytes: 
0016ec3c  54 68 69 73 20 69 73 20-61 20 74 65 78 74 20 66
              This is a text f
0016ec4c  69 6c 65 2e 0d 0a
              ile...

(Awkward wrapping done by me to avoid breaking the blog layout.)

This command is essentially a logical extension of yesterday’s example, with the addition of some state that is shared across the call. Specifically, the @$t0 and @$t1 user-defined pseudo-registers are used to save the lpBuffer ([esp+08h]) and lpNumberOfBytesRead ([esp+10h]) arguments to the ReadFile call across the function’s execution. When execution is stopped at the return address, the contents of the file data that were just read are dumped by dereferencing the values referred to by @$t0 and @$t1.

Although this sort of state-saving across execution can be useful, there are downsides. Firstly, this sort of breakpoint is fundamentally incompatible with multiple threads (at least in as much as multiple threads hitting the breakpoint in question simultaneously). This is because the debugger provides no provision for “expression-local”, or “thread-local” state – multiple threads hitting the breakpoint at the same time can step on eachothers toes, so to speak. (This problem can also occur with any sort of breakpoint that involves resuming execution until an implicit breakpoint created by a “g <address>” command, although it is arguably more severe with “stateful” breakpoints.)

This limitation in the debugger can be worked around in a limited fashion by making a breakpoint thread-specific via a thread specifier in the g command, although this is typically hardly convenient to do. Many call logging programs will account for multithreading natively and will not require any special work to accomodate multithreaded function calls. (Note that this problem is often not as severe as it might sound – in many cases, even in multithreaded programs, there is typically only one function that calls a function you’re interested in, or the liklihood of a thread collision is sufficiently small that it works anyway the vast majority of the time. However, in some circumstances, these style of breakpoints just do not work well if the function in question is called frequently from many threads and requires inspection of data after the function returns.)

Another significant limitation of using the debugger to do call logging (as opposed to a dedicated program) is that the debugger is typically very slow compared to a dediated program doing logging. The reason here is that for every breakpoint event, essentially all threads in the program are frozen, various state information is copied from the program to the debugger, and then the breakpoint expression is evaluated debugger-side. Additionally, unlike with a dedicated program, the results of the logging breakpoint are displayed in real time, instead of (say) being stored in a binary log buffer somewhere for later format and display. This means that even more overhead is incurred as the debugger UI needs to be updated on every breakpoint. As a result, if you set a conditional breakpoint on a frequently hit function, you may notice the program slow down significantly, perhaps even to the point of being unusable. Dedicated logging programs can employ a variety of techniques to circumvent these limitations of the debugger, which are primarily artifacts of the fact that the debugger is primarily designed to be a debugger and not a high-speed API monitor.

This is even more noticible in the kernel debugger case, as transitions to the debugger in in KD mode are very slow, such that even several transitions per second is enough to make a system all but unusable in practical terms. As a result, one needs to be extra careful in picking locations to set conditional logging breakpoints at in the kernel debugger (perhaps placing them in the middle of a function, in a specific interesting code path, rather than at the start so that all calls will be caught).

Given these limitations, it is worth doing a bit of analysis on the problem to determine if the debugger or a dedicated logging program is the best choice. Both approaches have strengths and weaknesses, and although the debugger is extremely flexible (and often very convenient), it isn’t necessarily the best choice in every conceivable scenario. In other words, use the best tool for the job. However, there are some circumstances where the only option is to use the debugger, such as kernel-mode call logging, so I would recommend at least having some basic knowledge of how to accomplish logging tasks with the debugger, even if you would normally always use a dedicated logging program. (Although, in the case of kernel mode debugging, again, the slowness of debugger transitions makes it important to pick “low-traffic” locations to breakpoint on.)

Still, an important part of being effective at debugging and solving problems is knowing your options and when (and when not) to use them. Using the debugger to perform call logging should just be one of many such options in your “debugging toolkit”.

Last time, I put forth the notion that WinDbg (and the other DTW debuggers) are a fairly decent choice for API call logging. This article expands on just how to do this sort of logging via the debugger, by starting out with a simple logging breakpoint and expanding on it to be more intelligent.

As previously mentioned, it is really not all that difficult to use the debugger to perform call logging. The basic idea involved is to just set a “conditional” breakpoint (e.g. via the bp command) at the start of a function you’re interested in. From there, the breakpoint can have commands to display input parameters. However, you can also get a bit more clever in some scenarios (e.g. displaying return values, values in output parameters, and the like), although there are some limitations to this that may or may not be a problem based on the characteristics of the program that you’re debugging.

To give a simple example of what I mean, there’s the classic “show all files opened via Win32 CreateFile as they are opened”. In order to do this, the way to go is to set a breakpoint on kernel32!CreateFileW. (Remember that most of the “A” Win32 APIs thunk to the “W” APIs, so you can often set a breakpoint on just the “W” version to get both. Of course, this is not always true (and some bizzare APIs like WinInet actually thunk “W” to “A”), but as a general rule of thumb, it’s more often the case than not.) The kernel32 breakpoint needs to be imbued with the knowledge of how to display the first argument based on the calling convention of the routine in question. Since CreateFile is __stdcall, that would be [esp+4] (for x86), and rcx (for x64).

At it’s most basic, the breakpoint command might look like so:

0:001> bp kernel32!CreateFileW "du poi(@esp+4) ; gc"

(Note that the gc command is similar to g, except that it is designed especially for use in conditional breakpoints. If you trace into a breakpoint that controls execution with gc, it will resume executing the same way the user was controlling the program instead of unconditionally resuming normally. The difference between a breakpoint using g and one using gc is that if you trace into a gc breakpoint, you’ll trace to the next instruction, whereas if you trace into a g breakpoint, control will resume full speed and you’ll lose your place.)

The debugger output for this breakpoint (when hit) lists the names passed to kernel32!CreateFileW, like so (if I were setting this breakpoint in cmd.exe, and then did “type C:\readme.txt”, this might come up in the debugger output):

00657ff0  "C:\\readme.txt"

(Note that as the breakpoint displays the string passed to the function, it will be a relative path if the program uses the relative path.)

Of course, we can do slightly more complicated things as well. For instance, it might be a good idea to display the returned handle and the last error code. This could be done by having the breakpoint go to the return point of the function after it dumps the first parameter, and then display the additional information. To do this, we might use the following breakpoint:

0:001> bp kernel32!CreateFileW "du poi(@esp+4) ; g @$ra ; !handle @eax f ; !gle ; g"

The gist of this breakpoint is to display the returned handle (and last error status) after the function returns. This is accomplished by directing the debugger to resume execution until the return address is hit, and then operate on the return value (!handle @eax f) and last error status (!gle). (The @$ra symbol is a pseudo-register that refers to the current function’s return address in a platform-independent fashion. Essentially, the g @$ra command runs the program until the return address is hit.)

The output from this breakpoint might be like so:

0016f0f0  "coffbase.txt"
Handle 60
  Type         	File
  Attributes   	0
  GrantedAccess	0x120089:
         ReadControl,Synch
         Read/List,ReadEA,ReadAttr
  HandleCount  	2
  PointerCount 	3
  No Object Specific Information available
LastErrorValue: (Win32) 0 (0) - The operation
  completed successfully.
LastStatusValue: (NTSTATUS) 0 - STATUS_WAIT_0

However, if we fail to open the file, the results are less than ideal:

00657ff0  "c:\\readme.txt"
Handle 4
  Type         	Directory
[...] enumeration of all handles follows [...]
21 Handles
Type           	Count
Event          	3
File           	4
Directory      	3
Mutant         	1
WindowStation  	1
Semaphore      	2
Key            	6
Thread         	1
LastErrorValue: (Win32) 0x2 (2) - The system
  cannot find the file specified.
LastStatusValue: (NTSTATUS) 0xc0000034 -
  Object Name not found.

What went wrong? Well, the !handle command expanded into essentially “!handle -1 f“, since CreateFile returned INVALID_HANDLE_VALUE (-1). This mode of the !handle extension enumerates all handles in the process, which isn’t what we want. However, with a bit of cleverness, we can improve upon this. A second take at the breakpoint might look like so:

0:001> bp kernel32!CreateFileW "du poi(@esp+4) ; g @$ra ; .if (@eax != -1) { .printf \"Opened handle %p\\n\", @eax ; !handle @eax f } .else { .echo Failed to open file, error: ; !gle } ; g"

Although that command might appear a bit intimidating at first, it’s actually fairly straightfoward. Like with the previous version of this breakpoint, the essence of what it accomplishes is to display the filename passed to kernel32!CreateFileW, and then resumes execution until CreateFile returns. Then, depending on whether the function returned INVALID_HANDLE_VALUE (-1), either the handle is displayed or the last error status is displayed. The output from the improved breakpoint might be something like this (with an example of successfully opening a file and then failing to open a file):

Success:

0016f0f0  "coffbase.txt"
Opened handle 00000060
Handle 60
  Type         	File
  Attributes   	0
  GrantedAccess	0x120089:
         ReadControl,Synch
         Read/List,ReadEA,ReadAttr
  HandleCount  	2
  PointerCount 	3
  No Object Specific Information available

Failure:

00657ff0  "C:\\readme.txt"
Failed to open file, error:
LastErrorValue: (Win32) 0x2 (2) - The system
  cannot find the file specified.
LastStatusValue: (NTSTATUS) 0xc0000034 -
  Object Name not found.

Much better. A bit of intelligence in the breakpoint allowed us to skip the undesirable behavior of dumping the entire process handle table in the failure case, and we could even skip displaying the last error code in the success case.

As one can probably imagine, there’s a whole other range of possibilities here once one considers the flexbility offered by conditional breakpoints. However, there are some downsides with this approach that must be considered as well. More on a couple of other more advanced condition breakpoints for logging purposes in a future posting (as well as a careful look at some of the limitations and disadvantages of using the debugger instead of a specialized program, and some “gotchas” you might run into with this sort of approach).

One common task that you may be faced with while debugging a problem is to log information about calls to a function or function(s). While if you want to know about a function in your program that you have source code to, you could often just add some sort of debug print and rebuild the program, sometimes this isn’t practical. For example, you might not always be able to reproduce a problem and so it might not viable to have to restart with a debug-ified build because you might blow away your repro. Or, more importantly, you might need to log calls to functions that you don’t have source code to (or aren’t building as part of your program, or otherwise don’t want to modify).

For example, you might want to log calls to various Windows APIs in order to gain information about a problem that you are troubleshooting. Now, depending on what you’re doing, you might be able to do this by adding debug prints before and after every single call to the particular API. However, this is often less than convenient, and if you aren’t the immediate caller of the function you want to log, then you’re not going to be able to take that route anyway.

There are a number of API spy/API logging packages out there (and the Debugging Tools for Windows distribution even ships with one, called Logger, though it tends to be fairly fragile – personally, I’ve had it crash out on me more often than I’ve had it actually work). Although you might be able to use one of those, a big limitation of “shrink-wrapped” logging tools is that they won’t know how to properly log calls to custom functions, or functions that are otherwise not known to the logging tool. The better logging tools out there are user-extensible to a certain extent, in that they typically provide some sort of scripting- or programmming- language that allows the user (i.e. you) to describe function parameters and calling conventions, so that they can be logged.

However, it can often be difficult (or even impossible) to describe many types of functions to these tools – such as functions that contain pointers to structures that contain pointers to other structures, or other such non-trivial constructs. As a result, for many circumstances, I tend to recommend to not use so-called “shrink-wrapped” API logging tools in situations where I want to log calls to functions.

In the event that it’s not a feasible solution to implement debug prints in source code, though, it would appear on the surface that this leaves one without a usable solution for logging calls. Not so, in fact – it turns out that with some careful use of so-called “conditional breakpoints”, you can often use the debugger (e.g. WinDbg/ntsd/cdb/kd, which is what I shall be referring to for the rest of this article) to provide this sort of call logging. Using the debugger has many advantages; for instance, you can do this sort of API logging “on the fly”, and in situations where you can attach the debugger after the process has started, you don’t even need to start the program specially in order to log it. Even better, however, is that the debugger has extensive support for displaying data in meaningful forms to the user.

If you think about it, displaying data to the user is one of the prinicpal functions of the debugger, in fact. It’s also one of the major reasons why the debugger is highly extensible via extensions, such that complicated data structures can be displayed and interpreted in a meaningful fashion. By using the debugger to perform your API logging, you can take advantage of the rich functionality for displaying data that is already baked into the debugger (and its extensions, and even any custom extensions of your own that you have written) to double as a call logging facility.

Even better, because the debugger can read and display many data types in a meaningful fashion based off of symbol files (if you have private symbols, such as for programs you compile or provide), for data types that don’t have specific debugger extensions for displaying them (like !handle, !error (for error codes), !devobj, and soforth), you can often utilize the debugger’s ability to format data based off of type information in symbols. This is typically done via the dt command, and often provides a workable display for most custom data types without having to do any sort of complicated “training” like you might have to do with a logging program. (Some data structures, such as trees and lists may need some more intelligence than what is provided in dt for displaying all parts of the data structure. This is typically true for “container” data types, although even for those types, you can still often use dt to display actual members within the container in a meaningful fashion.) Utilizing the information contained within symbols files (via the debugger) for API logging also frees you from having to ensure that your logging program’s definitions for all of your structures and other types are in synch with the program you are debugging, as the debugger automagically receives the correct definitions based on symbols (and if you are using a symbol server that includes indexed versions of your own internal symbols, the debugger will even be able to find the symbols on its own).

Another plus to this approach is that, provided you are reasonably familiar with the debugger, you probably won’t have to learn a new description language like you might if you were using an API logging program. This is because you’re probably already familiar with many of the commands the debugger makes available for displaying data, from every-day debugger usage. (Even if you aren’t all that familiar with the debugger, there is extensive documentation that ships with the debugger by default which describes how to format and display data via various debugger commands. Additionally, there are many examples describing how to use most of the important or useful debugger commands out there on the Internet.)

Okay, enough about why you might want to consider using the debugger to perform call logging. Next time, a quick look and walkthrough describing how you can do this (it’s really quite simple, as alluded to previously), along with some caveats and gotchas that you might want to watch out for along the way.

If you’ve ever worked on any sort of crash reporting mechanism, one of the constraints that you are probably familiar with is the size of the dump file created by your reporting mechanism. Obviously, as developers, we’d really love to write a full dump including the entire memory image of the process, full data about all threads and handles (and the like), but this is often less than possible in the real world (particularly if you are dealing with some sort of automated crash submission system, which needs to be as un-intrusive as possible, including not requiring the transfer of 50MB .dmp files).

One way you can improve the quality of the dumps your program creates without making the resulting .dmp unacceptably large is to just use a bit of intelligence as to what parts of memory you’re interested in. After all, while certainly potentially useful, chances are you probably won’t really need the entire address space of the process at the time of a crash to track down the issue. Often enough, simply a stack trace (+ listing of threads) is enough, which is more along the lines of what you see when you make a fairly minimalistic minidump.

However, there are lots of times where that little piece of state information that might explain how your program got into its crashed state isn’t on the stack, leaving you stuck without some additional information. An approach that can sometimes help is to include specific, “high-value” regions of memory in a memory dump. For example, something that can often be helpful (especially in the days of custom calling conventions that try to avoid using the stack where-ever possible) is to include a small portion of memory around each register in-memory.

The idea here is that when you’re going to write a dump, check each register in the faulting context to see if it points to a valid location in the address space of the crashed process. If so, you can include a bit of memory (say, +/- 128 bytes [or some other small amount] from the register’s value) in the dump. On x86, you can actually optimize this a bit further and typically leave out eip/esp/ebp (and any register that points into an executable section of an image section, on the assumption that you’ll probably be able to grab any relevant images from the symbol server (you are using a symbol repository with your own binaries included, aren’t you?) and don’t need to waste space with that code in the dump).

One class of problem that this can be rather helpful in debugging is a crash where you have some sort of structure or class that is getting used in some partially valid state and you need the contents of the struct/class to figure out just what happened. In many cases, you can probably infer the state of your mystery class/struct from what other threads in a program were doing, but sometimes this isn’t possible. In those cases, having access to the class/struct that was being ‘operated upon’ is a great help, and often times you’ll find code where there is a `this’ pointer to an address on the heap that is tantalyzingly present in the current register context. If you were using a typical minimalistic dump, then you would probably not have access to heap memory (due to size constraints) and might find yourself out of luck. If you included a bit of memory around each register when the crash occured, however, that just might get you the extra data points needed to figure out the problem. (Determining which registers “look” like a pointer is something easily accomplished with several calls to VirtualQueryEx on the target, taking each crash-context register value as an address in the target process and checking to see if it refers to a committed region.)

Another good use case for this technique is to include information about your program state in the form of including the contents of various key heap- (or global- ) based objects that wouldn’t normally be included in the dump. In that case, you probably need to set up some mechanism to convey “interesting” addresses to the crash reporting mechanism before a crash occurs, so that it can simply include them in the dump without having to worry about trying to grovel around in the target’s memory trying to pick out interesting things after-the-fact (something that is generally not practical in an automated fashion, especially without symbols). For example, if you’ve got some kind of server application, you could include pointers to particularly useful per-session-state data (or portions thereof, size constraints considered). The need for this can be reduced somewhat by including useful verbose logging data, but you might not always want to have verbose logging on all the time (for various reasons), which might result in an initial repro of a problem being less than useful for uncovering a root cause.

Assuming that you are following the recommended approach of not writing dumps in-process, the easiest way to handle this sort of communication between the program and the (hopefully isolated in a different process) crash reporting mechanism is to use something like a file mapping that contains a list (or fixed-size array) of pointers and sizes to record in the dump. This can make adding or removing “interesting” pointers from the list to be included as simple as adding or removing an entry in a flat array.

As far as including additional memory regions in a minidump goes, this is accomplished by including a MiniDumpCallback function in your call to MiniDumpWriteDump (via the CallbackParam parameter). The minidump callback is essentially a way to perform advanced customizations on how your dump is processed, beyond a set of general behaviors supplied by the DumpType parameter. Specifically, the minidump callback lets you do things like include/exclude all sorts of things from the dump – threads, handle data, PEB/TEB data, memory locations, and more – in a programmatic fashion. The way it works is that as MiniDumpWriteDump is writing the dump, it will call the callback function you supply a number of times to query you for any data you want to add or subtract from the dump. There’s a huge amount of customization you can do with the minidump callback; too much for just this post, so I’ll simply describe how to use it to include specific memory regions.

As far as including memory regions go, you need to wait for the MemoryCallback event being passed to your minidump callback. The way the MemoryCallback event works is that you are called back repeatedly, until your callback returns FALSE. Each time you are called back (and return TRUE), you are expected to have updated the CallbackOutput->MemoryBase and CallbackOutput->MemorySize output parameter fields with the base address and length of a region that is to be included in the dump. When your callback finally returns FALSE, MiniDumpWriteDump assumes that you’re done specifying additional memory regions to include and continues on to the rest of the steps involved in writing the dump.

So, to provide a quick example, assuming you had a DumpWriter class containing an array of address / length pairs, you might use a minidump callback that looks something like this to include those addresses in the dump:

BOOL CALLBACK DumpWriter::MiniDumpCallback(
 PVOID CallbackParam,
 const PMINIDUMP_CALLBACK_INPUT CallbackInput,
 PMINIDUMP_CALLBACK_OUTPUT CallbackOutput
 )
{
 DumpWriter *Writer;
 BOOL        Status;

 Status = FALSE;

 Writer = reinterpret_cast<DumpWriter*>(CallbackParam);

 switch (CallbackInput->CallbackType)
 {

/*
 ... handle other events ...
 */

 case MemoryCallback:
  //
  // If we have some memory regions left to include then
  // store the next. Otherwise, indicate that we're finished.
  //

  if (Writer->Index == DumpWriter->Count)
   Status = FALSE;
  else
  {
   CallbackOutput->MemoryBase =
     Writer->Addresses[ Writer->Index ].Base;
   CallbackOutput->MemorySize =
     Writer->Addresses[ Writer->Index ].Length;

   Writer->Index += 1;
   Status = TRUE;
  }
  break;

/*
 ... handle other events ...
 */
 }

 return Status;
}

In a future posting, I’ll likely revisit some of the other neat things that you can do with the minidump callback function (as well as other things you can do to make your minidumps more useful to work with). In the mean time, Oleg Starodumov also has some great documentation (beyond that in MSDN) about just what all the other minidump callback events do, so if you’re finding MSDN a little bit lacking in that department, I’d encourage you to check his article out.