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).
Was the choice of .if/.else over the “j” command purely a matter of style or is there a technical reason? The debugger docs only mention the “j” command when discussing conditional breakpoints.
It does mention that the “j” command cannot be followed by more commands but it looks like that wouldn’t matter for this example. I tried the following and got the same results:
bp kernel32!CreateFileW “du poi(@esp+4) ; g @$ra ; j (@eax != -1) ‘.printf \”Opened handle %p\n\”, @eax ; !handle @eax f; gc’ ; ‘.echo Failed to open file, error: ; !gle; gc'”
I do think the .if/.else verison is easier to read. Plus, I had to put the ‘gc” command in both branches since it couldn’t follow the “j” command as the docs say.
Anyway, just curious about your choice.
Mostly because it’s easier to read and it’s slightly more intuitive than “J”. As far as the documentation goes, “.if” and friends are relatively new (well, not so much anymore, but compared to “J” it’s new) – and as you probably have found out by now, the WinDbg documentation has been unfortunately rotting for a long time now. It seems like nobody knows about half of the new features released with any new DTW drop just because there is zero documentation even mentioning them.
Anyways, in most circumstances you could just use “J” instead of “.if” with some minor modifications (e.g. duplicating conditions following both branches — and indeed until very recently I’ve just done that by habit). I decided it’d probably be a bit more understandable of an example with “.if”, and to be honest, there really isn’t much reason to use “J” over .if” anymore (unless you’re “old fashioned” and are used to using it from the “old days”, back before there was such a thing as new-fangled “.if”).
BTW, in my 6.7.5.0 CHM, “.if” is mentioned (if in a cursory way) in the “Setting a Conditional Breakpoint” (in the index: “conditional breakpoints”).
[…] Nynaeve Adventures in Windows debugging and reverse engineering. « Debugger tricks: API call logging, the quick’n’dirty way (part 2) […]
[…] Debugger tricks: API call logging, the quick’n’dirty way (part 2) http://www.nynaeve.net/?p=144 […]