• Ntdebugging Blog

    Getting Ready for Windows Debugging

    • 8 Comments

     

    Welcome to the Microsoft NTDebugging blog!  I’m Matthew Justice, an Escalation Engineer on Microsoft’s Platforms Critical Problem Resolution (CPR) team.  Our team will be blogging about troubleshooting Windows problems at a low level, often by using the Debugging Tools for Windows.  For more information about us and this blog, check out the about page.

     

    To get things started I want to provide you with a list of tools that we’ll be referencing in our upcoming blog posts, as well as links to some technical documents to help you get things configured.

     

    The big list of tools:

     

    The following tools are part of the “Debugging Tools for Windows” – you’ll definitely need these

    http://www.microsoft.com/whdc/devtools/debugging/

    ·         windbg

    ·         cdb

    ·         ntsd

    ·         tlist

    ·         gflags

    ·         adplus

    ·         UMDH

    ·         symcheck

     

    Sysinternals provides some great tools that we’ll be discussing

    http://www.sysinternals.com

    ·         Process Explorer

    ·         Process Monitor

    ·         Regmon

    ·         Filemon

    ·         DbgView

    ·         Handle.exe

    ·         Tcpview

    ·         LiveKD

    ·         AutoRuns

    ·         WinObj

     

    There are many tools contained in “MPS Reports” (MPSRPT_SETUPPerf.EXE), but I’m listing it here specifically for Checksym

    http://www.microsoft.com/downloads/details.aspx?FamilyID=CEBF3C7C-7CA5-408F-88B7-F9C79B7306C0&displaylang=en

    ·         Checksym

     

    “Windows Server 2003 Resource Kit Tools” is another great set of tools.  In particular Kernrate is a part of that package

    http://www.microsoft.com/downloads/details.aspx?displaylang=en&familyid=9D467A69-57FF-4AE7-96EE-B18C4790CFFD

    ·         Kernrate

     

    Windows XP SP2 Support Tools

    http://www.microsoft.com/downloads/details.aspx?FamilyID=49AE8576-9BB9-4126-9761-BA8011FABF38&displaylang=en

    ·         netcap

    ·         poolmon

    ·         memsnap

    ·         tracefmt  (64-bit versions available in the DDK)

    ·         tracelog

    ·         tracepdb

    ·         depends

    ·         pstat

     

    “Visual Studio “ – in addition to the compilers and IDE, the following tools come in handy:

    ·         SPY++

    ·         dumpbin

     

    Perfwiz (Performance Monitor Wizard)

    http://www.microsoft.com/downloads/details.aspx?FamilyID=31fccd98-c3a1-4644-9622-faa046d69214&DisplayLang=en

     

    DebugDiag

    http://www.iis.net/handlers/895/ItemPermaLink.ashx

     

    Userdump (User Mode Process Dumper)

    http://www.microsoft.com/downloads/details.aspx?FamilyID=E089CA41-6A87-40C8-BF69-28AC08570B7E&displaylang=en

     

    Dheapmon (Desktop Heap Monitor)

    http://www.microsoft.com/downloads/details.aspx?familyid=5CFC9B74-97AA-4510-B4B9-B2DC98C8ED8B&displaylang=en

     

    Netmon 3.0

    §  Go to http://connect.microsoft.com/

    §  Sign in with your passport account

    §  Choose "Available Connections" on the left

    §  Choose "Apply for Network Monitor 3.0” (once you've finished with the application, the selection appears in your "My Participation" page)

    §  Go to the Downloads page (On the left side), and select the appropriate build 32 or 64 bit build.

     

     

     

    Some articles you may find useful:

     

    Debugging Tools and Symbols: Getting Started

    http://www.microsoft.com/whdc/devtools/debugging/debugstart.mspx

     

    Boot Parameters to Enable Debugging

    http://msdn2.microsoft.com/en-us/library/ms791527.aspx

     

    How to Generate a Memory Dump File When a Server Stops Responding (Hangs)

    http://support.microsoft.com/kb/303021/

     

    After installing the “Debugging Tools for Windows”, you’ll find two documents at the root of the install folder that are helpful:

     

    ·         kernel_debugging_tutorial.doc - A guide to help you get started using the kernel debugger.

     

    ·         debugger.chm - The help file for the debuggers.  It details the commands you can use in the debugger.  Think of this as a reference manual, rather than a tutorial.





  • Ntdebugging Blog

    Debug Fundamentals Exercise 4: The GAMEOVER exercise

    • 8 Comments

     

    We are back with another addition to the debugging fundamentals series here in 2009! Regardless of your debugging experience we hope you enjoy this one. Don’t worry too much if you can’t answer them all but give them your best shot.

     

    The problem:

     

    While debugging an application, a developer observes a crash and is puzzled. The developer saves a memory dump of the process using the command “.dump /ma dbgex4.dmp” and sends it to you for debug assistance.

     

    0:000> r

    eax=53454750 ebx=00000000 ecx=00000100 edx=000001b0 esi=001bfe20 edi=00ac36bc

    eip=47414d45 esp=001bfe00 ebp=4f564552 iopl=0         nv up ei pl zr na pe nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010246

    47414d45 ??              ???

     

    The attached zip, dbgex4.zip, includes three files. The program itself, the program’s symbols file and the saved memory dump file. (NOTE: You do not need to execute the program for the exercise however you may want to in order to solve the bonus’. You will need to rename the file dbgex4.ex_ to dbgex4.exe in order to run it).

     

    Using the accompanying files, answer the following questions:

     

    Part One – Debugging

     

    1.       What caused the access violation?

    2.       Examine the registers at the time of the crash.  Is there anything interesting about the contents?

    3.       How did the registers get into this state?

    4.       Find the offending data structure which caused this state to occur. What are its contents?

    5.       Are there security concerns with this access violation? Why?

    6.        Why is this class of crashes not seen in the wild much anymore?

    Part Two – Reverse Engineering

     

    Examine the functions main(), snap(), crack(), pop(), and boom().

    1.       Describe with a sentence or two what each one is doing.  (There is no need to comment on every assembly instruction or re-write the code in C here unless you really feel you need to.)

    Bonus:

    1.       If this access violation occurred while the program was running without a debugger present, would there be anything different about the crashing register state or the data structure which caused it? If so what is it and why? (HINT: If you would like to observe the crashing state like this, you can register windbg.exe to be the Just-In-Time debugger using the –I switch like so “windbg.exe -I”. When you run the dbgex4.exe program, it will crash and windbg.exe will launch automatically and attach to it.)

    2.       The functions from “Part Two – Reverse Engineering” perform operations on a set of data. During this manipulation some data is lost. Find this data and decode its “secret” message.

     

    Share this post :
  • Ntdebugging Blog

    Basics of Debugging Windows

    • 8 Comments

    Hello, this is East again. This blog post is about a topic that we always skip over when discussing debugging; what and where are the tools for debugging. I will touch on the different types of debuggers, loading symbols and the basics of getting started with loading up a dump under your preferred debugger.

    Microsoft currently offers 4 types of debugging tools. With these tools you can remote debug another machine over firewire or serial cable (USB also but may not work consistently), as well as debug usermode processes and dump files.

    Command line debuggers:

    1 ) kd.exe: kernel debugger – Used to review Crash dumps created by a blue screen crash event or a stop error. (kd –z <location of dump> –y <location of symbols>)

    2 ) cdb.exe: User mode debugger for reviewing applications,  processes, and process dumps  (cdb  –z <location of dump> –y <location of symbols> )

    3 ) ntsd.exe: CDB and NTSD are virtually identical, except that NTSD spawns a new text window when it is started, whereas CDB inherits the Command Prompt window from which it was invoked.  When I refer to "CDB", it applies to both CDB and NTSD.

    Graphical User Interface Debugger:

    4) Windbg.exe is a GUI based debugger. It can debug the same things as KD & CDB using the same commands. Windbg gives you the ability to have multiple windows open simultaneously  to review source code or other selectable items under the view menu.

    I like using windbg for all of my user and kernel debugging, while  others I work with prefer kd for kernel debugging and cdb for user mode debugging.

     

    There are 32bit and 64bit debuggers available.

    NOTE: Some people use Visual Studio as well, but this blog post will not cover using Visual Studio as a debugger.

     

    You can review applications that already have started on your machine using CDB or Windbg. You can have the problematic application launch under the debugger as well:

    Cdb or Windbg

    -p <pid> specifies the decimal process ID to attach to ( use tlist or the task manger to obtain the PID)

    -psn <name> specifies the process to attach to by service name

    <application to launch> -y <symbol path>

    NOTE: windbg allows you to use menu options as well: select “Attach to a Process” on the File menu to debug a user-mode application that is currently running.

     

    What are dumps?

    Memory dumps are a record of what was in memory and the registers at the time of a crash. There are 3 types of memory dumps:

    NOTE: The type of dump that will be written upon bugcheck can be configured by right clicking my computer ->properties ->Advanced tab ->Settings, in the Write debugging section you will use the first drop down box to select what type of memory dump you want. (See KB307973)

    ·         Mini dump – is a subset of memory that is in use by the application creating the dump.

    A mini memory Dump file is written to %SystemRoot%\Minidump\Memory.dmp by default and is usually less than a 1mb in size.

    ·         Kernel only – This is used to review the machine’s kernel memory at the time of the crash.

    ·         Full/Complete – This is the largest kernel mode dump file. It contains all information from kernel and user mode address spaces that was in physical memory at the time of the dump (about the same size as the physical memory on the box).

    Kernel and Complete Memory Dumps are written to %SystemRoot%\Memory.dmp by default.

    Note: You can configure the server to crash using certain keystrokes . This would be useful when troubleshooting a hung server or a timing issue, KB244139 explains how to configure your server for a manual crash.

    You can also create dump files from an application or process, these are known as User-mode dumps.  Additional information can be found on these types dump in the Debugging Tools for Windows help file.

     

    How do I read a dump file?

    In order to make fast progress with a memory dump file, it is best to load symbol files. Symbol files contains data that the debugger uses to interpret the application or driver code. They may contain:

    -          Global variable names

    -          Function names

    Private Symbols would contain the above information and:

    -          Local variable names

    -          Source-line numbers

    -          Type information for variables, structures, etc.

     Microsoft currently has two ways you can access symbols for the Operating System:

    Service pack download site – You will need to create:

    -          Separate directories for Windows 2000 RTM, Windows 2000 SP1, Windows 2000 SP2, Windows XP RTM, etc.

    -          Separate directories for all of the above for free vs. checked build

    -          Separate directories for hotfix symbols

     

    Public symbol server – uses a symbol store, which is a collection of symbol files. The symbol server uses the time stamp & file size to match up symbols to the active binary.After getting your symbol files together, you will need a way to tell the debugger where they are located and set up some other options.

    To set the symbol path do one of the following:

    -          _NT_SYMBOL_PATH environment variable

    -          -y command line option

    -          .sympath (Set Symbol Path) debugger command

    -          WinDbg: File | Symbol File Path dialog, or CTRL+S

    To set the executable Image Path (needed for minidumps only), do one of the foolowing:

    -          -i command line option

    -          .exepath debugger command

    -          WinDbg: File | Image File Path dialog, or CTRL+i

    -          Source Path

    -          .srcpath WinDbg: File | Source File Path dialog, or CTRL+P

    If symbol errors appear when you begin, you can try the below commands to help narrow down some problems;

    !sym noisy — gives verbose symbol information

    AND

    .reload —  to reload all symbols

     

    Also using the srv* in your symbol path tells the debugger to load and save symbols being used out to a specific directory:

    srv*DownstreamStore*<symbol locations>

     

    NOTE: You must always use .reload after you change the symbol path or fix a symbol error — the debugger doesn’t automatically reload your symbols!

     

    Now that we are done with the overview, let’s configure our machine as a host computer to open memory a dump.  I will be using Microsoft Public Symbol servers and I want to store current symbols locally to my host machine.

    Using windbg I will set my current workspace symbols to: srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols

    Click the menu option File ->Symbol File Path or Ctrl + S. This will bring up an empty box that will allow you to enter or browse to your symbol path.

    If using kd you want to set an environment variable (_NT_SYMBOL_PATH) under “my computer properties -> advanced tab” to always start with your symbols set to:  “srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols” or use this same path in your command line:

    Kd –z <path to dump.file> -y srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols

     

    NOTE: Windbg will append any workspace symbol path with the one set by the _NT_SYMBOL_PATH environment variable during loading of a memory dump.

    Ok, now we know what debugger we want to use and we know our symbol locations. Let’s open our first kernel memory dump , located on <drive letter> <path to dump file>

    Using windbg, I will load a dump file using menu options File ->Open crash Dump (ctrl + D) or drag the the dump file into the debugger; you can even  start windbg at the command prompt.  My command would look like this:

    Windbg  –z C:\training\case 7f\MEMORY051308.22.DMP

    I did not use the –y for symbol path, as it is set already in my default workspace or in my environment variable.

    When the debugger first loads a dump file it displays several lines of information before giving you a prompt to get started with your commands (by default):

    Microsoft (R) Windows Debugger Version 6.9.0003.113 X86  ß debugger version

    Copyright (c) Microsoft Corporation. All rights reserved. ß Copyright of the debugger creator

    Loading Dump File [C:\training\case 7f\MEMORY051308.22.DMP] ß location of the dump file loading

    Kernel Summary Dump File: Only kernel address space is available ß type of memory dump (mini, kernel, or full)

    Symbol search path is: srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols ß Symbol path for this debug session

    Executable search path is:  ß points to the directory the executable files are located. For most situations this is not needed. For other situations please check the debugger help file.

     

    The next 4 lines talk about The OS version, service packs and how many processors are on the box

    1 -Windows Server 2003 Kernel Version 3790 (Service Pack 2) MP (8 procs) Free x86 compatible

    2 - Product: Server, suite: Enterprise TerminalServer SingleUserTS

    3 - Built by: 3790.srv03_sp2_gdr.070304-2240

    4 - Kernel base = 0x80800000 PsLoadedModuleList = 0x808a6ea8

     

    Next we would see when the machine crashed and how long it was up prior to this crash:

    Debug session time: Wed May 14 01:27:36.768 2008 (GMT-4)

    System Uptime: 0 days 16:32:51.921

     

    After completing the above process, the debugger starts loading the dump file and parsing through the loaded symbols. Here you may notice some warnings for some user space processes which are not included in the kernel dump. This is ok.

    WARNING: Process directory table base BFF0A080 doesn't match CR3 007AF000

    WARNING: Process directory table base BFF0A080 doesn't match CR3 007AF000

    Loading Kernel Symbols

    ...........................................................................................................................................

    Loading User Symbols

    PEB is paged out (Peb.Ldr = 7ffdf00c).  Type ".hh dbgerr001" for details

    Loading unloaded module list

    *******************************************************************************

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

    *******************************************************************************

     

    1- Use !analyze -v to get detailed debugging information.

    2 - BugCheck 7F, {8, f773ffe0, 0, 0}

    3 - *** ERROR: Module load completed but symbols could not be loaded for ql2300.sy

    The three things I want to point out from above are:

    1 - !analyze –v: This is the debugger command used to help analyze a dump file by reviewing information passed to KeBugCheck including specific parameters of that crash. It will analyze this information and provide a definition of the bugcheck, a stack showing all current function calls, and, when possible, the name of an offending driver or process that the debugger thinks is at fault.  Please review the debugger help file for additional information in this area.

    2 – The type of bugcheck that occurred on the machine.

    3 – An error telling you about symbols missing or not available to help diagnose a particular driver or application. This can lead to a misdiagnostis if you’re not careful.

    Once loading is completed you should be at a kd> prompt. This prompt shows you the current processor you are using (if the machine has more than one).

    For this dump we are at processor 3 on an 8 proc machine:

    3: kd>

     

    To view the current crash stack location you can use the "K" command. There are multiple forms of this command, each one dumping the basic plus additional information. As functions are executed and call other functions, a call stack is created in stack memory. Here are two common commands to view the stack:

     

    3: kd> k

    ChildEBP RetAddr

    00000000 baebf0ce nt!KiTrap08+0x75

    b3a4bffc baebf737 storport!RaCallMiniportInterrupt+0x2

    b3a4c008 8088d889 storport!RaidpAdapterInterruptRoutine+0x1d

    b3a4c008 80a59d8e nt!KiInterruptDispatch+0x49

    b3a4c09c 80a5c2fc hal!HalpGenerateInterrupt+0x1d2

    b3a4c0c0 80a5c44d hal!HalpLowerIrqlHardwareInterrupts+0x108

    b3a4c0d0 808256ed hal!KfLowerIrql+0x59

    <snippet>

     

    3: kd> kb

    ChildEBP RetAddr  Args to Child

    00000000 baebf0ce 00000000 00000000 00000000 nt!KiTrap08+0x75

    b3a4bffc baebf737 97bedb88 b3a4c02c 8088d889 storport!RaCallMiniportInterrupt+0x2

    b3a4c008 8088d889 977b9e18 97bedad0 03010006 storport!RaidpAdapterInterruptRoutine+0x1d

    b3a4c008 80a59d8e 977b9e18 97bedad0 03010006 nt!KiInterruptDispatch+0x49

    b3a4c09c 80a5c2fc 97797004 97bedad0 00000102 hal!HalpGenerateInterrupt+0x1d2

    b3a4c0c0 80a5c44d 00000101 977b9e02 b3a4c0d8 hal!HalpLowerIrqlHardwareInterrupts+0x108

    b3a4c0d0 808256ed b3a4c0e8 baebf1c6 977b9bb0 hal!KfLowerIrql+0x59

    <snippet>

     

    Either one can be used depending on how much information you want to see and can use.

    This completes the Basic of Debugging Windows, Part I. I will create a Part II using specific questions gathered from our readers.

     

    Miscellaneous information:

    To go further with this topic I would suggest starting with the debugger help file included with the Microsoft Debugging Tools. 

    ADPlus – An automated way to use the cdb.exe to capture/create a usermode dump when a process hangs or crashes. (more info - http://msdn.microsoft.com/en-us/library/cc265629.aspx or kb286350)

    Public Symbols for Microsoft Operating Systems:

    Microsoft Public Symbol server : srv * DownstreamStore * http://msdl.microsoft.com/download/symbols

    example: srv*c:\mysyms*http://msdl.microsoft.com/download/symbols

     Microsoft Symbol packages http://www.microsoft.com/whdc/devtools/debugging/symbolpkg.mspx#d

    Use !Analyze-v to gather additional information about the bugcheck and a bucket-id for your dump file. The bucket-id can be submitted to Microsoft for review for similar crashes and resolutions. Try using the Microsoft Online Crash Analysis to submit your crash dump bucket-id for possible follow up from Microsoft or for Microsoft to look for trends: http://oca.microsoft.com/en/Welcome.aspx

    For concepts, tools and information about the system architecture:

    http://msdn.microsoft.com/en-us/default.aspx

    Windows Internal 4th edition (by Mark E. Russinovich & David A. Solomon) the whole book or Chapter 14 - Crash Dump Analysis

    Advanced Windows Debugging (by Mario Hewardt & Daniel Pravat )

    http://technet.microsoft.com/en-us/default.aspx

  • Ntdebugging Blog

    Debugging a Crash, Found a Trojan

    • 8 Comments

    Hi, I'm Manish from Global Escalation Services. I would like to present a multiple random bug check issue, which was caused by malicious code (trojan) running on the machine. This is the walkthrough of how we found the virus on the server.


    In this particular dump, the machine crashed with Bugcheck 0xA (IRQL_NOT_LESS_OR_EQUAL) because we got a Page Fault at dispatch level, also known as DPC Level (IRQL 2). Windows system architecture governs that we cannot have a page fault at dispatch level because paging requires I/O, I/O requires a wait, and we cannot wait while the IRQL is above dispatch level.  So when this anomaly happens Windows will intentionally crash the machine.

    We trapped in CcMapData because we touched the address c226d800 which was not valid because it’s paged out. If we look at implementation of CcMapData on MSDN http://msdn.microsoft.com/en-us/library/windows/hardware/ff539155(v=vs.85).aspx we see that this function can only be called below Dispatch Level, but the current CPU IRQL is 2.


    So how did this happen?  The most likely possibility is that some driver on the stack raised the IRQL by calling KeRaiseIrql and then forgot to lower it by calling KeLowerIrql.  There are many drivers on this stack and anyone could be the culprit. It is difficult to track when one of these may have done it as it’s long gone.


    We could have enabled IRQL Checking using Driver Verifier to find the culprit but we have to enable it on all drivers listed in the stack (and possibly others), which could cause some performance issues.  Also this was not the only crash we were seeing; there were various stop codes.

    So before going the verifier route I decided to dig more into this dump. I noticed there is an address on the stack for which the module name is not getting resolved. This looked odd (suspicious) as most of the time the debugger does a great job of finding the module.

    I started investigating what is this module.  It turned out to be a Trojan “TrojanDropper:Win32/Sirefef.B”.
    http://www.microsoft.com/security/portal/Threat/Encyclopedia/Entry.aspx?Name=TrojanDropper%3AWin32%2FSirefef.B

     

    0: kd> !analyze -v

    *******************************************************************************

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

    *******************************************************************************

    IRQL_NOT_LESS_OR_EQUAL (a)

    An attempt was made to access a pageable (or completely invalid) address at an

    interrupt request level (IRQL) that is too high.  This is usually

    caused by drivers using improper addresses.

    If a kernel debugger is available get the stack backtrace.

    Arguments:

    Arg1: c226d800, memory referenced

    Arg2: d0000002, IRQL

    Arg3: 00000000, bitfield :

          bit 0 : value 0 = read operation, 1 = write operation

          bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)

    Arg4: 808b64a6, address which referenced memory

     

    0: kd> kv

    ChildEBP RetAddr  Args to Child             

    f78ae41c 808b64a6 badb0d00 00000000 00000001 nt!KiTrap0E+0x2a7 (FPO: [0,0] TrapFrame @ f78ae41c)

    f78ae4cc f71a6f2d 8b22d520 f78ae4fc 00000400 nt!CcMapData+0x8c (FPO: [Non-Fpo])

    f78ae4ec f71a4494 f78ae7ec 8b64c150 01c6d800 Ntfs!NtfsMapStream+0x4b (FPO: [Non-Fpo])

    f78ae560 f71a6df0 f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadMftRecord+0x86 (FPO: [Non-Fpo])

    f78ae598 f71a6fac f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadFileRecord+0x7a (FPO: [Non-Fpo])

    f78ae5d0 f718e46d f78ae7ec e7c50cd8 e7c50ce0 Ntfs!NtfsLookupInFileRecord+0x37 (FPO: [Non-Fpo])

    f78ae67c f718e541 f78ae7ec e7c50cd8 f718e2cb Ntfs!NtfsWalkUpTree+0xbe (FPO: [Non-Fpo])

    f78ae6d8 f718e263 f78ae7ec e7c50cd8 00000000 Ntfs!NtfsBuildNormalizedName+0x44 (FPO: [Non-Fpo])

    f78ae704 f7196c2e f78ae7ec 8801d600 e7c50da0 Ntfs!NtfsQueryNameInfo+0x4b (FPO: [Non-Fpo])

    f78ae774 f71a0ff6 f78ae7ec 88081cb0 8b5f9260 Ntfs!NtfsCommonQueryInformation+0x291 (FPO: [Non-Fpo])

    f78ae7d8 f71a102f f78ae7ec 88081cb0 00000001 Ntfs!NtfsFsdDispatchSwitch+0x12a (FPO: [Non-Fpo])

    f78ae8f4 8081df85 8b3a7020 88081cb0 88081cb0 Ntfs!NtfsFsdDispatchWait+0x1c (FPO: [Non-Fpo])

    f78ae908 f721fd28 8b2fd220 8b60d308 8b54b020 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae934 8081df85 8b5f9260 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])

    f78ae948 f721fd28 88081ed0 8b60d308 c000000d nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae974 8081df85 8b54b020 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])

    f78ae988 f5c62bec 88081cb0 8b54a980 88081cb0 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    WARNING: Stack unwind information not available. Following frames may be wrong.

    f78ae99c f5c5e3ee 8b03b690 00000000 f78ae9c0 CtxSbx+0x5bec

    f78ae9ac 8081df85 8b03b690 88081cb0 8b0528e0 CtxSbx+0x13ee

    f78ae9c0 f61074e1 8b0528e0 8801d600 f78aea00nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae9e4 f61075d0 8b0a9b80 00081cb0 f78aea08 CtxAltStr+0x44e1

    f78ae9f4 8081df85 8b0a9b80 88081cb0 88081ed0 CtxAltStr+0x45d0

    f78aea08 8b5cfc89 00000000 87ef0000 87ef9002 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aec90 8081df85 8b5ef610 8b08c110 8b08c2a8 0x8b5cfc89 <------------ This looks odd what is this module?

    f78aeca4 f7241607 8b08c2a8 00000000 f78aece8nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aecb4 f72412b2 8b08c2a8 8b392b70 87f11974 CLASSPNP!SubmitTransferPacket+0xbb (FPO: [Non-Fpo])

    f78aece8 f7241533 00000000 00000e00 87f11808 CLASSPNP!ServiceTransferRequest+0x1e4 (FPO: [Non-Fpo])

    f78aed0c 8081df85 8b392ab8 00000000 8b2a2670 CLASSPNP!ClassReadWrite+0x159 (FPO: [Non-Fpo])

    f78aed20 f74c80cf 8b2b7d80 87f11998 f78aed44 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed30 8081df85 8b6e4020 87f11808 87f119bc PartMgr!PmReadWrite+0x95 (FPO: [Non-Fpo])

    f78aed44 f7317053 87f119d8 8b6e8148 882b9888 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed60 8081df85 8b2b7cc8 87f11808 87f119fc ftdisk!FtDiskReadWrite+0x1a9 (FPO: [Non-Fpo])

    f78aed74 f72cf4f5 885360cc 88536098 87f26810 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed90 f72d1517 87f11808 885360cc 8b60c470 volsnap!VspDecrementIrpRefCount+0x14f (FPO: [Non-Fpo])

    f78aeda8 f72c0398 87f26810 87f26810 88536098 volsnap!VspWriteVolumePhase22+0x3d (FPO: [Non-Fpo])

    f78aee30 f72d15d3 00f26810 885360cc 00000000 volsnap!VspAcquireNonPagedResource+0xc6 (FPO: [Non-Fpo])

    f78aee50 8081e123 00000000 87f215e8 88536098 volsnap!VspWriteVolumePhase2+0x59 (FPO: [Non-Fpo])

    f78aee80 f7241829 f78aeeb0 f72413ec 8b392ab8 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])

    f78aee88 f72413ec 8b392ab8 87f215e8 00000001 CLASSPNP!ClassCompleteRequest+0x11 (FPO: [Non-Fpo])

    f78aeeb0 8081e123 00000000 8b08c428 8b08c5c0 CLASSPNP!TransferPktComplete+0x1fd (FPO: [Non-Fpo])

    f78aeee0 f7266545 8b6e30e8 8b08c428 f78aef24 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])

    f78aeef0 f7265a8a 87f856a8 00000001 00000000 SCSIPORT!SpCompleteRequest+0x5e (FPO: [Non-Fpo])

    f78aef24 f7265130 8b6e30e8 87f856a8 f78aef9b SCSIPORT!SpProcessCompletedRequest+0x6a7 (FPO: [Non-Fpo])

    f78aef9c 8083211c 8b6e30a4 8b6e3030 00000000 SCSIPORT!ScsiPortCompletionDpc+0x2bd (FPO: [Non-Fpo])

    f78aeff4 8088dba7 f3f4f92c 00000000 00000000 nt!KiRetireDpcList+0xca (FPO: [Non-Fpo])

    f3f4f948 80a603d9 ffdffa02 f3f4f980 f3f4f980 nt!KiDispatchInterrupt+0x37 (FPO: [Uses EBP] [0,0,1])

    f3f4f964 80a60577 8b6c226c f3f4f980 8088d91d hal!HalpCheckForSoftwareInterrupt+0x81 (FPO: [Non-Fpo])

    f3f4f970 8088d91d 8b304c00 000001a3 f3f4fa04 hal!HalEndSystemInterrupt+0x67 (FPO: [Non-Fpo])

    f3f4f970 809395e7 8b304c00 000001a3 f3f4fa04 nt!KiInterruptDispatch+0x5d (FPO: [0,2] TrapFrame @ f3f4f980)

    f3f4fa04 80939c37 88139178 88028301 00000008 nt!ObpAllocateObject+0x199 (FPO: [Non-Fpo])

    f3f4fa38 808f8d28 00000000 8b76aad0 f3f4fa70 nt!ObCreateObject+0x129 (FPO: [Non-Fpo])

    f3f4fb44 80937a40 8b6afd10 00000000 88028398 nt!IopParseDevice+0x710 (FPO: [Non-Fpo])

    f3f4fbc4 80933b74 00000000 f3f4fc04 00000042 nt!ObpLookupObjectName+0x5b0 (FPO: [Non-Fpo])

    f3f4fc18 808eaee7 00000000 00000000 dffa7c01 nt!ObOpenObjectByName+0xea (FPO: [Non-Fpo])

    f3f4fc94 808ec181 077ef198 c0140000 077ef14c nt!IopCreateFile+0x447 (FPO: [Non-Fpo])

    f3f4fcf0 808eec10 077ef198 c0140000 077ef14c nt!IoCreateFile+0xa3 (FPO: [Non-Fpo])

    f3f4fd30 808897ec 077ef198 c0140000 077ef14c nt!NtCreateFile+0x30 (FPO: [Non-Fpo])

    f3f4fd30 7c82847c 077ef198 c0140000 077ef14c nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f3f4fd64)

    077ef22c 00000000 00000000 00000000 00000000 0x7c82847c

       

    The current CPU IRQL is 2, at which pagefaults cannot be serviced, hence windows crashed the machine.

    0: kd> !irql

    Debugger saved IRQL for processor 0x0 -- 2 (DISPATCH_LEVEL)

     

    Un-assembling from the return address of this unknown driver, to try to confirm that this is really driver code and that it really does belong in this call stack:

    0: kd> ub 8b5cfc89

    8b5cfc62 8bd7            mov     edx,edi

    8b5cfc64 c60605          mov     byte ptr [esi],5

    8b5cfc67 895e18          mov     dword ptr [esi+18h],ebx

    8b5cfc6a c7460400020000  mov     dword ptr [esi+4],200h

    8b5cfc71 c7460809000000  mov     dword ptr [esi+8],9

    8b5cfc78 c7461c70fb5c8b  mov     dword ptr [esi+1Ch],8B5CFB70h

    8b5cfc7f c64603e0        mov     byte ptr [esi+3],0E0h

    8b5cfc83 ff158c805d8b    call    dword ptr ds:[8B5D808Ch]


    Sure does call IofCallDriver

    0: kd> dps 8B5D808Ch l1

    8b5d808c  8081df40 nt!IofCallDriver

     

    So what is this driver? In Windows every image starts with a PE header which starts with letters “MZ”. So I started looking for PE header. I took the offset of the module on the stack and went back to its page boundary, then I started moving 1 page back at a time looking for the PE header.

    0: kd> dc 8b5cf000

    8b5cf000  0010b9f2 f02b0000 3b063c8b 83137538  ......+..<.;8u..

    8b5cf010  c08304e9 04f98304 b85fee73 00000001  ........s._.....

    8b5cf020  9cb8c35e b98b5d86 00000010 ff8bd02b  ^....]......+...

    8b5cf030  3b02348b 83137530 c08304e9 04f98304  .4.;0u..........

    8b5cf040  b85fee73 00000001 335fc35e ccc35ec0  s._.....^._3.^..

    8b5cf050  83ec8b55 78a04cec 538b5da4 c0b60f56  U....L.x.].SV...

    8b5cf060  827ae857 ff330000 33f46589 f845c7db  W.z...3..e.3..E.

    8b5cf070  00000400 8b084d8b 52510c55 50b4458d  .....M..U.QR.E.P

     

    0: kd> dc 8b5cf000-1000

    8b5ce000  01c73024 00000000 c70cc483 00800002  $0..............

    8b5ce010  845e5f00 b10874db 0815ff01 8b8b5d80  ._^..t.......]..

    8b5ce020  6a0c2444 15ff5000 8b5d8028 14c25b5d  D$.j.P..(.].][..

    8b5ce030  cccccc00 cccccccc cccccccc cccccccc  ................

    8b5ce040  6a306a56 2415ff00 8b8b5d80 74f685f0  Vj0j...$.].....t

    8b5ce050  6a006a53 68026a01 8b5d0892 5d08ae68  Sj.j.j.h..].h..]

    8b5ce060  ff006a8b 5d80ac15 ff56508b 5d80a815  .j.....].PV....]

    8b5ce070  000d8b8b ff8b5da2 5d80b015 6a006a8b  .....].....].j.j


    0: kd> dc 8b5cf000-1000*2

    8b5cd000  0689c033 89044689 46890846 1046890c  3....F..F..F..F.

    8b5cd010  89144689 ec831846 1c46891c 57204689  .F..F.....F..F W

    8b5cd020  85244689 8d0574f6 02eb284e c033c933  .F$..t..N(..3.3.

    8b5cd030  41890189 08418904 8b34468b 4e891048  ...A..A..F4.H..N

    8b5cd040  14508b10 8b145689 4e891848 1c508b18  ..P..V..H..N..P.

    8b5cd050  8b1c5689 4e891848 1c508b20 2424448d  .V..H..N .P..D$$

    8b5cd060  244c8d50 186a510c 8b245689 6a302454  P.L$.Qj..V$.T$0j

    8b5cd070  46c65205 46c70005 00000008 0c46c700  .R.F...F......F.

     

    Finally I found the PE header for this image.

    0: kd> dc 8b5cf000-1000*3

    8b5cc000  00905a4d 00000003 00000004 0000ffff  MZ..............

    8b5cc010  000000b8 00000000 00000040 00000000  ........@.......

    8b5cc020  00000000 00000000 00000000 00000000  ................

    8b5cc030  00000000 00000000 00000000 000000d0  ................

    8b5cc040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th

    8b5cc050  70207369 72676f72 63206d61 6f6e6e61  is program canno

    8b5cc060  65622074 6e757220 206e6920 20534f44  t be run in DOS

    8b5cc070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

     

    Using the built-in debugger extension !dh I dumped the header of this image to find the name.  Unfortunately there is no name for this image. This address 8b5cc000 is not in the loaded module list, which raised further suspicion. Either it is hiding its load address or this driver was not loaded by standard loading mechanism. This module date shows it’s pretty recent build.

    0: kd> !dh 8b5cc000

     

    File Type: DLL

    FILE HEADER VALUES

         14C machine (i386)

           4 number of sections

    4EA3461E time date stamp Sun Oct 23 04:09:26 2011

     

           0 file pointer to symbol table

           0 number of symbols

          E0 size of optional header

        2102 characteristics

                Executable

                32 bit word machine

                DLL

     

    OPTIONAL HEADER VALUES

         10B magic #

        9.00 linker version

        A400 size of code

        2000 size of initialized data

           0 size of uninitialized data

        46C0 address of entry point

        1000 base of code

             ----- new -----

    10000000 image base

        1000 section alignment

         200 file alignment

           1 subsystem (Native)

        5.00 operating system version

        0.00 image version

        5.00 subsystem version

       10000 size of image

         400 size of headers

        DF1F checksum

    00100000 size of stack reserve

    00001000 size of stack commit

    00100000 size of heap reserve

    00001000 size of heap commit

           0  DLL characteristics

           0 [       0] address [size] of Export Directory

        C91C [      3C] address [size] of Import Directory

           0 [       0] address [size] of Resource Directory

           0 [       0] address [size] of Exception Directory

           0 [       0] address [size] of Security Directory

        F000 [     3FC] address [size] of Base Relocation Directory

           0 [       0] address [size] of Debug Directory

           0 [       0] address [size] of Description Directory

           0 [       0] address [size] of Special Directory

           0 [       0] address [size] of Thread Storage Directory

           0 [       0] address [size] of Load Configuration Directory

           0 [       0] address [size] of Bound Import Directory

        C000 [     1A8] address [size] of Import Address Table Directory

           0 [       0] address [size] of Delay Import Directory

           0 [       0] address [size] of COR20 Header Directory

           0 [       0] address [size] of Reserved Directory

     

     

    SECTION HEADER #1

       .text name

        A354 virtual size

        1000 virtual address

        A400 size of raw data

         400 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    60000020 flags

             Code

             (no align specified)

             Execute Read

     

    SECTION HEADER #2

      .rdata name

        13AC virtual size

        C000 virtual address

        1400 size of raw data

        A800 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    40000040 flags

             Initialized Data

             (no align specified)

             Read Only

     

    SECTION HEADER #3

       .data name

         4B0 virtual size

        E000 virtual address

         200 size of raw data

        BC00 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    C0000040 flags

             Initialized Data

             (no align specified)

             Read Write

     

    SECTION HEADER #4

      .reloc name

         576 virtual size

        F000 virtual address

         600 size of raw data

        BE00 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    42000040 flags

             Initialized Data

             Discardable

             (no align specified)

             Read Only


    0: kd> !lmi 8b5cc000 

    Loaded Module Info: [8b5cc000]

    ffffffff8b5cc000 is not a valid address

     

    0: kd> lmvm 8b5cc000 

    start    end        module name


    Checking the import table it does have calls to raise and lower the IRQL. We get to the import table by taking the base address plus the offset to the Import Address Table Directory.  The below output is just a snippet of the whole table.

    0: kd> dps 8b5cc000+c000

    8b5d8000  80a603f4 hal!KfLowerIrql

    8b5d8004  80a5ff00 hal!KeGetCurrentIrql

    8b5d8008  80a600b4 hal!KfRaiseIrql

     

    Dumping the entire image contents in memory to find more clues about this driver.  Again, I am only showing snippets of the whole output.

    0: kd> dc 8b5cc000  L?10000/4

    8b5cc000  00905a4d 00000003 00000004 0000ffff  MZ..............

    8b5cc010  000000b8 00000000 00000040 00000000  ........@.......

    8b5cc020  00000000 00000000 00000000 00000000  ................

    8b5cc030  00000000 00000000 00000000 000000d0  ................

    8b5cc040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th

    8b5cc050  70207369 72676f72 63206d61 6f6e6e61  is program canno

    8b5cc060  65622074 6e757220 206e6920 20534f44  t be run in DOS

    8b5cc070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

    8b5d5e20  76000000 66697265 77252079 00000a5a  ...verify %wZ...

    8b5d5e30  31000000 35343332 39383736 33323130  ...1234567890123

    8b5d5e40  37363534 31303938 35343332 39383736  4567890123456789

    8b5d5e50  33323130 37363534 31303938 35343332  0123456789012345

    8b5d5e60  39383736 33323130 37363534 31303938  6789012345678901

    8b5d5e70  00343332 66000000 646e756f 67697320  234....found sig

    8b5d5e80  7574616e 3d206572 0a752520 b4000000  nature = %u.....   

     

    Interestingly this image has other images (modules) embedded in it.  We can see other PE headers, which again have no name.  This looks highly suspicious and resembles behavior used by malicious software.

    8b5d0970  f775c085 4848c78b 4dc35f5e 0300905a  ..u...HH^_.MZ...

    8b5d0980  04000000 ff000000 b80000ff 00000000  ................

    8b5d0990  40000000 00000000 00000000 00000000  ...@............

    8b5d09a0  00000000 00000000 00000000 00000000  ................

    8b5d09b0  00000000 c8000000 0e000000 000eba1f  ................

    8b5d09c0  21cd09b4 cd4c01b8 69685421 72702073  ...!..L.!This pr

    8b5d09d0  6172676f 6163206d 746f6e6e 20656220  ogram cannot be

    8b5d09e0  206e7572 44206e69 6d20534f 2e65646f  run in DOS mode.

    8b5d2200  4d00004e 0300905a 04000000 ff000000  N..MZ...........

    8b5d2210  b80000ff 00000000 40000000 00000000  ...........@....

    8b5d2220  00000000 00000000 00000000 00000000  ................

    8b5d2230  00000000 00000000 00000000 f0000000  ................

    8b5d2240  0e000000 000eba1f 21cd09b4 cd4c01b8  ...........!..L.

    8b5d2250  69685421 72702073 6172676f 6163206d  !This program ca

    8b5d2260  746f6e6e 20656220 206e7572 44206e69  nnot be run in D

    8b5d2270  6d20534f 2e65646f 240a0d0d 00000000  OS mode....$....

     

    After ensuring my AV definitions were up to date, I decided to dump this memory contents into a file onto my machine. The moment contents were written my AV Microsoft Forefront Endpoint Protection caught a Trojan in this file.

    0: kd> .writemem c:\temp\drv.sys 8b5cc000   L?10000
    Writing 10000 bytes................................

       
    image001

     

    image003


    Before any further trouble shooting we asked the customer to clean the Trojan. Once we did that bug checks disappeared.


    Hope you enjoyed reading this post.
  • Ntdebugging Blog

    Troubleshooting Pool Leaks Part 2 – Poolmon

    • 8 Comments

    In our previous article we discussed how to identify a pool leak using perfmon.  Although it may be interesting to know that you have a pool leak, most customers are interested in identifying the cause of the leak so that it can be corrected.  In this article we will begin the process of identifying what kernel mode driver is leaking pool, and possibly identify why.

     

    Often when we are collecting data for a poor performance scenario there are two pieces of data that we collect.  Perfmon log data is one, as we discussed in our previous article.  The other piece of data is poolmon logs.  The memory manager tracks pool usage according to the tag associated with the pool allocations, using a technique called pool tagging.  Poolmon gathers this data and displays it in an easy to use format.  Poolmon can also be configured to dump data to a log, and in some scenarios it is beneficial to schedule poolmon to periodically collect such logs.  There are several available techniques to schedule poolmon, however that is beyond the scope of this article.

     

    Poolmon has shipped with many different packages over the years; it is currently available with the Windows Driver Kit.  If you install the WDK to the default folder, poolmon will be in “C:\Program Files (x86)\Windows Kits\8.0\Tools\x64”.  Poolmon does not have dependencies on other modules in this folder; you can copy it to your other computers when you need to investigate pool usage.

     

    How does pool tagging work?  When a driver allocates pool it calls the ExAllocatePoolWithTag API.  This API accepts a tag - a four-letter string - that will be used to label the allocation.  It is up to a driver developer to choose this tag.  Ideally each developer will choose a tag that is unique to their driver and use a different tag for each code path which calls ExAllocatePoolWithTag.  Because each tag should be unique to each driver, if we can identify the tag whose usage corresponds with the leak we can then begin to identify the driver which is leaking the memory.  The tag may also give the driver developer clues as to why the memory is being leaked, if they use a unique tag for each code path.

     

    To view the pool usage associated with each tag run “poolmon -b” from a command prompt.  This will sort by the number of bytes associated with each tag.  If you are tracking pool usage over a period of time, you can log the data to a file with “poolmon -b -n poolmonlog1.txt”, replacing 1 with increasing numbers to obtain a series of logs.  Once you have a series of logs you may be able to view usage increasing for a specific tag, in a corresponding fashion to what you see in perfmon.

     

    When analyzing poolmon the important data is at the top.  Typically the tag with the largest usage in bytes is the cause of the leak.

     

    Poolmon -b

     

    In the above data we can see that the tag with the most pool usage is “Leak”.  Now that we know what tag is leaking we need to identify what driver is using this tag.  Techniques for associating a leak with a tag vary, but findstr is often effective.  Most drivers are located in c:\windows\system32\drivers, so that is a good starting point when looking for the driver.  If you don’t find a result in that folder, go up a folder and try again, repeating until you get to the root of the drive.

     

    C:\>findstr /s Leak *.sys

    Users\Administrator\Desktop\myfault.sys:

    AìIALeak;┴☼BAì

    ·∟   §£ Θ─  A╗☻   E"Θ╡☺ Hï♣╔♂  $Θª  Hï:Hc ê\@ë

      └δ_Aï ╞♣@  ë♣▓  Aï@ë¼←  δCAâ∙uAïAìIALeak;┴☼B3ï §

     

    In the above output we can see that “Leak” is used in myfault.sys.  If we hadn’t forced this leak with notmyfault, the next step in troubleshooting would be an internet search for the tag and the driver.  Often such a search will allow you to identify a specific fault within the driver and a solution.

     

    Don’t panic if findstr doesn’t find your tag, or if you find the tag but it is not unique to one driver.  In future articles we will cover additional techniques for associating drivers with tags, and for associating allocations with specific code within a driver.

  • Ntdebugging Blog

    Case of the Unexplained Services exe Termination

    • 8 Comments

    Hello Debuggers! This is Ron Stock from the Global Escalation Services team and I recently worked an interesting case dispatched to our team because Services.exe was terminating. Nothing good ever happens when Services.exe exits. In this particular case, client RDP sessions were forcibly disconnected from the server and the server machine was shutting down unexpectedly. This is the message encountered at the console on the server.

     

     

     

    The customer was able to trigger the crash by changing anything to do with a particular non-Microsoft service in the Services MMC (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...) To protect our vendor friend, I refer to this service as FriendlyService throughout this article. We could have stopped the investigation right here and implicated the FriendlyService vendor, however as you will see, this service was merely a victim.

     

    Investigation

    When investigating a process termination, I routinely gather a process dump to start my investigation. The frustrating thing about this instance was how none of our debugging tools were generating a dump file when Services.exe terminated. I tried the usual toolset including AdPlus, ProcDump and DebugDiag to no avail. Despite the lack of data from a memory dump, I was still able to piece together a stack and attack the problem through a creative approach. Debugging is an art.

     

    First I reviewed the application log which was loaded with entries like this one.

     

    11/29/2012 04:29:05 PM  Information   HE2NTSP208       1004    Application Error  N/A Faulting application services.exe, version 5.2.3790.4455, faulting module msvcr80.dll, version 8.0.50727.6195, fault address 0x000000000001df67

     

    From the event log entry above I was able to determine the faulting module, msvcr80.dll, and the relative offset, 0x000000000001df67. This address is basically the return address of the faulting call. As you can see from the ln output below, the function name was msvcr80!wcscpy_s. As I noted above, I wasn’t able to gather a dump during process termination so I had the customer use ProcDump to snap a dump of Services.exe during normal process operation (not a crash dump).

     

    0:000> ln 00000000`78130000 + 0x000000000001df67
    (00000000`7814ded0)   msvcr80!wcscpy_s+0x97   |  (00000000`7814df80)   msvcr80!wcsncpy_s

     

    Next I needed to determine which DLLs in the Services.exe process were calling msvcr80!wcscpy_s by reviewing the import tables of the binaries loading in the process. I used the !peb command to dump out the Process Environment Block (PEB). This gave me the list of base addresses for each loaded DLL. I focused mainly on non-Microsoft binaries. To protect our vendor friends, I renamed the DLL to ThirdPartyServiceMonitor.Dll in this article.

     

    This is the output from the !peb command with the base addresses in the left column.

     

    0:000> !peb

    PEB at 000007fffffde000

        InheritedAddressSpace:    No

        ReadImageFileExecOptions: No

        BeingDebugged:            Yes

        ImageBaseAddress:         0000000100000000

        Ldr                       0000000077fa9f20

        Ldr.Initialized:          Yes

        Ldr.InInitializationOrderModuleList: 00000000000d2df0 . 00000000001a3600

        Ldr.InLoadOrderModuleList:           00000000000d2d20 . 000000000019cbc0

        Ldr.InMemoryOrderModuleList:         00000000000d2d30 . 000000000019cbd0

                Base TimeStamp                     Module

           100000000 49882047 Feb 03 04:45:27 2009 C:\WINDOWS\system32\services.exe

            77ec0000 4ecbcd57 Nov 22 10:27:03 2011 C:\WINDOWS\system32\ntdll.dll

            77d40000 49c51cdd Mar 21 11:59:09 2009 C:\WINDOWS\system32\kernel32.dll

         7ff7fc00000 45d6ccae Feb 17 03:36:46 2007 C:\WINDOWS\system32\msvcrt.dll

         7ff7fee0000 4a61f064 Jul 18 10:55:16 2009 C:\WINDOWS\system32\ADVAPI32.dll

         7ff7fd30000 4c6ba77a Aug 18 04:27:22 2010 C:\WINDOWS\system32\RPCRT4.dll

         7ff7e9c0000 4a37438e Jun 16 02:02:38 2009 C:\WINDOWS\system32\Secur32.dll

            77c20000 45e7c5c2 Mar 02 00:35:46 2007 C:\WINDOWS\system32\USER32.dll

         7ff7fc90000 490062ac Oct 23 06:40:28 2008 C:\WINDOWS\system32\GDI32.dll

         7ff7c680000 45d6ccab Feb 17 03:36:43 2007 C:\WINDOWS\system32\USERENV.dll

         7ff7c450000 45d6cc90 Feb 17 03:36:16 2007 C:\WINDOWS\system32\SCESRV.dll

         7ff7e490000 45d6cc04 Feb 17 03:33:56 2007 C:\WINDOWS\system32\AUTHZ.dll

         7ff77370000 4fedd464 Jun 29 11:14:28 2012 C:\WINDOWS\system32\NETAPI32.dll

         7ff7c410000 45d6cca5 Feb 17 03:36:37 2007 C:\WINDOWS\system32\umpnpmgr.dll

         7ff7d4d0000 45d6ccb8 Feb 17 03:36:56 2007 C:\WINDOWS\system32\WINSTA.dll

         7ff65470000 45d6cc5c Feb 17 03:35:24 2007 E:\Program Files\ThirdPartyDirectory\ThirdParty2.dll

              400000 424360e9 Mar 24 19:52:57 2005 C:\WINDOWS\system32\msvcp60.dll

         7ff7d500000 45d6cc3b Feb 17 03:34:51 2007 C:\WINDOWS\system32\IMM32.DLL

              e50000 4df9462e Jun 15 18:54:22 2011 E:\Program Files\ThirdPartyDirectory\ThirdPartyServiceMonitor.dll

     

    Using the base address of ThirdPartyServiceMonitor, I dumped the header to find the Import Address Table Directory.

     

    0:000> !dh 00000000`00e50000

     

    1E000 [     758] address [size] of Import Address Table Directory

     

    Using the dps command I dumped all of the functions in the import table of ThirdPartyServiceMonitor.dll. I found msvcr80!wcscpy_s in the function list. This indicates ThirdPartyServiceMonitor.dll makes calls to the msvcr80!wcscpy_s.

     

    0:000> dps 00000000`00e50000+ 1E000 l758/@$ptrsize

    <snippet>

    .

    .

    00000000`00e6e458  00000000`7814d890 msvcr80!_wcsnicmp

    00000000`00e6e460  00000000`7814db20 msvcr80!_wcsicmp

    00000000`00e6e498  00000000`7814ded0 msvcr80!wcscpy_s

    .

    .

     

    Since this was the only third party DLL with msvcr80!wcscpy_s in its import table, I was able to continue piecing together my stack. ThirdPartyServiceMonitor.dll was calling msvcr80!wcscpy_s and causing Services.exe to crash. At this point in the investigation, the stack looks like this-

     

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    In my quest to continue building my “conceptual” stack without a crash dump file, I reviewed the status code from the “System Shutdown” dialog displayed when Services.exe terminated. Notice the status code -1073741811 in the error. What the heck does that mean?

     

     

    Well I easily resolved the cryptic status code by passing 0n-1073741811 to the !error command in the debugger. The “0n” prefix indicates the value should be interpreted as decimal rather than hex by the debugger. I also included the negative symbol “-“ because this also appears in status code.

     

    0:030> !error 0n-1073741811

    Error code: (NTSTATUS) 0xc000000d (3221225485) - An invalid parameter was passed to a service or function.

     

    Armed with the status code information, I reviewed the msvcr80!wcscpy_s assembly code to determine if this status code was returned at any point. In the assembly I found a call to a function named msvcr80!_invalid_parameter. In context of the message, “an invalid parameter was passed to a service or function”, this certainly sounds like the code path taken.

     

    0:000> uf msvcr80!wcscpy_s

    <snippet>

    msvcr80!wcscpy_s+0x1a

       18 00000000`7814deea e88184feff      call    msvcr80!_errno(00000000`78136370)

       18 00000000`7814deef 4533c9          xor     r9d,r9d

       18 00000000`7814def2 4533c0          xor     r8d,r8d

       18 00000000`7814def5 33d2            xor     edx,edx

       18 00000000`7814def7 33c9            xor     ecx,ecx

       18 00000000`7814def9 48c744242000000000 mov   qword ptr [rsp+20h],0

       18 00000000`7814df02 c70016000000    mov     dword ptr[rax],16h

       18 00000000`7814df08 e873d1feff      call    msvcr80!_invalid_parameter (00000000`7813b080)

       18 00000000`7814df0d b816000000      mov     eax,16h

       34 00000000`7814df12 4883c438        add     rsp,38h

       34 00000000`7814df16 c3              ret

     

    It was reasonable to add this call to my conceptual stack because the call tree makes sense.

     

    msvcr80!_invalid_parameter

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    Because I’m a curious kind of guy, I unassembled msvcr80!_invalid_parameter to peel back another layer of the onion. To my surprise I found a call to msvcr80!_imp_TerminateProcess. BOOM! This explains why the debugger wasn’t catching the process crash. The process was terminating ‘organically’ through a TerminateProcess call rather than crashing due to an exception, however it was unexpectedly terminating. In other words, all of the services running on the machine were not expecting Services.exe to terminate.

     

    msvcr80!_invalid_parameter+0xd5

    <snippet>

       88 00000000`7813b155 ff156d200900    call    qword ptr [msvcr80!_imp_GetCurrentProcess (00000000`781cd1c8)]

       88 00000000`7813b15b ba0d0000c0      mov     edx,0C000000Dh

       88 00000000`7813b160 488bc8          mov     rcx,rax

       88 00000000`7813b163 ff1557200900    call    qword ptr [msvcr80!_imp_TerminateProcess(00000000`781cd1c0)]

     

    Now I was able to cobble together a fairly accurate stack without a dump file. At this point I could tell ThirdPartyServiceMonitor.dll was passing bad parameters to msvcr80!wcscpy_s. However, this didn’t explain how FriendlyService (mentioned in the blog introduction) was triggering the issue. I needed to go deeper with a live debug by leveraging the stack information I devised.

     

    msvcr80!_imp_TerminateProcess

    msvcr80!_invalid_parameter

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    On the customer’s server I attached Windbg to the Services.exe process and set a breakpoint on msvcr80!_invalid_parameter.

     

    0:001> bp msvcr80!_invalid_parameter

     

    Then I had the customer reproduce the issue by changing the startup type on FriendlyService in the Services MMC. As I mentioned above, this was one way to trigger the issue. BOOM! My breakpoint hit and looked exactly like the conceptual stack I pieced together. Now I was able to determine what ThirdPartyServiceMonitor was passing to msvcr80!wcscpy_s while broken in with the debugger.

     

    0:035> k

    Child-SP          RetAddr           Call Site

    00000000`105deb00 00000000`7814df67 msvcr80!_invalid_parameter+0xe3

    00000000`105df0c0 00000000`00e53045 msvcr80!wcscpy_s+0x97

    00000000`105df100 00000000`00e5947e ThirdPartyServiceMonitor+0x3045

    00000000`105df130 00000000`00e58405 ThirdPartyServiceMonitor+0x947e

    00000000`105df180 000007ff`7fd69c75 ThirdPartyServiceMonitor+0x8405

    00000000`105df1b0 000007ff`7fe9ccc9 rpcrt4!Invoke+0x65

    00000000`105df200 000007ff`7fe9d58d rpcrt4!NdrStubCall2+0x54d

     

    I reviewed the assembly of ThirdPartyServiceMonitor at the point in which it calls msvcr80!wcscpy_s. I discovered that the vendor hardcoded the size of the destination string buffer with 200 hex (512 decimal) while the size of the source string buffer was greater than 512 decimal.

     

    0:035> ub 00000000`00e53045

    ThirdPartyServiceMonitor+0x3020:

    00000000`00e53020 898324040000    mov     dword ptr [rbx+424h],eax

    00000000`00e53026 488b4738        mov     rax,qword ptr [rdi+38h]

    00000000`00e5302a 4c8b4010        mov     r8,qword ptr [rax+10h] <<<< Source Buffer

    00000000`00e5302e 4d85c0          test    r8,r8

    00000000`00e53031 7412            je      ThirdPartyServiceMonitor+0x3045 (00000000`00e53045)

    00000000`00e53033 488d8b28040000  lea     rcx,[rbx+428h] <<<< Destination Buffer

    00000000`00e5303a ba00020000      mov     edx,200h <<<<< Buffer Size hardcoded to 200 hex

    00000000`00e5303f ff1553b40100    call    qword ptr [ThirdPartyServiceMonitor!PlugControl+0xff38 (00000000`00e6e498)] <<<< call to msvcr80!wcscpy_s

    00000000`00e53045 eb16            jmp     ThirdPartyServiceMonitor +0x305d (00000000`00e5305d) <<<< return from msvcr80!wcscpy_s

     

    0:035> .formats 200

    Evaluate expression:

      Hex:     00000000`00000200

      Decimal: 512

     

    Here is the definition of wcscpy_s from MSDN

    errno_t wcscpy_s(

       wchar_t *strDestination,         // Location of destination string buffer

       size_t numberOfElements,         // Size of the destination string buffer.

       const wchar_t *strSource         // Null-terminated source string buffer.

    );

     

    Here are the parameters passed to msvcr80!wcscpy_s. As a reminder, the x64 compiler uses rcx to pass the first parameter, rdx for the second, and r8 for the third. In this case the buffer size was the second parameter in rdx and the source buffer was in r8, the third parameter.

     

    0:035> dq 00000000`00e6e498 l1

    00000000`00e6e498  00000000`7814ded0

     

    0:035> ln 00000000`7814ded0

    (00000000`7814ded0)   msvcr80!wcscpy_s   |  (00000000`7814df80)   msvcr80!wcsncpy_s

    Exact matches:

        msvcr80!wcscpy_s

     

    Dumping the source string in r8 showed the string was clearly longer than 512 characters.

     

    0:035> dc 00000000`0103b438

    00000000`0103b438  003a0000 0049005c 0074006e 00670065  ..:.\.F.r.e.i.n.

    00000000`0103b448  00610072 00690074 006e006f 00670041  d.l.y.S.e.r.v.i.

    00000000`0103b458  006e0065 005c0074 0069006c 005c0062  c.e.\.l.i.b.\..

    .

    .

    0:035> dc

    00000000`0103b738  00650070 002e0072 00700061 002e0070  p.e.r...a.p.p...

    00000000`0103b748  00610070 00610072 0065006d 00650074  p.a.r.a.m.e.t.e.

    00000000`0103b758  002e0072 003d0031 00770020 00610072  r...1.=. .w.r.a.

    00000000`0103b768  00700070 00720065 0061002e 00700070  p.p.e.r...a.p.p.

    00000000`0103b778  0070002e 00720061 006d0061 00740065  ..p.a.r.a.m.e.t.

    00000000`0103b788  00720065 0032002e 0020003d 00720077  e.r...2.=. .w.r.

    00000000`0103b798  00700061 00650070 002e0072 00700061  a.p.p.e.r...a.p.

    00000000`0103b7a8  002e0070 00610070 00610072 0065006d  p...p.a.r.a.m.e.

    0:035> dc

    00000000`0103b7b8  00650074 002e0072 003d0033 00770020  t.e.r...3.=. .w.

    00000000`0103b7c8  00610072 00700070 00720065 0061002e  r.a.p.p.e.r...a.

    00000000`0103b7d8  00700070 0070002e 00720061 006d0061  p.p...p.a.r.a.m.

    00000000`0103b7e8  00740065 00720065 0034002e 0020003d  e.t.e.r...4.=. .

    00000000`0103b7f8  00720077 00700061 00650070 002e0072  w.r.a.p.p.e.r...

    00000000`0103b808  00700061 002e0070 00610070 00610072  a.p.p...p.a.r.a.

    00000000`0103b818  0065006d 00650074 002e0072 003d0035  m.e.t.e.r...5.=.

    00000000`0103b828  00770020 00610072 00700070 00720065  .w.r.a.p.p.e.r.

     

    It was not hard to figure out this string was the imagefile path located at HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\FriendlyService. You can see from the string that service takes parameters which increased the size of the image path beyond 512 characters.

     

    FriendlyService\lib\friendly.3\sbin\friendlywindows-x86-32.exe-s E:\ FriendlyService\conf\wrapper.conf set.DATA_APP=apia "set.DATA_APP_LONG= FriendlyServiceVendor" set.DATA_EXE=E:\ FriendlyService\bin\..\lib\friendly.3\bin set.DATA_HOME=E:\ FriendlyService\bin\..\lib\friendly.3 set.INSTALL_DIR=E:\ FriendlyService\bin\.. wrapper.working.dir=E:\ FriendlyService\bin\.. wrapper.app.parameter.1= wrapper.app.parameter.2= wrapper.app.parameter.3= wrapper.app.parameter.4= wrapper.app.parameter.5= wrapper.app.parameter.6= wrapper.app.parameter.7= wrapper.app.parameter.8= wrapper.app.parameter.9=

     

    The ThirdPartyServiceMonitor hooks any changes made to a service (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...). After hooking the change, ThirdPartyServiceMonitor.dll performs a string copy of the service’s image file path. In most cases this works like a champ, however in this instance, the FriendlyService image path from vendor 1 is really long and the ThirdPartyServiceMonitor from vendor 2 doesn’t account for service image paths exceeding 512 characters. This is the perfect storm! ThirdPartyServiceMonitor needs to remove the hardcoded buffer size.

     

    This example occurred on Windows Server 2003.  Starting in Windows 7 and Windows Server 2008 R2, Windows has added functionality for catching processes that exit ‘organically’ through a TerminateProcess call.  You can find information on this added functionality on MSDN.

  • Ntdebugging Blog

    Interpreting Event 153 Errors

    • 8 Comments

    Hello my name is Bob Golding and I would like to share with you a new event that you may see in the system event log.  Event ID 153 is an error associated with the storage subsystem. This event was new in Windows 8 and Windows Server 2012 and was added to Windows 7 and Windows Server 2008 R2 starting with hot fix KB2819485.

     

    An event 153 is similar to an event 129.  An event 129 is logged when the storport driver times out a request to the disk; I described event 129 messages in a previous article.  The difference between a 153 and a 129 is that a 129 is logged when storport times out a request, a 153 is logged when the storport miniport driver times out a request.  The miniport driver may also be referred to as an adapter driver or HBA driver, this driver is typically written the hardware vendor.

     

    Because the miniport driver has a better knowledge of the request execution environment, some miniport drivers time the request themselves instead of letting storport handle request timing.  This is because the miniport driver can abort the individual request and return an error rather than storport resetting the drive after a timeout.  Resetting the drive is disruptive to the I/O subsystem and may not be necessary if only one request has timed out.  The error returned from the miniport driver is bubbled up to the class driver who can log an event 153 and retry the request.

     

    Below is an example event 153:

     

    Event 153 Example

     

    This error means that a request failed and was retried by the class driver.  In the past no message would be logged in this situation because storport did not timeout the request.  The lack of messages resulted in confusion when troubleshooting disk errors because timeouts would occur but there would be no evidence of the error.

     

    The details section of the event the log record will present what error caused the retry and whether the request was a read or write. Below is the details output:

     

    Event 153 Details

     

    In the example above at byte offset 29 is the SCSI status, at offset 30 is the SRB status that caused the retry, and at offset 31 is the SCSI command that is being retried.  In this case the SCSI status was 00 (SCSISTAT_GOOD), the SRB status was 09 (SRB_STATUS_TIMEOUT), and the command was 28 (SCSIOP_READ). 

     

    The most common SCSI commands are:

    SCSIOP_READ - 0x28

    SCSIOP_WRITE - 0x2A

     

    The most common SRB statuses are below:

    SRB_STATUS_TIMEOUT - 0x09

    SRB_STATUS_BUS_RESET - 0x0E

    SRB_STATUS_COMMAND_TIMEOUT - 0x0B

     

    A complete list of SCSI operations and statuses can be found in scsi.h in the WDK.  A list of SRB statuses can be found in srb.h.

     

    The timeout errors (SRB_STATUS_TIMEOUT and SRB_STATUS_COMMAND_TIMEOUT) indicate a request timed out in the adapter. In other words a request was sent to the drive and there was no response within the timeout period.  The bus reset error (SRB_STATUS_BUS_RESET) indicates that the device was reset and that the request is being retried due to the reset since all outstanding requests are aborted when a drive receives a reset.

     

    A system administrator who encounters event 153 errors should investigate the health of the computer’s disk subsystem.  Although an occasional timeout may be part of the normal operation of a system, the frequent need to retry requests indicates a performance issue with the storage that should be corrected.

  • Ntdebugging Blog

    Troubleshooting Pool Leaks Part 1 – Perfmon

    • 7 Comments

    Over the years the NTDebugging Blog has published several articles about pool memory and pool leaks.  However, we haven’t taken a comprehensive approach to understanding and troubleshooting pool memory usage.  This upcoming series of articles is going to tackle pool leaks from the basics to advanced troubleshooting techniques.  Most of the examples will use the Windows Sysinternals tool NotMyFault to generate a leak so our readers will be able to reproduce the described behavior and repeat the troubleshooting steps.

     

    We need to start by understanding what pool is and how it is used.  Pool is virtual memory that is used by drivers in much the same way user mode applications use heap.  A driver developer calls ExAllocatePoolWithTag to get a block of memory that can be used in much the same way a user mode programmer would use memory returned by HeapAlloc or malloc.  The memory manager, which is responsible for managing pool, is able to efficiently handle small allocations by taking a page of virtual memory (typically 4KB) and breaking it up into smaller blocks.  The memory manager is also able to allocate pool in blocks larger than a page.  There are two types of pool a developer can request from ExAllocatePoolWithTag, paged pool and nonpaged pool.  As the names suggest one type of pool memory can be paged out, and the other cannot be paged.  Paged pool is used for most allocations, nonpagedpool is used for memory that will be written or read at an IRQL of DISPATCH_LEVEL or above.

     

    Pool leaks happen when a driver calls ExAllocatePoolWithTag but never calls the corresponding ExFreePool or ExFreePoolWithTag routine.  A leak is different than just high memory utilization, which may happen in normal conditions as load increases.  For example, the srv.sys driver creates work items for incoming requests, and when there is a large amount of SMB traffic to a server the pool usage from srv.sys may increase to handle this traffic.  Typically the differentiation between a leak and high memory usage due to load is that a leak never decreases.  Memory usage that is load related should decrease when the load is reduced.  Monitoring is required to differentiate between these two scenarios.  Performance Monitor (aka perfmon) is typically the most effective tool to begin such an investigation.

     

    The symptom of a pool leak is often poor system performance when the system runs out of pool, or on 64-bit systems the pool may begin to consume a large amount of the available memory.  This symptom makes perfmon an ideal tool to begin troubleshooting as it can be used to identify a wide variety of potential causes of poor performance.  Perfmon is most useful when it is started before a system enters a state of poor performance so that trend data can be analyzed leading up to the problem.

     

    You can use the below commands from an elevated command prompt to collect perfmon data from such a scenario.

     

    First create the data collector.  This command collects data from a variety of counters at a 5 minute interval and is designed to be run for several hours prior to and during a the time a system experiences poor performance (shorter intervals can be used for leaks that happen faster than several hours). We often recommend collecting these counters to perform general performance troubleshooting because we usually don’t know that there is a memory leak until after this data is collected and analyzed.

    Logman.exe create counter PerfLog-Long -o "c:\perflogs\\%computername%_PerfLog-Long.blg" -f bincirc -v mmddhhmm -max 300 -c "\LogicalDisk(*)\*" "\Memory\*" "\Cache\*" "\Network Interface(*)\*" "\Paging File(*)\*" "\PhysicalDisk(*)\*" "\Processor(*)\*" "\Processor Information(*)\*" "\Process(*)\*" "\Redirector\*" "\Server\*" "\System\*" "\Server Work Queues(*)\*" "\Terminal Services\*" –si 00:05:00

     

    Then start collecting data:

    Logman.exe start PerfLog-Long

     

    When the performance problem is being experienced, stop collecting data:

    Logman.exe stop PerfLog-Long

     

    After you have collected the data, open the .blg file in the Performance Monitor MMC snap-in.  Browse to the Memory object, and add the counters “Pool Nonpaged Bytes” and “Pool Paged Bytes”.  This should leave you with a view similar to the below screenshot.

     

    image001

     

    The steadily increasing line in the above screenshot, without a substantial decrease in the line, is an indicator that nonpaged pool memory is being leaked.  If we look at the maximum count we see that nonpaged pool has consumed 540MB.  The significance of this value depends on the amount of RAM in the system.  In this instance the system has 1GB of RAM so nonpaged pool is consuming 54% of the available memory.  We can now conclude that the cause of the performance problem is a nonpaged pool memory leak, which is consuming a large amount of RAM and preventing other components from using this RAM.

     

    Next we need to start investigating which driver has allocated the most pool.  We will begin that in part 2.

  • Ntdebugging Blog

    Challenges of Debugging Optimized x64 Code

    • 7 Comments

    If you have not had the luxury of debugging optimized x64 code as of yet, don’t wait much longer and fall behind the times!  Due to the x64 fastcall-like calling convention coupled with the abundance of general purpose registers, finding variable values at arbitrary points in a call stack can be very tricky indeed.

    In this article, I’d like to detail some of my favorite techniques for debugging optimized x64 code.  But before digging into these techniques, let’s first have a quick overview of the x64 calling convention.

    The x64 Calling Convention

    Those of you familiar with the fastcall calling convention on x86 platforms will recognize the similarities to the x64 calling convention.  Whereas you typically have to maintain knowledge of multiple calling conventions on x86 platforms, on x64 platforms there is currently just one.  (Of course, I’m excluding the case of no calling convention which one can achieve with __declspec(naked) or by coding in straight assembly.)

    I won’t go into all of the various nuances of the x64 calling convention, therefore I recommend you check out the following link (http://msdn.microsoft.com/en-us/library/ms794533.aspx).  But commonly, the first four parameters into a function are passed via the registers rcx, rdx, r8, and r9.  If the function accepts more than four parameters, those parameters are passed on the stack.  (Those of you familiar with the x86 fastcall calling convention where the first two parameters are passed in ecx and edx will recognize the similarities).

    To help illustrate how the x64 calling convention works, I have created some simple example code.  Although the code is contrived and far from real-world code, it demonstrates some scenarios that are likely to encounter in the real word.  The code is shown below.

    #include <stdlib.h>

    #include <stdio.h>

    #include <windows.h>

    __declspec(noinline)

    void

    FunctionWith4Params( int param1, int param2, int param3,

                         int param4 )

    {

        size_t lotsOfLocalVariables1 = rand();

        size_t lotsOfLocalVariables2 = rand();

        size_t lotsOfLocalVariables3 = rand();

        size_t lotsOfLocalVariables4 = rand();

        size_t lotsOfLocalVariables5 = rand();

        size_t lotsOfLocalVariables6 = rand();

        DebugBreak();

        printf( "Entering FunctionWith4Params( %X, %X, %X, %X )\n",

                param1, param2, param3, param4 );

        printf( "Local variables: %X, %X, %X, %X, %X, %X \n",

                lotsOfLocalVariables1, lotsOfLocalVariables2,

                lotsOfLocalVariables3, lotsOfLocalVariables4,

                lotsOfLocalVariables5, lotsOfLocalVariables6 );

    }

    __declspec(noinline)

    void

    FunctionWith5Params( int param1, int param2, int param3,

                         int param4, int param5 )

    {

        FunctionWith4Params( param5, param4, param3, param2 );

        FunctionWith4Params( rand(), rand(), rand(), rand() );

    }

    __declspec(noinline)

    void

    FunctionWith6Params( int param1, int param2, int param3,

                         int param4, int param5, int param6 )

    {

        size_t someLocalVariable1 = rand();

        size_t someLocalVariable2 = rand();

        printf( "Entering %s( %X, %X, %X, %X, %X, %X )\n",

                "FunctionWith6Params",

                param1, param2, param3, param4, param5, param6 );

        FunctionWith5Params( rand(), rand(), rand(),

                             param1, rand() );

        printf( "someLocalVariable1 = %X, someLocalVariable2 = %X\n",

                someLocalVariable1, someLocalVariable2 );

    }

    int

    main( int /*argc*/, TCHAR** /*argv*/ )

    {

        // I use the rand() function throughout this code to keep

        // the compiler from optimizing too much.  If I had used

        // constant values, the compiler would have optimized all

        // of these away.

        int params[] = { rand(), rand(), rand(),

                         rand(), rand(), rand() };

        FunctionWith6Params( params[0], params[1], params[2],

                             params[3], params[4], params[5] );

        return 0;

    }

     

    Cut and paste this code into a cpp file (such as example.cpp).  I used the Windows SDK (specifically the Windows SDK CMD Shell) to compile this code as C++ code by using the following command line:

    cl /EHa /Zi /Od /favor:INTEL64 example.cpp /link /debug

    Notice the /Od switch.  This disables all optimizations.  Later on, I’ll enable maximum optimization and that’s when the fun begins!

    Once you have the executable module built (mine is named example.exe), then you can fire it up in the debugger as follows:

    windbg -Q -c "bu example!main;g;" example.exe

    The command above will launch the application in windbg, set a breakpoint on the main() routine, and then go to that breakpoint.

    Now, let’s have a look at a diagram of what the stack looks like when FunctionWith6Params() gets called.  The diagram shown below illustrates the stack when the instruction pointer is at the beginning of the code for FunctionWith6Params() but before the prolog code has executed:

    CallStack1

    Notice that the caller, in this case main(), allocated enough space on the stack for all six parameters to FunctionWith6Params() even though the first four parameters are passed in via registers.  The extra space on the stack is commonly referred to as the “home space” for the register parameters.  In the previous diagram, I have shown those slots filled with xxxxxxxx to indicate that the values within there are virtually random at this point.  That’s because the caller, main(), does not initialize these slots.  The called function, at its discretion, may store the first four parameters in this space for safe keeping.  This is exactly what happens in non-optimized builds and is a huge debugging convenience since you can easily find the contents of the first four parameters on the stack if you need to.  Additionally, windbg stack commands such as kb and kv which show these first few parameters will report true results.

    With all of that said, here is what the stack looks like after the prolog code in FunctionWith6Params() executes:

    CallStack2

    The prolog assembly code for FunctionWith6Params() is shown below:

    0:000> uf .

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 28]:

       41 00000001`40015900 mov     dword ptr [rsp+20h],r9d
       41 00000001`40015905 mov     dword ptr [rsp+18h],r8d
       41 00000001`4001590a mov     dword ptr [rsp+10h],edx
       41 00000001`4001590e mov     dword ptr [rsp+8],ecx
       41 00000001`40015912 push    rbx
       41 00000001`40015913 push    rsi
       41 00000001`40015914 push    rdi
       41 00000001`40015915 sub     rsp,50h

    You can see that the first four instructions save the first four parameters on the stack in the home space allocated by main().  Then, the prolog code saves any non-volatile registers that FunctionWith6Params() plans to use during its execution.  The saved registers’ states are restored in the function epilog code prior to returning to the caller.  Finally the prolog code reserves some space on the stack, in this case, for 0x50 bytes.

    What is this space reserved on the top of the stack for?  First, space is created for any local variables.  In this case, FunctionWith6Params() has two.  However, those two local variables only account for 0x10 bytes.  What’s the deal with the rest of the space created on the top of the stack?

    On the x64 platform, when code prepares the stack for calling another function, it does not use push instructions to put the parameters on the stack as is commonly the case in x86 code.  Instead, the stack pointer typically remains fixed for a particular function.  The compiler looks at all of the functions the code in the current function calls, it finds the one with the maximum number of parameters, and then creates enough space on the stack to accommodate those parameters.  In this example, FunctionWith6Params() calls printf() passing it 8 parameters.  Since that is the called function with the maximum number of parameters, the compiler creates 8 slots on the stack.  The top four slots on the stack will then be the home space used by any functions FunctionWith6Params() calls.

    A handy side effect of the x64 calling convention is that once you are inside the bracket of the prolog and epilog of a function, the stack pointer does not change while the instruction pointer is in that function.  This eliminates the need for a base pointer which is common in x86 calling conventions.  When the code in FunctionWith6Params() prepares to call a child function, it simply puts the first four parameters into the required registers and, if there are more than 4 parameters, it uses mov instructions to place the remaining parameters in the allocated stack space but making sure to skip the first four parameter slots on the stack.

    Debugging Optimized x64 code (The Nightmare Begins)

    Why is debugging x64 optimized code so tricky?  Well, remember that home space that the caller creates on the stack for the callee to save the first four parameters?  It turns out that the calling convention does not require the callee to use that space!  And you can certainly bet that optimized x64 code will not use that space unless it is necessary and convenient for its optimization purposes.  Moreover, when optimized code does use the home space, it could use it to store non-volatile registers rather than the first four parameters to the function.

    Go ahead and recompile the example code using the following command line:

    cl /EHa /Zi /Ox /favor:INTEL64 example.cpp /link /debug

    Notice the use of the /Ox switch.  This turns on maximum optimization.  Debug symbols are still turned on so we can debug the optimized code easily.  Always build your release product with debug information turned on so you can debug your release builds!

    Let’s look at how the prolog assembly code for FunctionWith6Params() has changed:

       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    The optimized code is significantly different!  Let’s itemize the changes below:

    ·         The function uses the home space on the stack, however, it does not store the first four parameters there.  Instead it uses the space to store some non-volatile registers it must restore later in the epilog code.  This optimized code is going to make use of more processor registers, therefore it must save more of the non-volatile registers.

    ·         It still pushes three non-volatile registers onto the stack for safe keeping along with the other three it stored in the home space.

    ·         It then creates space on the stack.  However, it’s less space than in the non-optimized code, and is only 0x40 bytes.  That’s because the optimized code uses registers to represent the local variables someLocalVariable1 and someLocalVariable2.  Therefore, it only has to create space for the 8 slots needed to call the function with the maximum number of parameters, printf().

    ·         It then stores the first four parameters into non-volatile registers rather than in the home space. (Don’t count on this behavior.  An optimized function may make no copies of the contents of rcx, rdx, r8, and r9.  It all depends on the structure of the code)

    Now step through FunctionWith6Params() to the source line just after the first printf() call.  The output generated from the printf() call on my machine is as follows:

    Entering FunctionWith6Params( 29, 4823, 18BE, 6784, 4AE1, 3D6C )

    A common version of the stack command in windbg is kb, which also displays the first few parameters to each function in the frame.  In reality, it is displaying the first few positions of the stack.  The output for the kb command is as follows:

    0:000> kb
    RetAddr           : Args to Child                                                           : Call Site
    00000001`4001593b : 00000000`00004ae1 00000000`00004823 00000000`000018be 00000000`007e3570 : example!FunctionWith6Params+0x6a [c:\temp\blog_entry\sample_code\example.cpp @ 37]
    00000001`40001667 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000001 : example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 57]
    00000000`76d7495d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : example!__tmainCRTStartup+0x15b
    00000000`76f78791 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
    00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

    Notice that not all of the first four parameters of FunctionWith6Params() match what is shown by the kb command!  Of course, this is a side effect of the optimization.  You simply cannot trust the output displayed by kb and kv in optimized code.  This is the biggest reason why optimized x64 code is so difficult to debug.  Trust me when I say that it’s just pure luck that the second and third slots in the kb output above match the actual parameter values to FunctionWith6Params().  It’s because FunctionWith6Params() stores non-volatile registers in those slots and it just so happens that main() put those values in those non-volatile registers prior to calling FunctionWith6Params().

    Parameter Sleuthing -- Technique 1 (Down the Call Graph)

    Now, let’s look at some techniques for finding elusive function parameters to functions in the call stack while running x64 code.  I have placed a DebugBreak() call in FunctionWith4Params() to illustrate.  Go ahead and let the code run in windbg until it hits this breakpoint.  Now, imagine what you are looking at is actually not a live debugging scenario but rather a dump file from a customer of yours and this is the point where your application has crashed.  So, you take a look at the stack and it looks like the following:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Now, let’s say that in order for you to figure out what went wrong, you need to know the first parameter to FunctionWith6Params().  Assume you have not seen the first parameter in the console output. No fair cheating!

    The first technique I would like to illustrate involves digging downward into the call graph  to find out what has happened to the contents of rcx (the first parameter) after entering FunctionWith6Params().  In this case, since the parameters are 32bit integers, we’ll be attempting to follow the contents of ecx, which is the lower half of rcx.

    Let’s start by looking at the assembly code within FunctionWith6Params() starting from the beginning up to the call into FunctionWith5Params()::

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    FunctionWith6Params() copies ecx into r12d to preserve it for later use since the contents must be passed to multiple functions within the body of FunctionWith6Params().  Notice at the point where FunctionWith5Params() is called, the contents of ecx have been copied into both r12d and r9d, however, r9d is volatile so we must be careful with it since it could get overwritten prior to the next function call when FunctionWith5Params() calls FunctionWith4Params().  Armed with this information, let’s dig into the assembly code for FunctionWith5Params() that has executed up to this point:

    0:000> u example!FunctionWith5Params example!FunctionWith5Params+0x20
    example!FunctionWith5Params [c:\temp\blog_entry\sample_code\example.cpp @ 32]:
    00000001`40015880 mov     qword ptr [rsp+8],rbx
    00000001`40015885 mov     qword ptr [rsp+10h],rsi
    00000001`4001588a push    rdi
    00000001`4001588b sub     rsp,20h
    00000001`4001588f mov     ecx,dword ptr [rsp+50h]
    00000001`40015893 mov     eax,r9d
    00000001`40015896 mov     r9d,edx
    00000001`40015899 mov     edx,eax
    00000001`4001589b call    example!ILT+10(?FunctionWith4ParamsYAXHHHHZ) (00000001`4000100f)

    At the point where FunctionWith4Params() is called, the value we are after is now in eax, edx, and r12d.  Again, be careful with eax and edx as they are volatile.  However, since FunctionWith5Params() did not touch r12d, the contents of the parameter we are still after are still in r12d

    Now, let’s look at the code in FunctionWith4Params() that has executed so far:

    0:000> u example!FunctionWith4Params example!FunctionWith4Params+0x66
    example!FunctionWith4Params [c:\temp\blog_entry\sample_code\example.cpp @ 9]:
    00000001`400157b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400157b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400157ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400157bf 57              push    rdi
    00000001`400157c0 4154            push    r12
    00000001`400157c2 4155            push    r13
    00000001`400157c4 4156            push    r14
    00000001`400157c6 4157            push    r15
    00000001`400157c8 4883ec50        sub     rsp,50h
    00000001`400157cc 458be1          mov     r12d,r9d
    00000001`400157cf 458be8          mov     r13d,r8d
    00000001`400157d2 448bf2          mov     r14d,edx
    00000001`400157d5 448bf9          mov     r15d,ecx
    00000001`400157d8 e8afbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157dd 4898            cdqe
    00000001`400157df 4889442448      mov     qword ptr [rsp+48h],rax
    00000001`400157e4 e8a3bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157e9 4898            cdqe
    00000001`400157eb 4889442440      mov     qword ptr [rsp+40h],rax
    00000001`400157f0 e897bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157f5 4863e8          movsxd  rbp,eax
    00000001`400157f8 e88fbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157fd 4863f0          movsxd  rsi,eax
    00000001`40015800 e887bcfeff      call    example!rand (00000001`4000148c)
    00000001`40015805 4863f8          movsxd  rdi,eax
    00000001`40015808 e87fbcfeff      call    example!rand (00000001`4000148c)
    00000001`4001580d 4863d8          movsxd  rbx,eax
    00000001`40015810 ff15a24b0100    call    qword ptr [example!_imp_DebugBreak (00000001`4002a3b8)]

    We just found what we are looking for!  The red highlighted line shows r12 being saved on the stack because FunctionWith4Params() wants to reuse r12.  Since r12 is a non-volatile register, it must save the contents somewhere so it can restore the contents before the function exits.  All we have to do is locate that slot on the stack, and assuming that the stack has not been corrupted, we’ll have our prize.

    One technique for finding the slot is to start with the Child-SP value associated with the FunctionWith4Params() frame in the stack dump shown previously, which is 00000000`0012fdd0 in my build.  Using that value, let’s dump the stack content using the dps command:

    0:000> dps 00000000`0012fdd0 L10
    00000000`0012fdd0  00000001`00000001
    00000000`0012fdd8  00000001`40024040 example!_iob+0x30
    00000000`0012fde0  00000000`00000000
    00000000`0012fde8  00000001`40002f9e example!_getptd_noexit+0x76
    00000000`0012fdf0  00000000`00261310
    00000000`0012fdf8  00000001`40001a92 example!_unlock_file2+0x16
    00000000`0012fe00  00000000`00000001
    00000000`0012fe08  00000000`00004823
    00000000`0012fe10  00000000`000041bb
    00000000`0012fe18  00000000`00005af1
    00000000`0012fe20  00000000`00000000
    00000000`0012fe28  00000000`00000000
    00000000`0012fe30  00000000`00002cd6
    00000000`0012fe38  00000000`00000029
    00000000`0012fe40  00000000`00006952
    00000000`0012fe48  00000001`400158a0 example!FunctionWith5Params+0x20 [c:\temp\blog_entry\sample_code\example.cpp @ 34]

    I have highlighted the position that rsp points to when we enter FunctionWith4Params() in red.  Based on the prolog code shown for FunctionWith4Params() above, we can find the slot where our prize is stored.  I have highlighted it in green above and you can see the value on my machine is 0x29, which matches the value printf() sent to the console.  Additionally, I highlighted r14d in green in the assembly code for FunctionWith4Params() to indicate where the contents of edx (the second parameter) were copied to.  Since FunctionWith4Params() is virtually the top function on the stack (due to the fact that DebugBreak() takes no parameters), then r14d should also contain the value we are after.  Dumping the contents of r14 proves this as shown below:

    0:000> r r14
    r14=0000000000000029

    To sum up, when you are chasing register-passed parameter values down through a call graph, look for places where the value is copied into.  Specifically, if the value is copied into a non-volatile register, that can be a good thing.  If a downstream function wants to reuse that non-volatile register, it must first save the contents (usually on the stack) so it can restore it when it is done.  If you’re not that lucky, you may be able to trace a register it was copied into which has not been changed at the breakpoint.  Both conditions were shown above.

    Parameter Sleuthing -- Technique 2 (Up the Call Graph)

    The second technique I would like to demonstrate is very similar to the first technique except that we walk the stack/call-graph in the opposite direction as before, that is, up the call graph.  Unfortunately, none of these techniques are fool proof and guaranteed to bear fruit.  So, it’s nice to have multiple techniques to employ even though all of them may strike out.

    We know that when FunctionWith6Params() gets called, ecx contains the value we are after.  Therefore, if we look at the code for main(), maybe we can find the source from which the ecx register was filled prior to the function call.  Let’s have a look as the assembly code in main():

    0:000> u example!main example!main+0x5b
    example!main [c:\temp\blog_entry\sample_code\example.cpp @ 58]:
    00000001`400159b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400159b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400159ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400159bf 48897c2420      mov     qword ptr [rsp+20h],rdi
    00000001`400159c4 4154            push    r12
    00000001`400159c6 4883ec30        sub     rsp,30h
    00000001`400159ca e8bdbafeff      call    example!rand (00000001`4000148c)
    00000001`400159cf 448be0          mov     r12d,eax
    00000001`400159d2 e8b5bafeff      call    example!rand (00000001`4000148c)
    00000001`400159d7 8be8            mov     ebp,eax
    00000001`400159d9 e8aebafeff      call    example!rand (00000001`4000148c)
    00000001`400159de 8bf0            mov     esi,eax
    00000001`400159e0 e8a7bafeff      call    example!rand (00000001`4000148c)
    00000001`400159e5 8bf8            mov     edi,eax
    00000001`400159e7 e8a0bafeff      call    example!rand (00000001`4000148c)
    00000001`400159ec 8bd8            mov     ebx,eax
    00000001`400159ee e899bafeff      call    example!rand (00000001`4000148c)
    00000001`400159f3 448bcf          mov     r9d,edi
    00000001`400159f6 89442428        mov     dword ptr [rsp+28h],eax
    00000001`400159fa 448bc6          mov     r8d,esi
    00000001`400159fd 8bd5            mov     edx,ebp
    00000001`400159ff 418bcc          mov     ecx,r12d
    00000001`40015a02 895c2420        mov     dword ptr [rsp+20h],ebx
    00000001`40015a06 e8fab5feff      call    example!ILT+0(?FunctionWith6ParamsYAXHHHHHHZ) (00000001`40001005)

    We see that ecx was copied from the contents of r12d.  This is helpful since r12d is a non-volatile register, and if it is reused by a function further down the call stack, it must be preserved and that preservation usually means putting a copy on the stack.  It would have been nice if ecx were filled with a value from the stack, at which point we would be virtually done.  But in this case, we just need to start our journey back downwards again.

    We don’t have to look very far.  Let’s have another look at the prolog code for FunctionWith6Params():

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    r12 is reused in FunctionWith6Params(), which means that our prize will be on the stack.  Let’s start by looking at the Child-SP for this frame which is at 00000000`0012fe80 by using the dps command:

    0:000> dps 00000000`0012fe80 L10
    00000000`0012fe80  00000000`00001649
    00000000`0012fe88  00000000`00005f90
    00000000`0012fe90  00000000`00000029
    00000000`0012fe98  00000000`00004823
    00000000`0012fea0  00000000`00006952
    00000000`0012fea8  00000001`00006784
    00000000`0012feb0  00000000`00004ae1
    00000000`0012feb8  00000001`00003d6c
    00000000`0012fec0  00000000`00000000
    00000000`0012fec8  00000000`00000029
    00000000`0012fed0  00000000`00006784
    00000000`0012fed8  00000001`4000128b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 72]

    I have highlighted in red the slot rsp points to when we enter FunctionWith6Params().  At this point, it is a simple matter to walk the assembly code and find the slot where the value is stored.  I have highlighted it in green above.

    Parameter Sleuthing -- Technique 3 (Inspecting Dead Space)

    The final technique I would like to demonstrate involves a little more trickery and involves looking at “dead” or previously used slots on the stack that are not used by the current function call.  To demonstrate, let’s say that after the DebugBreak() is hit, we need to know what the contents of param4 that were passed to FunctionWith6Params().  Let’s have another look at the assembly that has executed for FunctionWith6Params() and this time, let’s follow r9d, the fourth parameter:

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    Notice that r9d is first moved into ebx.  But also, notice that it copied the contents into a slot on the stack at rsp+0x28.  What is this slot?  It’s the sixth parameter to the following printf() call.  Remember that the compiler looks at all of the functions the code calls and finds the function with the maximum number of parameters and then allocates enough space for that function.  As the code prepares to call printf(), it is moving the value we are after into the sixth parameter slot in that reserved stack space.  But what use is this information?

    If you examine FunctionWith6Params(), you see that every function called after printf() takes less than six parameters.  Specifically, the call to FunctionWith5Params() only uses five of those slots and just leaves the remaining three with junk in them.  This junk is actually our treasure!  From examining the code, it’s guaranteed that nobody has overwritten the slot represented by rsp+28.

    To find this slot, let’s again start by getting the Child-SP value for the frame we’re talking about as shown below:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    We can then take the highlighted value above and use the same offset in the code to find our value:

    0:000> dd 000000000012fe80+28 L1
    00000000`0012fea8  00006784

    As expected, the “dead” slot on the stack contains the value we are after.  You can compare the value to the output shown on the console to verify.

    A Non-volatile Register Shortcut

    Now that I have shown you the theory behind finding these elusive values passed around in registers, let me show you a shortcut that will make life a little bit easier.  The shortcut relies upon the /r option of the .frame command.  When using .frame /r, the debugger has the smarts to track non-volatile registers.  But as with any technique, always have multiple tools in your pocket in case you need to use all of them to verify a result.

    To demonstrate, let’s consider Technique 2 described previously where we look up the call graph and we want to know what r12 was prior to main() calling FunctionWith6Params().  Go ahead and re-launch the application in windbg and let it run until it hits the DebugBreak().  Now, let’s take a look at the stack including the frame numbers:

    0:000> knL
     # Child-SP          RetAddr           Call Site
    00 00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    01 00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    02 00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    03 00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b
    05 00000000`0012ff20 00000000`7748495d example!__tmainCRTStartup+0x15b
    06 00000000`0012ff60 00000000`775b8791 kernel32!BaseThreadInitThunk+0xd
    07 00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Based on our previous analysis of the assembly in main(), we know that the first parameter to FunctionWith6Params() was also stored in the non-volatile register r12 in main() prior to calling FunctionWith6Params().  Now, check out what we get when we use the .frame /r command to set the current frame to 4.

    0:000> .frame /r 4
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 70]
    rax=0000000000002ea6 rbx=0000000000004ae1 rcx=0000000000002ea6
    rdx=0000000000145460 rsi=00000000000018be rdi=0000000000006784
    rip=0000000140015a0b rsp=000000000012fee0 rbp=0000000000004823
     r8=000007fffffdc000  r9=0000000000001649 r10=0000000000000000
    r11=0000000000000246 r12=0000000000000029 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0         nv up ei pl nz na pe nc
    cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
    example!main+0x5b:
    00000001`40015a0b 488b5c2440      mov     rbx,qword ptr [rsp+40h] ss:00000000`0012ff20=0000000000000000

    As you can see, .frame /r shows the register contents as they were in main() prior to calling FunctionWith6Params().  Beware!  You can only trust the non-volatile registers when using this command!  Be sure to check out the following link to see which registers are considered volatile: Register Usage for x64 64-Bit.

    .frame /r can spare you the time spent manually digging around on the stack to find saved volatile registers.  In my experiments, .frame /r even works where there is no symbol information available.  However, it never hurts to know how to do it manually in case you’re faced with a situation where .frame /r breaks down.

    Conclusion

    The x64 calling convention and the abundance of general purpose registers in the processor bring many opportunities for optimization to the table.  However, when all of those optimizations are in play, they can certainly make debugging difficult.  After giving a brief overview of the x64 calling convention, I demonstrated three techniques one can use to find parameter values to various functions in the call stack.  I also showed you a shortcut you can use to see non-volatile registers for a particular frame in the call stack.  I hope you find these techniques useful in your debugging adventures.  Additionally, I urge you to become more familiar with all of the nuances of the x64 calling convention.

     

  • Ntdebugging Blog

    How Windows Shuts Down

    • 7 Comments

    Hi my name is Bryan,  I'm a escalation engineer on the Microsoft CPR platforms team.   A common problem scenario involves shutting down Windows. When troubleshooting problems during shut down we have to look at the Winlogon.exe process which can be tricky and must be done correctly.

     

    Troubleshooting Techniques

     

    Common Settings

     

    Settings that would affect how Windows shuts down are mostly in HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon, and are documented thoroughly at http://www.microsoft.com/technet/prodtechnol/windows2000serv/reskit/regentry/12314.mspx. The setting to really pay attention is:

     

    DisableCAD (REG_DWORD). When set to 1 the GINA will bypass the Ctrl-Alt-Del dialog and go straight to the logon prompt. The system cannot be shutdown when the logon prompt at the console is displayed.

     

    Another common setting that is sometimes needed for security reasons is in HKLM\SYSTEM\CurrentControlSet\Control\Session Manager\Memory Management.

     

    ClearPageFileAtShutdown (REG_DWORD). When set to 1 the memory manager will clear the paging file on shutdown. If the paging file is large this can significantly the time it takes for the system to shut down.

     

    Winlogon Event Notification

     

    Prior to Windows Vista/2008 Server, Winlogon Notification Packages can be used to reliably monitor the state of Winlogon. These are simple export DLLs that are registered with entry points for each event monitored by the package. Winlogon explicitly calls these entry points when a specific event occurs. Each package handles the notification within the context of the Winlogon process. Keep in mind that a bug in a notification package can cause problems in Winlogon and render the system inaccessible. You can find more information about Winlogon Notification Packages at http://msdn2.microsoft.com/en-us/library/aa380545.aspx.

     

    Starting with Windows Vista support for Winlogon Notification Packages has been pulled. Most of this functionality is still provided through SCM event notifications. See the following link for more information about this.

     

    http://technet2.microsoft.com/WindowsVista/en/library/6ec4ec6d-6b84-44c9-b3af-116589a42b861033.mspx?mfr=true

     

    You can find information about how to write a service here.

     

    http://msdn2.microsoft.com/en-us/library/ms685969.aspx

     

    However these notifications are performed asynchronously so the exact moment of each state within Winlogon cannot be reliably known.

     

    Winlogon Logging

     

    Winlogon logging is obtained by applying the checked build of Winlogon and setting the following registry values under HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon.

     

    DebugFlags (REG_SZ). This is a comma-separated list of debug flags to capture. The list of flags is Error, Warning, Trace, Init, Timeout, Sas, State, MPR, CoolSwitch, Profile, DebugLsa, DebugSpm, DebugMpr, DebugGo, Migrate, DebugServices, Setup, SC, Notify, and Job.

     

    LogFile (REG_SZ). This is the path to the log file where the events should be written. If this value is missing then the events are written to the debug port.

     

    These options can also be placed in the win.ini file. This option and other debug logging options for Winlogon can be found in these articles.

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;232575

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;221833

     

    Checked builds of Windows binaries are available through MSDN subscriptions. The checked binary applied to the system must match the service pack level of the system.

     

    When looking at the Winlogon logs there are three check points to identify. They are the three ExitWindowsEx calls made during shutdown. These log entries were made during a shutdown initiated with “shutdown –r –f –t 0”.

     

    328.372> Winlogon-Trace: Doing remote-initiated (Administrator) Reboot=true, Force=true

    328.372> Winlogon-Trace: Starting user thread for Logoff, flags = 3807

    328.764> Winlogon-Trace: Doing immediate shutdown, LastGinaRet = b, Flags = 3804

    328.764> Winlogon-Trace: Calling ExitWindowsEx(0x3804, 0)

    .

    .

    .

    328.1528> Winlogon-Trace: ExitWindowsEx called to shut down COM processes

    .

    .

    .

    328.332> Winlogon-Trace: Starting shutdown

    328.332> Winlogon-Trace: Starting user thread for Logoff, flags = 7

    .

    .

    .

    328.284> Winlogon-Trace: Calling ExitWindowsEx(0x7, 0)

     

    If shutdown stalls then based on the log entries you should be able to identify which part of shutdown it is stuck in.

     

    Debugging

     

    In order to debug Winlogon you will need to first install the debugging tools for Windows (http://www.microsoft.com/whdc/devtools/debugging/default.mspx). It contains information about how to set up the debugger for Winlogon debugging. If the debugger is not set up correctly on Winlogon the system can easily get in an unusable state and the system will need to be reinstalled.

     

    You should debug Winlogon whenever a problem manifests itself on the Winlogon desktop where the SAS and logon prompt dialogs are displayed. When debugging Winlogon you should start by looking at the main process thread. If shutdown (or any other Winlogon activity) is hung that thread will show what happened to prevent shutdown from completing. Also look at these Winlogon flags which provide some indication of whether or not the main thread is even processing a shutdown.

     

    0105fe8c winlogon!g_fReadyForShutdown

    0105fdf8 winlogon!ShutdownHasBegun

    01062b3c winlogon!ShutdownInProgress

    01062b30 winlogon!ShutdownTime

     

    I will point out how these variables are modified.

     

    Shutdown Sequence of Events

     

    If you are debugging a shutdown issue you first need to understand the sequence of events that take place during shutdown. This will help isolate what activity may be failing.

     

    RPC Call

     

    An application, local or remote, tells Windows to shut down by calling the Win32 API InitiateSystemShutdownEx (http://msdn2.microsoft.com/en-us/library/aa376874.aspx). This API creates an RPC call over the named pipe InitShutdown. The remote connect and RPC call looks like this in a network trace.

     

    11:08:40.025                 CLIENT         SERVER        SMB              SMB: C; Nt Create Andx, FileName = \InitShutdown

    11:08:40.027                 CLIENT         SERVER        MSRPC        MSRPC: c/o Request: unknown Call=0x1 Opnum=0x2 Context=0x0 Hint=0x20

     

    A local connect would not need to go over the network, but it uses the same mechanism to make this call.

     

    The server side of this RPC call is handled by the function BaseInitiateShutdownEx in the Winlogon.exe process. This RPC worker performs the following actions.

     

    1.       Checks the privilege level of the client. If the client privilege test fails then the error status code is returned. This will typically be ERROR_ACCESS_DENIED (0x5).

    2.       Parses the shutdown command sent by the RPC client. If the command is malformed then the status error code of ERROR_INVALID_PARAMETER (0x57) is returned.

    3.       Checks the Winlogon flags ShutdownInProgress, ShutdownHasBegun, g_fReadyForShutdown, and the current state of the terminal desktop to see if we can shutdown. Winlogon cannot begin the shutdown if a shutdown is in progress or if it is not ready. Winlogon also will not start a shutdown if the force flag was not specified in the command and the desktop is locked. If the ShutdownInProgress or ShutdownHasBegun flag is set then the return value is ERROR_SHUTDOWN_IN_PROGRESS (0x45B). If the g_fReadyForShutdown is not set then the return value is ERROR_NOT_READY (0x15).

     

    Debugger output:

    dd winlogon!g_fReadyForShutdown l 1

    0105fe8c  00000001

     

    dd winlogon!ShutdownInProgress l 1

    01062b3c  00000000

     

    dd winlogon!ShutdownHasBegun l 1

    0105fdf8  00000000

     

    4.       Winlogon initializes the shutdown data including the global variable ShutdownTime. If this variable has been set then we know we’ve gotten this far.

     

    Debugger Output:

    dq winlogon!ShutdownTime l 1

    01062b30  01c7a859`baee0060

     

    .formats 01c7a859`baee0060

    Evaluate expression:

      Time:    Wed Jun  6 12:42:54.506 2007 (GMT-4)

     

    5.       If Winlogon has determined that it can proceed then the ShutdownInProgress flag is set. Subsequent shutdown requests from this point will fail in step 3 when it checks this flag.

    6.       Generates the shutdown audit event if auditing was enabled. Note that shutdown may fail at some point after this even though the audit log is generated.

    7.       Creates another thread to continue working on the shutdown. At this point the RPC worker thread returns to the caller.

     

    To this point there has been no visible indication on the server being shutdown. If the RPC worker fails for some reason then the client application will get an indication of the failure. If the RPC worker successfully hands the shutdown request to the next thread then the client application will get ERROR_SUCCESS (0) as the return code. The client application will get no indication of a failure after that point.

     

    Worker Thread

     

    The RPC worker thread hands control to the LogoffThreadProc thread. If the delay specified in the shutdown command was 0 then the ShutdownInProgress flag is cleared and the ShutdownHasBegun is set. In the Winlogon log you will see a line that starts with “Doing immediate shutdown”. Otherwise you will not see any visible indication at this point that a shutdown is occurring.

     

    If the delay specified in the shutdown command was greater than 0 then the countdown shutdown dialog is displayed.

     

    Shutdown

     

    When that dialog completes the AbortShutdown flag is checked. This flag would get set as a result of a call to AbortSystemShutdown (http://msdn2.microsoft.com/en-us/library/aa376630.aspx). If it is set then the shutdown is aborted. Otherwise the ShutdownInProgress flag is cleared, the ShutdownHasBegun flag is set and if the shutdown was initiated by a system process then we shut the system down immediately at this point with no further clean up.

     

    After these flags are updated the ExitWindowsInProgress flag is set and we call the Win32 API ExitWindowsEx (http://msdn2.microsoft.com/en-us/library/ms893047.aspx). In the Winlogon log you will see a line that starts with “Calling ExitWindowsEx”.

     

    Debugger Output:

    dd winlogon!ExitWindowsInProgress l 1

    0105fd84  00000001

     

    The Win32 API ExitWindowsEx makes an RPC call to CSRSS.EXE. CSRSS synchronously sends a WM_QUERYENDSESSION message to all Windows applications. When an application gets this message it indicates that shutdown can continue and CSRSS then sends the WM_ENDSESSION message. After that the process is terminated. If the application indicates that it cannot be terminated then CSRSS stops processing any further applications and waits for the interactive user to close the application. The ExitWindowsEx call will fail with error ERROR_OPERATION_ABORTED (0x3E3) and the Winlogon flags are reset so that a new shutdown request can be processed.

     

    An application that prevents shutdown from proceeding in this manner can be seen visual since it will be the foreground window on the desktop. To confirm which application returned did this you will need to live debug CSRSS. A return code of 3 from either winsrv!ConsoleClientShutdown or winsrv!UserClientShutdown will indicate the application did this.

     

    Debugger Output:

    0:002> pc

    eax=00000000 ebx=7c81a3ab ecx=7ffdb000 edx=75a58ca0 esi=75a58ca0 edi=00164600

    eip=75a564de esp=0052fe40 ebp=0052fe68 iopl=0         nv up ei pl zr na po nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246

    CSRSRV!CsrShutdownProcesses+7e:

    75a564de ff5740 call dword ptr [edi+0x40]{winsrv!UserClientShutdown (75a9db1f)} ds:0023:00164640=75a9db1f

     

    ; Step past the call.

    0:002> p

    eax=00000003 ebx=7c81a3ab ecx=7ffdb000 edx=75a58ca0 esi=75a58ca0 edi=00164600

    eip=75a564e1 esp=0052fe4c ebp=0052fe68 iopl=0         nv up ei pl zr na po nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246

    CSRSRV!CsrShutdownProcesses+81:

    75a564e1 8bf8             mov     edi,eax

     

    ; The first parameter is a structure that contains the process ID.

    75a564d5 ff75f4           push    dword ptr [ebp-0xc]

    75a564d8 ff750c           push    dword ptr [ebp+0xc]

    75a564db ff75f8           push    dword ptr [ebp-0x8]

    75a564de ff5740           call    dword ptr [edi+0x40]

     

    ; Get the pointer to this structure.

    0:002> dd ebp-8 l 1

    dd ebp-8 l 1

    0052fe60  0018a530

     

    ; The first DWORD is the process ID. The second DWORD is the thread ID.

    0:002> dd 0018a530 l 1

    dd 0018a530

    0018a530  0000066c

     

    ; Break into kernel mode so we can look at all the processes.

    0:002> .breakin

    .breakin

    Break instruction exception - code 80000003 (first chance)

    nt!RtlpBreakWithStatusInstruction:

    8081db0e cc              int     3

     

    ; Get the process object with that process ID.

    kd> !process 0000066c 0

    Searching for Process with Cid == 66c

    PROCESS ff62a638  SessionId: 0  Cid: 066c    Peb: 7ffdf000  ParentCid: 0108

        DirBase: 0390d000  ObjectTable: e1658e38  HandleCount:  51.

        Image: test.exe

     

    Console (text-based) applications are asynchronously sent a separate CTRL_SHUTDOWN_EVENT notification. This means that ExitWindowsEx will proceed no matter how the application chooses to handle this notification.

     

    Services.exe (and all Windows services) is a console application which receives this notification from CSRSS. Services.exe registers a control handler ScShutdownNotificationRoutine which calls ScShutdownAllServices on shutdown. This function traverses through all Windows services that are not stopped or stopping and that accept the shutdown notification and sends them the SERVICE_CONTROL_SHUTDOWN notification. Each service has 20 seconds by default to shutdown. However a service may request more time by calling SetServiceStatus with a wait hint and updated check point. It can do this so long as it continues to respond within the current timeout period. However since Services.exe received this as an asynchronous message from CSRSS.EXE it will not prevent the system from shutting down.

     

    After ExitWindowsEx returns control to Winlogon the ExitWindowsInProgress flag is cleared and LogoffThreadProc exits.

     

    MainLoop

     

    The state of Winlogon is controlled by the main process thread in a function called MainLoop. As LogoffThreadProc sets the ShutdownHasBegun flag and calls ExitWindowsEx the MainLoop function picks up on this change of state and begins executing its shutdown code. Since MainLoop is responsible for interaction with the user this is the first place where the user will get visible confirmation from Winlogon that the system is shutting down.

     

    When MainLoop sees that the Winlogon state has changed to shutting down it takes the following actions.

     

    1.       Signal the shell that we are shutting down. This causes the Explorer shell to disappear.

    2.       Checks to see if there are any updates to the user’s profile.

    3.       Send out the logoff notification event.

    4.       Delete network connections.

    5.       Play the logoff sound.

    6.       Play the system exit sound.

    7.       Creates a KillComProcesses thread. This calls ExitWindowsEx and will wait up to 15 minutes for this to complete.

    8.       Save and unload the user’s profile.

    9.       Delete RAS connections.

    10.    Send out the shutdown notification event.

    11.    Stop Windows file protection.

    12.    Creates another LogoffThreadProc thread which again calls ExitWindowsEx.

    13.    Call the shutdown function in the GINA. This displays the Windows is shutting down dialog.

    14.    Wait for any remaining system processes to complete. If we are stuck here then we would need to look at System, smss.exe, or csrss.exe. One of those will be stuck in some action.

    15.    Shut down the system.

     

    Winlogon uses the native API NtShutdownSystem in step 15. If there is a hang after this point then you will see the main thread in Winlogon stuck in this call and the real problem is likely the result of a device driver in the System process. This call will never return.

Page 4 of 24 (235 items) «23456»