• Ntdebugging Blog

    How Windows Starts Up (Part the second)

    • 7 Comments

    Howdy folks, David here again with part two of How Windows Starts Up.  Today we’ll be covering the Boot Loader Phase.  Let’s take a moment to recap where we are at this point.  So far, the computer has completed POST, executed the MBR code, located the active partition, executed the Boot Sector code in that partition, found NTLDR and loaded it into memory.  So what happens next?  During this phase, we’ll be discussing the following files located in the root of your system volume:  NTLDR, ntdetect.com and boot.ini.

     

    The Boot Loader Phase begins when NTLDR executes:

     

    1.    NTLDR switches the processor from real mode to 32-bit flat memory mode.

    How does it do this you ask?  NTLDR contains two parts – a 16-bit component which handles switching the processor to Protected Mode and a 32-bit component which handles everything else. 

     

    When NTLDR first begins execution, the processor is in an x86-operating mode called Real-Mode.  In Real-Mode, no virtual to physical translation of memory addresses occurs, which means that all memory addresses use the 16-bit Segment:Offset format, and only the first 1MB of the computer's physical memory is accessible.  However, we don’t have to concern ourselves with this too much because the first action NTLDR takes is to switch the CPU to Protected-Mode. 

     

    *Trivia Alert*  before we enter Protected-Mode, we enable the A20 Line – you IBM guys know what I’m talking about… 

     

    Still no virtual-to-physical translation occurs at this point in the boot process, but a full 32 bits of memory addressing becomes accessible, and now NTLDR can access up to 4GB of physical memory. 

     

    2.    NTLDR creates enough page tables to make memory below 16MB accessible with paging turned on.  This number has been increased with Windows Server 2003. 

     

    3.    NTLDR enables paging.  “Protected-Mode with Paging Enabled” is the mode in which Windows executes during normal operation.

     

    4.    NTLDR then starts the FAT and NTFS mini file system drivers contained within its own code.  Unlike the Boot Sector's file system code, NTLDR's code is sophisticated enough to read subdirectories.

     

    Note:   All disk access from this point until the Kernel Phase begins uses BIOS Interrupt 13h, Extended Interrupt 13h or NTBOOTDD.SYS

     

    5.    NTLDR locates and parses Hiberfil.sys to determine if it contains a valid hibernator file.  If a valid hibernator file is found, then that file is loaded into memory and execution continues from the point the computer was placed into hibernation.

     

    Hibernation files are interesting.  The file either contains a full memory image, or it contains a pointer (ARC path) to the boot partition of the last operating system that entered hibernation.  That boot partition will contain another Hiberfil.sys file, which contains a full memory image of the hibernating operating system.  If the Hiberfil.sys file is a pointer, the file will contain an ARC path using one of the following syntaxes:

     

                             - linkmulti()disk()rdisk()partition()

                             - linksignature()disk()rdisk()partition()

                             - linkscsi()disk()rdisk()partition()

     

    6.    If Hiberfil.sys is not found, NTLDR parses the Boot.ini file.  If the Boot.ini contains a reference to more than one operating system or boot option, then the boot loader screen is displayed. 

     

    This is a sample of a default Boot.ini file from a Windows 2000 Server-based computer:

     

    [boot loader]

    timeout=30

    default=multi(0)disk(0)rdisk(0)partition(1)\WINNT

    [operating systems]

    multi(0)disk(0)rdisk(0)partition(1)\WINNT="Windows 2000 Server" /fastdetect

     

    Let’s talk a bit about what’s in the Boot.ini file.  Boot.ini contains a list of ARC paths.  Ok, quick – five bonus points to the first person who can tell me what ‘ARC’ stands for…  come on…  Yes, you there in the red shirt… correct!  It stands for ‘Advanced RISC Computing’; now beam down with the captain.  The rest of you come with me…

     

    ARC paths may use the “Multi”, “SCSI” or “Signature” syntax.

     

    The “Multi” syntax instructs Windows to rely on the system BIOS to load system files.  This means that NTLDR will be using INT13 BIOS calls to find and load NTOSKRNL and any other files on the boot partition.

     

    The “SCSI” syntax tells Windows to load a SCSI device driver to access the boot partition.  A copy of the driver must be renamed to NTBOOTDD.SYS and placed in the root of the system partition.

     

    The “Signature” syntax is equivalent to the SCSI syntax, but is used instead to support the Plug and Play architecture in Windows 2000 or later.  Because Windows 2000 is a PnP OS, the SCSI controller number instance might vary each time you start Windows 2000, especially if you add new SCSI controller hardware after setup.

     

    The Signature syntax instructs NTLDR to locate the drive with a disk signature that matches the value in the parentheses, regardless of which SCSI controller number that the drive is connected to.  Keep in mind that the Signature syntax also requires the presence of an Ntbootdd.sys file in the root of the system partition.  If you recall from the previous post, the disk signature value is located in the MBR.

     

    Example:

    signature(8b467c12)disk(1)rdisk(0)partition(2)\winnt="Windows 2000"

     

          Signature() syntax is used only if one of the following conditions exists:

     

    ·         The System BIOS or controller hosting the boot partition on which Windows is installed, does not support INT13 Extensions, or has the INT13 Extensions option disabled, and the partition on which you installed Windows is either larger than ~7.8 gigabytes (GB) in size, or the ending cylinder number for that partition is higher than 1024.

    ·         The drive on which you installed Windows is connected to a SCSI controller with SCSI BIOS disabled, so INT13 BIOS calls cannot be used during the boot process.

     

                            227704 Windows May Use Signature() Syntax in the Boot.ini File

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

     

    7.    If Boot.ini is not found, NTLDR attempts to continue the boot process by assuming that Windows was installed in the default location on the same partition (c:\windows).  If the c:\windows directory is not found, NTLDR displays this error message:  Windows could not start because the following file is missing or corrupt: \winnt root\system32\ntoskrnl.exe

     

    8.    If the boot loader screen is displayed, the user must select an operating system to boot.

    a.    If the user chooses to run an operating system other than Windows 2003/XP such as DOS or Windows 95/98, NTLDR loads and executes the Bootsect.dos file located in the root of the boot drive.

    (1)  If the Bootsect.dos file is found, NTLDR loads it into RAM and then passes control to it.

    (2)  Bootsect.dos then loads IO.sys, MSDOS.sys, Command.com, etc., as necessary and proceeds to boot the downlevel operating system.

    (3)  If the file is not found in the root, NTLDR displays:

    I/O Error accessing boot sector file multi(0)disk(0)rdisk(0)partition(1): \bootsect.dos

    b.    If the user selects a Windows NT-based operating system, NTLDR executes Ntdetect.com.

    (1)  If the ARC path points to a hard drive or partition that is not on the system, the following is displayed:

    Windows could not start because of a computer disk hardware configuration problem.  Could not read from the selected boot disk.  Check boot path and disk hardware.  Please check the Windows documentation about hardware disk configuration and your hardware reference manuals for additional information.

    (2)  The above message may also be displayed if you are using Signature() ARC path notation and the disk signature in the MBR is overwritten (for example, by a virus) or changed (corrupted) so that it no longer matches the Signature() value in the Boot.ini file.  The following error message may also be displayed when there are problems with the Signature () value:

    Windows could not start because of the following ARC firmware boot configuration problem: did not properly generate ARC name for HAL and system paths. Please check the Windows documentation about ARC configuration options and your hardware reference manuals for additional information.

     

    9.    Ntdetect.com initializes and detects all supported hardware that it can find.  (Troubleshooting tip:  There is an Ntdetect.chk on the Windows Resource Kit CD in the Debug.cab file, which can be renamed and used in place of Ntdetect.com to view what Ntdetect.com is detecting during startup.  You know you want to – go ahead, I’ll wait…)

     

    Ntdetect.com detects the following components:

     

    a)    Computer ID

    b)    Bus/adapter type

    c)    Video adapter

    d)    Keyboard

    e)    Communications ports

    f)     Floppy disks

    g)    Mouse or other pointing devices

    h)    Parallel ports

     

    10.  Ntdetect.com passes its list of hardware components to NTLDR.

     

    11.  If the /SOS switch was used in the Boot.ini for the OS that is loading, NTLDR will display the files it loads into memory from this point on.  Keep in mind – none of these files are being initialized.  They are just being loaded into RAM at this point.  I can’t tell you how many times someone has incorrectly concluded that there is a problem with MUP.SYS because it’s the last file displayed on this screen before their computer hangs.  Poor MUP – always getting a bad rap.  This list can be useful, however; it can help you identify potential malware that may be loading.

     

    12.  NTLDR loads Ntoskrnl.exe and Hal.dll into memory.  Again, *loading*, not initializing.

     

    13.  NTLDR loads the System registry hive into memory.  If Windows cannot load the registry hive, it may be necessary to restore the System hive from the ERD or by using the Windows Recovery Console to copy the files from the Windows\Repair or Windows\Repair\RegBack folder.

     

    14.  NTLDR reads the HKLM\System\Select registry key.

    a.    If the Last Known Good option was not selected, NTLDR looks for the “Default” value in the SELECT key to select which ControlSet to use.  (0x1 = ControlSet001, 0x2 = ContolSet002, 0x3 = ControlSet003) 

    b.    If the Last Known Good option was selected, NTLDR looks for the “LastKnownGood” value in the SELECT key to select the ControlSet to use.

     

    15.  NTLDR sets the “Current” value in the HKLM\System\Select key to the ControlSet being used.

     

    Note:  At this point, NTLDR has determined which ControlSet it needs to use, but we don’t actually create the “CurrentControlSet” symbolic link until the kernel initializes (more on that in our next installment).  Therefore, for the purposes of this discussion, I’ll use *ActiveControlSet* to refer to whichever registry ControlSet has been identified as the one NTLDR needs to use.

     

    16.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\Nls\Codepage for the “Acp”, “Oemcp”, and “Oemhal” values.  These entries are pointers to the table of codepage information stored in the same key.  The table has the filenames that correspond to the codepage numbers.  NTLDR loads these files into memory.  The defaults are C_1252.nls, C_437.nls, and Vgaoem.fon.

     

    A code page is a character set specific to an operating system or hardware platform.  It maps character codes to individual characters.  Different code pages include different special characters, typically customized for a language or a group of languages.  The system uses code pages to translate keyboard input into character values for non-Unicode based applications, and to translate character values into characters for non-Unicode based output displays.

     

    17.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\Nls\Language for the “Default” value.  This entry is a pointer to the table of language information stored in the same key.  NTLDR loads this file into memory.  The default is L_intl.nls.

     

    18.  NTLDR scans HKLM\System\*ActiveControlSet*\Services for device drivers with a “Start” value of 0x0.  It finds their “Group” and “Tag” values also.

     

    19.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\ServiceGroupOrder for the order that service groups should be loaded.

     

    20.  NTLDR sorts the drivers by “Group” and then by their “Tag” value.  Each service or driver has a particular group to which it belongs.  All drivers within a specific group are ordered by tag. 

     

    21.  NTLDR loads the 0x0 device drivers into memory.  It does not initialize or start these drivers.

     

    22.  The board is set, and the pieces are moving.  NTLDR executes Ntoskrnl.exe.

     

    Troubleshooting the Boot Loader Phase

     

    Okay, now that we’ve seen what is supposed to happen, what could possibly go wrong?  Well, several things…

     

    First, all file-system activity during this phase uses BIOS Int13, Extended Int13 or Ntbootdd.sys. 

     

    1.    If your computer uses Extended Int 13, verify that Ext. Int13 is enabled in your system’s BIOS or SCSI BIOS as appropriate.

     

    2.    If you are using a SCSI driver, verify that you are using the correct SCSI driver (Ntbootdd.sys).  If you are using "SCSI()" syntax in the Boot.ini file, copy the correct device driver for the SCSI controller to the root and then rename it to Ntbootdd.sys.  This is the driver that is stored in the Winnt.sbs\System32\Drivers folder (for example, the Aic78xx.sys file).  If you use "MULTI()" syntax in the Boot.ini file, you do not need to do this.  Use the Windows Recovery Console or a Windows NT boot floppy to complete this step.

     

                301680 HOW TO: Create a Boot Disk for an NTFS or FAT Partition

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

     

    307654 How to install and use the Recovery Console in Windows XP

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

     

     

    Significant Errors during this phase:

     

    ·         Windows could not start because of a computer disk hardware configuration problem.  Could not read from the selected boot disk.  Check boot path and disk hardware.  Please check the Windows documentation about hardware disk configuration and your hardware reference manuals for additional information.

     

    This error indicates that the ARC path is pointing to a hard drive or partition that is not on the system.  This message may also be displayed if you are using Signature() ARC path notation and the disk signature in the MBR is overwritten (for example, by a virus) or changed (corrupted) so that it no longer matches the Signature() value in the Boot.ini file. 

     

    ·         Windows could not start because of the following ARC firmware boot configuration problem: did not properly generate ARC name for HAL and system paths. Please check the Windows documentation about ARC configuration options and your hardware reference manuals for additional information.

     

    This error message may be displayed when there are problems with the Signature () ARC path syntax.

     

    Ntoskrnl.exe missing or corrupt.  This error could be the result of an incorrect ARC path in the Boot.ini file.  Use the information in the following knowledge base articles to correct the Boot.ini information.

     

                102873 BOOT.INI and ARC Path Naming Conventions and Usage

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

     

                155222 How to Determine the ARC Path

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

     

                130921 Creating an FT Boot Disk With Scsi( ) and Multi( ) Identifiers

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

     

    It is also possible to use the Windows XP Recovery Console to create a new Boot.ini for a Windows NT, Windows 2000 or .NET installation.  Please see the following knowledge base article for a description of this process:

     

                291980 A Discussion About the Bootcfg Command and Its Uses

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

     

    Specify the /SOS switch in the Boot.ini file and monitor the output to the screen.  If the system stops responding before anything is output to the screen, then the problem may be with hardware detection.  Replace Ntdetect.com with Ntdetect.chk to view the hardware detected by the system during this phase.

     

                103659 Setup Hangs While Inspecting Hardware; How to Use Ntdetect.com

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

     

                320040 HOW TO: Use Ntdetect.chk to Identify Hardware Problems

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

     

     

    Incorrect HAL

    If after specifying the /SOS option, you see that an incorrect version of the HAL.DLL is loading, use the following KB articles to replace the HAL or troubleshoot other HAL-related issues:

     

                314477 "Hardware Configuration Problem" Err Msg Starting Windows

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

     

                237556 Troubleshooting Windows 2000 Hardware Abstraction Layer Issues

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

     

    330184  "Invalid Boot.ini" or "Windows could not start" error messages

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

     

     

    Unable to load System hive

    Several problems could happen here.  First, consider that the amount of memory we’re dealing with is only 16MB.  We have to squeeze NTLDR, the System Registry Hive, the kernel, the HAL, all the boot drivers and the PFN database into a relatively small area.  So, with Windows Server 2003, we’ve given ourselves a bit more room. 

     

                302594 The System hive memory limitation is improved in Windows Server 2003

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

     

    If Windows is unable to load the System registry hive into memory, then it may be necessary to restore the System hive from the ERD or use the Windows Recovery Console to copy the files from the Winnt\Repair or Winnt\Repair\RegBack folder whichever version is most recent.

     

                307545 How to Recover from a Corrupted Registry

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

     

     

    Table of Startup Type Values

    HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services

    0x0 = Boot

    Loaded into RAM by the Boot loader (NTLDR) during Boot Loader Phase, then initialized by the Kernel (NTOSKRNL) during Kernel Phase

    0x1 = System

    Loaded and initialized by the Kernel during Kernel Phase

    0x2 = Auto

    Loaded or started automatically at system startup

    0x3 = Manual

    Driver is manually started by the user or another process

    0x4 = Disabled

    Driver is not to be started (There are exceptions, such as NTFS)

     

     

    Conclusion

    Well folks, we certainly have covered a lot of ground so far.  Any questions?  Yes, you there in the front…  Ah, why have we not discussed any blue screens?  Very good question.  We haven’t seen any BSOD’s up to this point in the boot sequence because the kernel isn’t running yet and STOP errors are generated by the kernel.  No kernel, no blue screens. 

     

    That’s all the time we have this week boys & girls.  Join us next time for How Windows Starts Up, The Kernel Phase.

     

  • Ntdebugging Blog

    How the Clipboard Works, Part 2

    • 1 Comments

    Last time, we discussed how applications place data on the clipboard, and how to access that data using the debugger. Today, we'll take a look at how an application can monitor the clipboard for changes.  Understanding this is important because it is a place where Windows allows 3rd-party code to "hook" into the system.  If you experience unexpected behavior with copying and pasting, a program using these hooks may be misbehaving.  We’ll start by covering the hooking mechanisms for clipboard, and then review how to identify what applications, if any, are using these hooks in the debugger.

     

    There are three ways to monitor the clipboard for changes - clipboard viewers, clipboard format listeners, and querying the clipboard sequence number.  We will focus on the first two as these allow an application to register for notifications whenever the clipboard is updated.  The third method simply allows an application to check and see if a change has occurred, and should not be used in a polling loop.

     

    The Clipboard Viewer functionality has been around since Windows 2000, if not earlier.  The way it works is pretty simple - an application interested in receiving clipboard change notifications calls SetClipboardViewer and passes a handle to its window.  Windows then stores that handle in a per-session win32k global, and anytime the clipboard is changed Windows sends a WM_DRAWCLIPBOARD message to the registered window.

     

    Of course, multiple applications are allowed to register their windows as clipboard viewers - so how does Windows handle that?  Well, if an application calls SetClipboardViewer and another clipboard viewer was already registered, Windows returns the handle value of the previous viewer's window to the new viewer.  It is then the responsibility of the new viewer to call SendMessage every time it receives a WM_DRAWCLIPBOARD to notify the next viewer in the chain. Each clipboard viewer also needs to handle the WM_CHANGECBCHAIN message, which notifies  all viewers when one of the viewers in the chain is removed, and specifies what the next viewer in the chain is.  This allows the chain to be maintained.

     

    An obvious problem with this design is it relies on each clipboard viewer application to behave correctly, not to terminate unexpectedly, and to generally be a good citizen.  If any viewer decided not to be friendly, it could simply skip notifying the next viewer in line about an update, rendering the next viewer and all subsequent viewers impotent.

     

    To address these problems, the Clipboard Format Listener mechanism was added in Windows Vista. This works in much the same way as the clipboard viewer functionality except in this case Windows maintains the list of listeners, instead of depending on each application to preserve a chain.

     

    If an application wishes to become a clipboard format listener,it calls the AddClipboardFormatListener function and passes in a handle to its window. After that, its window message handler will receive WM_CLIPBOARDUPDATE messages.  When the application is ready to exit or no longer wishes to receive notifications, it can call RemoveClipboardFormatListener.

     

    Now that we've covered the ways to register a viewer/listener, let's take a look at how to identify them using the debugger.  First, you'll need to identify a process in the session you are interested in checking for clipboard monitors.  It can be any win32 process in that session -we just need to use it to locate a pointer to the Window Station.  In this case, I'll use the Notepad window I used in part 1: 

    kd> !process 0 0 notepad.exe

    PROCESS fffff980366ecb30

        SessionId: 1  Cid: 0374   Peb: 7fffffd8000  ParentCid: 0814

        DirBase: 1867e000  ObjectTable: fffff9803d28ef90  HandleCount: 52.

        Image: notepad.exe

     

    If you are doing this in a live kernel debug, you'll need to change context into the process interactively (using .process /I< address> then hit g and wait for the debugger to break back in).  Now DT the process address as an _EPROCESS and look for the Win32Process field: 

    kd> dt _EPROCESS fffff980366ecb30 Win32Process

    nt!_EPROCESS

       +0x258 Win32Process : 0xfffff900`c18c0ce0 Void

     

    Now DT the Win32Process address as a win32k!tagPROCESSINFO and identify the rpwinsta value: 

    kd> dt win32k!tagPROCESSINFO 0xfffff900`c18c0ce0 rpwinsta

       +0x258 rpwinsta : 0xfffff980`0be2af60 tagWINDOWSTATION

     

    This is our Window Station. Dump it using dt: 

    kd> dt 0xfffff980`0be2af60 tagWINDOWSTATION

    win32k!tagWINDOWSTATION

       +0x000 dwSessionId      : 1

       +0x008 rpwinstaNext     : (null)

       +0x010 rpdeskList       : 0xfffff980`0c5e2f20 tagDESKTOP

       +0x018 pTerm            : 0xfffff960`002f5560 tagTERMINAL

       +0x020 dwWSF_Flags      : 0

       +0x028 spklList         : 0xfffff900`c192cf80 tagKL

       +0x030 ptiClipLock      : (null)

       +0x038 ptiDrawingClipboard: (null)

       +0x040 spwndClipOpen    : (null)

       +0x048 spwndClipViewer  : 0xfffff900`c1a4ca70 tagWND

       +0x050 spwndClipOwner   : 0xfffff900`c1a3ef70 tagWND

       +0x058 pClipBase        : 0xfffff900`c5512fa0 tagCLIP

       +0x060 cNumClipFormats  : 4

       +0x064 iClipSerialNumber : 0x16

       +0x068 iClipSequenceNumber : 0xc1

       +0x070 spwndClipboardListener : 0xfffff900`c1a53440 tagWND

       +0x078 pGlobalAtomTable: 0xfffff980`0bd56c70 Void

       +0x080 luidEndSession   : _LUID

       +0x088 luidUser         : _LUID

       +0x090 psidUser         : 0xfffff900`c402afe0 Void

     

    Note the spwndClipViewer, spwndClipboardListener, and spwndClipOwnerfields.  spwndClipViewer is the most-recently-registered window in the clipboard viewer chain.  Similarly, spwndClipboardListener is the most recent listener in our Clipboard Format Listener list.  spwndClipOwner is the window that set the content in the clipboard.

     

    Given the window, it is just a few steps to determine the process.  This would work forspwndClipViewer, spwndClipboardListener, and spwndClipOwner.  First, dt the value as a tagWND.  We'll use the spwndClipViewer for this demonstration: 

    kd> dt 0xfffff900`c1a4ca70 tagWND

    win32k!tagWND

       +0x000 head             : _THRDESKHEAD

       +0x028 state            : 0x40020008

       +0x028 bHasMeun         : 0y0

       +0x028 bHasVerticalScrollbar : 0y0

     

    We only care about the head - so since it is at offset 0, dt the same address as a _THRDESKHEAD: 

    kd> dt 0xfffff900`c1a4ca70 _THRDESKHEAD

    win32k!_THRDESKHEAD

       +0x000 h                : 0x00000000`000102ae Void

       +0x008 cLockObj         : 6

       +0x010 pti              : 0xfffff900`c4f26c20tagTHREADINFO

       +0x018 rpdesk           : 0xfffff980`0c5e2f20 tagDESKTOP

       +0x020 pSelf            : 0xfffff900`c1a4ca70  "???"

     

    Now, dt the address in pti as a tagTHREADINFO: 

    kd> dt 0xfffff900`c4f26c20 tagTHREADINFO

    win32k!tagTHREADINFO

       +0x000 pEThread         : 0xfffff980`0ef6cb10 _ETHREAD

       +0x008 RefCount         : 1

       +0x010 ptlW32           : (null)

       +0x018 pgdiDcattr       : 0x00000000`000f0d00 Void

     

    Here, we only care about the value of pEThread, which we can pass to !thread: 

    kd> !thread 0xfffff980`0ef6cb10 e

    THREAD fffff9800ef6cb10 Cid 087c.07ec  Teb: 000007fffffde000 Win32Thread: fffff900c4f26c20 WAIT: (WrUserRequest) UserModeNon-Alertable

        fffff9801c01efe0  SynchronizationEvent

    Not impersonating

    DeviceMap                 fffff980278a0fc0

    Owning Process            fffff98032e18b30       Image:         viewer02.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount     5435847        Ticks: 33 (0:00:00:00.515)

    Context Switch Count     809            IdealProcessor: 0                 LargeStack

    UserTime                  00:00:00.000

    KernelTime                00:00:00.062

    Win32 Start Address 0x000000013f203044

    Stack Init fffff880050acdb0 Current fffff880050ac6f0

    Base fffff880050ad000 Limit fffff880050a3000 Call 0

    Priority 11 BasePriority 8 UnusualBoost 0 ForegroundBoost 2IoPriority 2 PagePriority 5

    Child-SP          RetAddr           Call Site

    fffff880`050ac730 fffff800`01488f32 nt!KiSwapContext+0x7a

    fffff880`050ac870 fffff800`0148b74f nt!KiCommitThreadWait+0x1d2

    fffff880`050ac900 fffff960`000dc8e7 nt!KeWaitForSingleObject+0x19f

    fffff880`050ac9a0 fffff960`000dc989 win32k!xxxRealSleepThread+0x257

    fffff880`050aca40 fffff960`000dafc0 win32k!xxxSleepThread+0x59

    fffff880`050aca70 fffff960`000db0c5 win32k!xxxRealInternalGetMessage+0x7dc

    fffff880`050acb50 fffff960`000dcab5 win32k!xxxInternalGetMessage+0x35

    fffff880`050acb90 fffff800`01482ed3 win32k!NtUserGetMessage+0x75

    fffff880`050acc20 00000000`77929e6a nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880`050acc20)

    00000000`002ffb18 00000000`00000000 0x77929e6a

     

    As you can see, we have a clipboard viewer registered from process viewer02.exe.  Because of viewer's process-maintained chain architecture, it isn't easy to see the next process in the chain.  However, we can do this for clipboard listeners.  Let's look back at our window station: 

    kd> dt 0xfffff980`0be2af60 tagWINDOWSTATION

    win32k!tagWINDOWSTATION

       +0x000 dwSessionId      : 1

       +0x008 rpwinstaNext     : (null)

       +0x010 rpdeskList       : 0xfffff980`0c5e2f20 tagDESKTOP

       +0x018 pTerm            : 0xfffff960`002f5560 tagTERMINAL

       +0x020 dwWSF_Flags      : 0

       +0x028 spklList         : 0xfffff900`c192cf80 tagKL

       +0x030 ptiClipLock      : (null)

       +0x038 ptiDrawingClipboard : (null)

       +0x040 spwndClipOpen    : (null)

       +0x048 spwndClipViewer  : 0xfffff900`c1a4ca70tagWND

       +0x050 spwndClipOwner   : 0xfffff900`c1a3ef70tagWND

       +0x058 pClipBase        : 0xfffff900`c5512fa0 tagCLIP

       +0x060 cNumClipFormats  : 4

       +0x064 iClipSerialNumber : 0x16

       +0x068 iClipSequenceNumber : 0xc1

       +0x070 spwndClipboardListener: 0xfffff900`c1a53440 tagWND

       +0x078 pGlobalAtomTable: 0xfffff980`0bd56c70 Void

       +0x080 luidEndSession   : _LUID

       +0x088 luidUser         : _LUID

       +0x090 psidUser         : 0xfffff900`c402afe0 Void

     

    If we dt the spwndClipboardListener, there is a field that shows the next listener named spwndClipboardListenerNext: 

    kd> dt 0xfffff900`c1a53440 tagWND spwndClipboardListenerNext

    win32k!tagWND

       +0x118 spwndClipboardListenerNext : 0xfffff900`c1a50080 tagWND

     

    When you reach the last clipboard format listener's tagWND, its spwndClipboardListenerNext value will be null: 

    kd> dt 0xfffff900`c1a50080 tagWND spwndClipboardListenerNext

    win32k!tagWND

       +0x118 spwndClipboardListenerNext : (null)

     

    Using this window address, we can go through the same steps as above to identify this listener's process name. As mentioned earlier, since tagWND is a kernel structure, the OS is maintaining these spwndClipboardListener/spwndClipboardListenerNext pointers, so they aren't susceptible to the chain problems of clipboard viewers.

     

    That wraps up our clipboard coverage. I hope you found it informative.  Want to learn more about monitoring the clipboard?  This MSDN article is a good resource.

     

    -Matt Burrough

  • Ntdebugging Blog

    Tracking down MmSt paged pool usage

    • 6 Comments

     

    A trend that I’ve noticed recently are cases involving paged pool depletion with high MmSt tag usage that remains after trying KB304101 (PoolUsageMaximum). These pool allocations are used by the memory manager for section object prototype PTEs. There are generally only two options when this happens: 1) upgrade to a 64-bit platform, or 2) reduce the size of the volumes. But we may want to know what mapped files are using this memory. Here is how it can be done. Start with !memusage.

     

    5: kd> !memusage

     loading PFN database

    loading (100% complete)

    Compiling memory usage data (99% Complete).

                 Zeroed:  19073 ( 76292 kb)

                   Free:      0 (     0 kb)

                Standby: 1468824 (5875296 kb)

               Modified:    368 (  1472 kb)

        ModifiedNoWrite:   1927 (  7708 kb)

           Active/Valid: 605772 (2423088 kb)

             Transition:      0 (     0 kb)

                    Bad:      0 (     0 kb)

                Unknown:      0 (     0 kb)

                  TOTAL: 2095964 (8383856 kb)

      Building kernel map

      Finished building kernel map

    Scanning PFN database - (100% complete)

     

    Following this you will see the list of mapped files and their control areas.

     

      Usage Summary (in Kb):

    Control Valid Standby Dirty Shared Locked PageTables  name

    8c62a638  1108  945868  3064     0     0     0  mapped_file( $Mft )

     

    The control area is the address at the far left and has a Segment field that contains the total number of PTEs.

     

    5: kd> dt 8c62a638 _CONTROL_AREA Segment->TotalNumberOfPtes

    nt!_CONTROL_AREA

       +0x000 Segment                    :

          +0x004 TotalNumberOfPtes          : 0x1e8b00

     

    The MmSt allocations contain these PTEs so all we need to do is multiply this by the size of a PTE to get the total size of the MmSt allocations for this control area. Note that there may be multiple allocations for this control area, but this number will reflect the total size all these allocations.

     

    5: kd> ?? 0x1e8b00 * sizeof(nt!_MMPTE)

    unsigned int 0xf45800

     

    So now we know the MmSt size in bytes for a single control area, or mapped file. What if we would like to see the totals for all mapped files from the !memusage output? First, place the !memusage output in a text file and remove all header information. You will also need to remove all tail information including the page file and process summaries. Every line should look like these.

     

    8c62a638  1108  945868  3064     0     0     0  mapped_file( $Mft )

    8b06ac18   516      0     0     0     0     0    No Name for File

     

    We want to include the “No Name for File” entries since those are valid mapped files even though the name could not be located. Next strip out everything but the control area address. You can use Excel or any other tool that allows you to select and delete columns in a text file. Now we have a file with a single column of all the control areas on the system. The following debugger command script can be used to process this file.

     

    $$ countptes.txt script

    r $t2 = 0;

     

    $$ Replace the memusage.txt file name with your file name.

    .foreach /f (ca "memusage.txt") {

        r $t1 = @@c++(((nt!_CONTROL_AREA *)(0x${ca}))->Segment->TotalNumberOfPtes);

        .printf "Control Area %p : %d\n", ${ca}, @$t1;

        r $t2 = @$t2 + @$t1;

    }

     

    .printf "Total PTEs : %d\n", @$t2;

    .printf "MmSt size  : %d bytes\n", (@$t2 * @@c++(sizeof(nt!_MMPTE)));

     

    The following command will execute the script.

     

    5: kd> $$><countptes.txt

     

    This will show the number of PTEs for each control area, followed by a summary.

     

    Total PTEs : 62790244

    MmSt size  : 502321952 bytes

     

    A common high user of MmSt allocations is $Mft. The cache manager will hold the MmSt allocations for these file system metadata files at a cost of up to 4 files per PTE. This technique can be used to determine how much $Mft is using MmSt pool memory by first using findstr at a command prompt to isolate just those values from the !memusage output.

     

    C:\Projects>findstr /c:"$Mft" memusage.txt >mftusage.txt

     

    After stripping out the control area addresses with Excel and running the command script you’ll have the size of the MmSt allocations for just the $Mft files. If this is consuming most of the MmSt bytes then you are limited to the options mentioned at the beginning of this article. There may be other options if something else is the primary user but it will likely involve reducing some heavy load on the system.

     

    -Bryan

  • Ntdebugging Blog

    Debugging a Hang at “Applying Computer Settings”

    • 2 Comments

    Hi Everyone - My name is Aman. I'm an Escalation Engineer on the Microsoft GES (Global Escalation Services) team. We recently came across a critical situation where-in the following issues were reported by the customer:

     

    1.       DC login hangs at “applying computer settings” regardless of RDP or local console.

    2.       Connecting to the server using computer management console fails with "RPC Server is too busy to complete the operation"

    3.       Server responds to ping in the problem state but cannot be accessed through ports 445/139.

    4.       Reboot will fix the issue for a couple of days but the problem will return again.

     

    The case had already been troubleshot many times in the past without any results. So, to get to the root cause, it was escalated to GES and we took a full memory dump. In this blog I want to show you how to navigate between processes via LPC messages to drill down to root cause.

     

    Disclaimer – Not every hang at “Applying Computer Settings” requires a debug. Standard troubleshooting typically resolves this type of thing. 

     

    Now let's have a look at the Complete Memory Dump (note: a Kernel dump is not enough). Since the console session hangs at "applying computer settings", the target starting point of my debug will be the process called winlogon. Winlogon.exe is the executable responsible for initiating the logon process for users. If the console session is hung at "applying computer settings", winlogon has to have an explanation as to why it's unable to process the user logon successfully.

     

    So, let’s get the address of the winlogon process:

     

    kd> ! process 0 0 winlogon.exe

    PROCESS 85c63830  SessionId: 0  Cid: 01a4    Peb: 7ffdf000  ParentCid: 0158

        DirBase: 39f6a000  ObjectTable: e13d7928  HandleCount: 535.

        Image: winlogon.exe

     

    PROCESS 84f02020  SessionId: 1  Cid: 0344    Peb: 7ffdf000  ParentCid: 0158

        DirBase: 2d675000  ObjectTable: e35abc78  HandleCount: 313.

        Image: winlogon.exe

     

     

    So, why we have two winlogon processes executing? Simple, the customer tried to log into the domain controller via RDP and local console. Both methods resulted in the hang, hence creating two winlogon sessions. Let’s check the first one and see what's happening in there. I picked up only questionable threads for the sake of this session.

     

     

    kd> .process /p /r 85c63830

    Implicit process is now 85c63830

    Loading User Symbols

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

    .........

    kd> !process 85c63830 7

    PROCESS 85c63830  SessionId: 0  Cid: 01a4    Peb: 7ffdf000  ParentCid: 0158

        DirBase: 39f6a000  ObjectTable: e13d7928  HandleCount: 535.

        Image: winlogon.exe

        VadRoot 85c599c8 Vads 157 Clone 0 Private 1266. Modified 1081. Locked 0.

        DeviceMap e1001150

        Token                             e1743a38

        ElapsedTime                       15:50:33.974

        UserTime                          00:00:00.187

        KernelTime                        00:00:02.125

        QuotaPoolUsage[PagedPool]         53444

        QuotaPoolUsage[NonPagedPool]      63864

        Working Set Sizes (now,min,max)  (1161, 50, 345) (4644KB, 200KB, 1380KB)

        PeakWorkingSetSize                2834

        VirtualSize                       49 Mb

        PeakVirtualSize                   52 Mb

        PageFaultCount                    10861

        MemoryPriority                    BACKGROUND

        BasePriority                      13

        CommitCharge                      1979

     

     

     

            THREAD 847318d0  Cid 01a4.58e4  Teb: 7ffdd000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                84731abc  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 00213bd7:

            Current LPC port e125d4e0

            Not impersonating

            DeviceMap                 e1001150

            Owning Process            85c63830       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3650157        Ticks: 525 (0:00:00:08.203)

            Context Switch Count      2            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init f5c98000 Current f5c97c20 Base f5c98000 Limit f5c95000 Call 0

            Priority 14 BasePriority 13 PriorityDecrement 0

            ChildEBP RetAddr  Args to Child             

            f5c97c38 808202b6 847318d0 84731978 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            f5c97c50 8081fb6e 84731abc 84731a90 847318d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            f5c97c94 80915355 84731abc 00000011 f5c97d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            f5c97d50 8082350b 0000080c 00087ba0 00087ba0 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            f5c97d50 7c8285ec 0000080c 00087ba0 00087ba0 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f5c97d64)

            0075fab0 7c82787b 77c80a6e 0000080c 00087ba0 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            0075fab4 77c80a6e 0000080c 00087ba0 00087ba0 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            0075fb00 77c7fcf0 0075fb3c 0075fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            0075fb0c 77c80673 0075fb3c 75822c38 0075ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            0075fb20 77ce315a 0075fb68 00087c18 001125a8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            0075ff08 75822b74 75822c38 75822b8a 0075ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            0075ff20 75822b4f 00b81460 0075ff3c 0075ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            0075ff30 75824e7a 0075ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            0075ff60 0103917b 0075ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

            0075ffb8 77e64829 001125a8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            0075ffec 00000000 010390b7 001125a8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

    We found somewhere around 15 threads in the process above. Only the above thread looked suspicious since it has issued a LPC call and hasn't received a reply yet. Before we investigate further, let’s check the other winlogon process and find out about the threads in there as well....just in case if there is a commonality or not amongst both the processes...

     

    Note the long tick counts in these threads!

     

     

    kd> .process /p /r 84f02020

    Implicit process is now 84f02020

    Loading User Symbols

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

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

    kd> !process 84f02020 7

    PROCESS 84f02020  SessionId: 1  Cid: 0344    Peb: 7ffdf000  ParentCid: 0158

        DirBase: 2d675000  ObjectTable: e35abc78  HandleCount: 313.

        Image: winlogon.exe

        VadRoot 85e86dd0 Vads 184 Clone 0 Private 656. Modified 722. Locked 0.

        DeviceMap e1001150

        Token                             e3a09030

        ElapsedTime                       04:51:33.657

        UserTime                          00:00:00.140

        KernelTime                        00:00:00.796

        QuotaPoolUsage[PagedPool]         49464

        QuotaPoolUsage[NonPagedPool]      10080

        Working Set Sizes (now,min,max)  (1099, 50, 345) (4396KB, 200KB, 1380KB)

        PeakWorkingSetSize                2193

        VirtualSize                       48 Mb

        PeakVirtualSize                   50 Mb

        PageFaultCount                    4312

        MemoryPriority                    BACKGROUND

        BasePriority                      13

        CommitCharge                      1329

     

            THREAD 847a93f0  Cid 0344.4ab0  Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                847a95dc  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0020b318:

            Current LPC port e3761290

            Impersonation token:  e3a92250 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3500419        Ticks: 150263 (0:00:39:07.859)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9d00000 Current b9cffc20 Base b9d00000 Limit b9cfd000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b9cffc38 808202b6 847a93f0 847a9498 00000310 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b9cffc50 8081fb6e 847a95dc 847a95b0 847a93f0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b9cffc94 80915355 847a95dc 00000011 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b9cffd50 8082350b 00000364 000b9760 000b9760 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b9cffd50 7c8285ec 00000364 000b9760 000b9760 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9cffd64)

            0087fab0 7c82787b 77c80a6e 00000364 000b9760 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            0087fab4 77c80a6e 00000364 000b9760 000b9760 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            0087fb00 77c7fcf0 0087fb3c 0087fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            0087fb0c 77c80673 0087fb3c 75822c38 0087ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            0087fb20 77ce315a 0087fb68 000b9820 000a8bd8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            0087ff08 75822b74 75822c38 75822b8a 0087ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            0087ff20 75822b4f 000c1e30 0087ff3c 0087ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            0087ff30 75824e19 0087ff3c 00080000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            0087ff60 0103917b 0087ff78 00000000 00000000 WlNotify!SensStartScreenSaverEvent+0x58 (FPO: [1,9,0])

            0087ffb8 77e64829 000a8bd8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            0087ffec 00000000 010390b7 000a8bd8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 847ad8d0  Cid 0344.4c7c  Teb: 7ffac000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                847adabc  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0020bf59:

            Current LPC port e3761290

            Impersonation token:  e39b1358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3513766        Ticks: 136916 (0:00:35:39.312)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9dc0000 Current b9dbfc20 Base b9dc0000 Limit b9dbd000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b9dbfc38 808202b6 847ad8d0 847ad978 00000341 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b9dbfc50 8081fb6e 847adabc 847ada90 847ad8d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b9dbfc94 80915355 847adabc 00000011 b9dbfd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b9dbfd50 8082350b 00000364 000ba340 000ba340 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b9dbfd50 7c8285ec 00000364 000ba340 000ba340 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9dbfd64)

            00b7fab0 7c82787b 77c80a6e 00000364 000ba340 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            00b7fab4 77c80a6e 00000364 000ba340 000ba340 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            00b7fb00 77c7fcf0 00b7fb3c 00b7fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            00b7fb0c 77c80673 00b7fb3c 75822c38 00b7ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            00b7fb20 77ce315a 00b7fb68 000ba400 000a8b80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            00b7ff08 75822b74 75822c38 75822b8a 00b7ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            00b7ff20 75822b4f 000c1e30 00b7ff3c 00b7ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            00b7ff30 75824e7a 00b7ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            00b7ff60 0103917b 00b7ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

            00b7ffb8 77e64829 000a8b80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            00b7ffec 00000000 010390b7 000a8b80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 84989b40  Cid 0344.4c88  Teb: 7ffaa000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                84989d2c  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0020bf60:

            Current LPC port e3761290

            Impersonation token:  e3a48030 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3513766        Ticks: 136916 (0:00:35:39.312)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9c44000 Current b9c43c20 Base b9c44000 Limit b9c41000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b9c43c38 808202b6 84989b40 84989be8 00000741 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b9c43c50 8081fb6e 84989d2c 84989d00 84989b40 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b9c43c94 80915355 84989d2c 00000011 b9c43d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b9c43d50 8082350b 00000364 000c18a8 000c18a8 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b9c43d50 7c8285ec 00000364 000c18a8 000c18a8 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9c43d64)

            00dffab0 7c82787b 77c80a6e 00000364 000c18a8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            00dffab4 77c80a6e 00000364 000c18a8 000c18a8 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            00dffb00 77c7fcf0 00dffb3c 00dffb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            00dffb0c 77c80673 00dffb3c 75822c38 00dfff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            00dffb20 77ce315a 00dffb68 000c1968 000bcd80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            00dfff08 75822b74 75822c38 75822b8a 00dfff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            00dfff20 75822b4f 000c1e30 00dfff3c 00dfff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            00dfff30 75824d57 00dfff3c 00020000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            00dfff60 0103917b 00dfff78 00000000 00000000 WlNotify!SensLockEvent+0x58 (FPO: [1,9,0])

            00dfffb8 77e64829 000bcd80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            00dfffec 00000000 010390b7 000bcd80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 847d7b18  Cid 0344.4c9c  Teb: 7ffa6000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                847d7d04  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0020bfb4:

            Current LPC port e3761290

            Impersonation token:  e423a358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3514154        Ticks: 136528 (0:00:35:33.250)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9c00000 Current b9bffc20 Base b9c00000 Limit b9bfd000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b9bffc38 808202b6 847d7b18 847d7bc0 00002601 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b9bffc50 8081fb6e 847d7d04 847d7cd8 847d7b18 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b9bffc94 80915355 847d7d04 00000011 b9bffd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b9bffd50 8082350b 00000364 000ab970 000ab970 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b9bffd50 7c8285ec 00000364 000ab970 000ab970 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9bffd64)

            00fcfab0 7c82787b 77c80a6e 00000364 000ab970 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            00fcfab4 77c80a6e 00000364 000ab970 000ab970 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            00fcfb00 77c7fcf0 00fcfb3c 00fcfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            00fcfb0c 77c80673 00fcfb3c 75822c38 00fcff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            00fcfb20 77ce315a 00fcfb68 000aba30 000bd858 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            00fcff08 75822b74 75822c38 75822b8a 00fcff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            00fcff20 75822b4f 000c1e30 00fcff3c 00fcff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            00fcff30 75824db8 00fcff3c 00040000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            00fcff60 0103917b 00fcff78 00000000 00000000 WlNotify!SensUnlockEvent+0x58 (FPO: [1,9,0])

            00fcffb8 77e64829 000bd858 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            00fcffec 00000000 010390b7 000bd858 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 8478e8d0  Cid 0344.53d0  Teb: 7ffab000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                8478eabc  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0020f7bb:

            Current LPC port e3761290

            Impersonation token:  e3811358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3572296        Ticks: 78386 (0:00:20:24.781)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b94bc000 Current b94bbc20 Base b94bc000 Limit b94b9000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b94bbc38 808202b6 8478e8d0 8478e978 00000310 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b94bbc50 8081fb6e 8478eabc 8478ea90 8478e8d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b94bbc94 80915355 8478eabc 00000011 b94bbd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b94bbd50 8082350b 00000364 000880a8 000880a8 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b94bbd50 7c8285ec 00000364 000880a8 000880a8 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b94bbd64)

            00dbfab0 7c82787b 77c80a6e 00000364 000880a8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            00dbfab4 77c80a6e 00000364 000880a8 000880a8 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            00dbfb00 77c7fcf0 00dbfb3c 00dbfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            00dbfb0c 77c80673 00dbfb3c 75822c38 00dbff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            00dbfb20 77ce315a 00dbfb68 00088168 0008bd80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            00dbff08 75822b74 75822c38 75822b8a 00dbff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            00dbff20 75822b4f 000c1e30 00dbff3c 00dbff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            00dbff30 75824e19 00dbff3c 00080000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            00dbff60 0103917b 00dbff78 00000000 00000000 WlNotify!SensStartScreenSaverEvent+0x58 (FPO: [1,9,0])

            00dbffb8 77e64829 0008bd80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            00dbffec 00000000 010390b7 0008bd80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 846e6660  Cid 0344.56a8  Teb: 7ffa7000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                846e684c  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 0021117f:

            Current LPC port e3761290

            Impersonation token:  e37a5358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3602966        Ticks: 47716 (0:00:12:25.562)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9500000 Current b94ffc20 Base b9500000 Limit b94fd000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b94ffc38 808202b6 846e6660 846e6708 00000241 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b94ffc50 8081fb6e 846e684c 846e6820 846e6660 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b94ffc94 80915355 846e684c 00000011 b94ffd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b94ffd50 8082350b 00000364 0008ba78 0008ba78 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b94ffd50 7c8285ec 00000364 0008ba78 0008ba78 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b94ffd64)

            00f8fab0 7c82787b 77c80a6e 00000364 0008ba78 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            00f8fab4 77c80a6e 00000364 0008ba78 0008ba78 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            00f8fb00 77c7fcf0 00f8fb3c 00f8fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            00f8fb0c 77c80673 00f8fb3c 75822c38 00f8ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            00f8fb20 77ce315a 00f8fb68 0008bb38 0009bbf0 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            00f8ff08 75822b74 75822c38 75822b8a 00f8ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            00f8ff20 75822b4f 000c1e30 00f8ff3c 00f8ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            00f8ff30 75824e7a 00f8ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            00f8ff60 0103917b 00f8ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

            00f8ffb8 77e64829 0009bbf0 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            00f8ffec 00000000 010390b7 0009bbf0 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 8470d428  Cid 0344.56b4  Teb: 7ffa4000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                8470d614  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 00211186:

            Current LPC port e3761290

            Impersonation token:  e4167358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3602966        Ticks: 47716 (0:00:12:25.562)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9378000 Current b9377c20 Base b9378000 Limit b9375000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b9377c38 808202b6 8470d428 8470d4d0 00002241 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b9377c50 8081fb6e 8470d614 8470d5e8 8470d428 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b9377c94 80915355 8470d614 00000011 b9377d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b9377d50 8082350b 00000364 0013b340 0013b340 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b9377d50 7c8285ec 00000364 0013b340 0013b340 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9377d64)

            016dfab0 7c82787b 77c80a6e 00000364 0013b340 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            016dfab4 77c80a6e 00000364 0013b340 0013b340 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            016dfb00 77c7fcf0 016dfb3c 016dfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            016dfb0c 77c80673 016dfb3c 75822c38 016dff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            016dfb20 77ce315a 016dfb68 0013b400 0007f808 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            016dff08 75822b74 75822c38 75822b8a 016dff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            016dff20 75822b4f 000c1e30 016dff3c 016dff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            016dff30 75824d57 016dff3c 00020000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            016dff60 0103917b 016dff78 00000000 00000000 WlNotify!SensLockEvent+0x58 (FPO: [1,9,0])

            016dffb8 77e64829 0007f808 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            016dffec 00000000 010390b7 0007f808 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

            THREAD 846c4b40  Cid 0344.56d0  Teb: 7ffa2000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

                846c4d2c  Semaphore Limit 0x1

            Waiting for reply to LPC MessageId 00211223:

            Current LPC port e3761290

            Impersonation token:  e3826358 (Level Impersonation)

            DeviceMap                 e1bca430

            Owning Process            84f02020       Image:         winlogon.exe

            Attached Process          N/A            Image:         N/A

            Wait Start TickCount      3603490        Ticks: 47192 (0:00:12:17.375)

            Context Switch Count      1            

            UserTime                  00:00:00.000

            KernelTime                00:00:00.000

            Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

            Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

            Stack Init b9310000 Current b930fc20 Base b9310000 Limit b930d000 Call 0

            Priority 13 BasePriority 13 PriorityDecrement 0

            Kernel stack not resident.

            ChildEBP RetAddr  Args to Child             

            b930fc38 808202b6 846c4b40 846c4be8 00002301 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

            b930fc50 8081fb6e 846c4d2c 846c4d00 846c4b40 nt!KiSwapThread+0x83 (FPO: [0,2,0])

            b930fc94 80915355 846c4d2c 00000011 b930fd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

            b930fd50 8082350b 00000364 0013c440 0013c440 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

            b930fd50 7c8285ec 00000364 0013c440 0013c440 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b930fd64)

            0175fab0 7c82787b 77c80a6e 00000364 0013c440 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

            0175fab4 77c80a6e 00000364 0013c440 0013c440 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

            0175fb00 77c7fcf0 0175fb3c 0175fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

            0175fb0c 77c80673 0175fb3c 75822c38 0175ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

            0175fb20 77ce315a 0175fb68 0013c500 00098ef8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

            0175ff08 75822b74 75822c38 75822b8a 0175ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

            0175ff20 75822b4f 000c1e30 0175ff3c 0175ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

            0175ff30 75824db8 0175ff3c 00040000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

            0175ff60 0103917b 0175ff78 00000000 00000000 WlNotify!SensUnlockEvent+0x58 (FPO: [1,9,0])

            0175ffb8 77e64829 00098ef8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

            0175ffec 00000000 010390b7 00098ef8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

    Wow!....look at that...around 8 threads, and all waiting for replies to the LPC calls issued. So, both the winlogon processes are stuck waiting for a reply for the LPC calls they made.

     

    The next part is to find out what's happening at the server part of these LPC calls since winlogon is stuck until the processing of the LPC calls are finished.

     

    To find the server part of the LPC call, we pick the message ID from each thread. Look for (Waiting for reply to LPC MessageId "message_id":) in the threads above. Let's start with the first winlogon process to find out the server end of the LPC call it had in there. If you remember, we did find one thread in the first winlogon process waiting for a reply to the LPC call and message id of that LPC call was 00213bd7.

     

    kd> !lpc message 00213bd7

    Searching message 213bd7 in threads ...

    Client thread 847318d0 waiting a reply from 213bd7                         

    Searching thread 847318d0 in port rundown queues ...

     

    Server communication port 0xe365aa90

        Handles: 1   References: 1

        The LpcDataInfoChainHead queue is empty

            Connected port: 0xe125d4e0      Server connection port: 0xe1c37920

     

    Client communication port 0xe125d4e0

        Handles: 1   References: 2

        The LpcDataInfoChainHead queue is empty

     

    Server connection port e1c37920  Name: senssvc

        Handles: 1   References: 17

        Server process  : 85e021e0 (svchost.exe)

        Queue semaphore : 850fa890

        Semaphore state 16 (0x10)

            Messages in queue:

            0000 e3791a88 - Busy  Id=001fbe4f  From: 0f4c.335c  Context=80060002  [e1c37930 . e1281378]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000028 00000005 00010050 00d0fdac

            0000 e1281378 - Busy  Id=001fbe56  From: 0f4c.336c  Context=80060002  [e3791a88 . e15c5350]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00490065 0074006e 006c0065 00500000

            0000 e15c5350 - Busy  Id=00200326  From: 0f4c.3840  Context=80060002  [e1281378 . e14ba008]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 0008c080 00000000 0049004d 00440048

            0000 e14ba008 - Busy  Id=0020032a  From: 0f4c.3848  Context=80060002  [e15c5350 . e1120290]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 00000000 0000000c 00000000

            0000 e1120290 - Busy  Id=002049b3  From: 0f4c.3b08  Context=80060002  [e14ba008 . e40a48c8]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00600040 00600050 00900050 00600050

            0000 e40a48c8 - Busy  Id=00204e8d  From: 0f4c.09c8  Context=80060002  [e1120290 . e1ab41d0]

                       Length=00200008  Type=00000005 (LPC_PORT_CLOSED)

                       Data: fd48cde3 01c9700a

            0000 e1ab41d0 - Busy  Id=0020b318  From: 0344.4ab0  Context=80050001  [e40a48c8 . e1b35378]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000028 00000005 00010050 00d0fdac

            0000 e1b35378 - Busy  Id=0020bf59  From: 0344.4c7c  Context=80050001  [e1ab41d0 . e1bdc918]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 00000000 00000000 00000000

            0000 e1bdc918 - Busy  Id=0020bf60  From: 0344.4c88  Context=80050001  [e1b35378 . e1657ca0]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 0037002d 00350032 00340033 00350035

            0000 e1657ca0 - Busy  Id=0020bfb4  From: 0344.4c9c  Context=80050001  [e1bdc918 . e3a463e8]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 4ed07378 cf0ee4b3 5faeb176 0000000c

            0000 e3a463e8 - Busy  Id=0020f7bb  From: 0344.53d0  Context=80050001  [e1657ca0 . e1bcab08]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 00000000 00000000 00000000

            0000 e1bcab08 - Busy  Id=0021117f  From: 0344.56a8  Context=80050001  [e3a463e8 . e4190008]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 813a8198 00001601 00027011

            0000 e4190008 - Busy  Id=00211186  From: 0344.56b4  Context=80050001  [e1bcab08 . e40afca8]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 002e0070 0061006d 00720072 006f0069

            0000 e40afca8 - Busy  Id=00211223  From: 0344.56d0  Context=80050001  [e4190008 . e37de340]

                       Length=00c000a8  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 4bdd485c 5d18bba4 d4bb211b 0000000c

            0000 e37de340 - Busy  Id=00213bd7  From: 01a4.58e4  Context=80030000  [e40afca8 . e1c37930]

                       Length=00780060  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 811fc308 00001601 000152cb

        The message queue contains 15 messages

        The LpcDataInfoChainHead queue is empty

     

    Done!                                            

     

    Interesting, along with the message id, 00213bd7 , in the queue, we also found all other message ID's seen in the second winlogon process.

    Take a look at the messages in queue and you will see all of them in there.

     

    So, now the question arises as to what is this process doing and why its unable to process these LPC call's successfully.

     

    Let's switch context to the Server process  :  85e021e0 (svchost.exe)

     

    kd> .process /p /r 85e021e0

    Implicit process is now 85e021e0 

    Loading User Symbols

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

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

     

    When I dumped the threads in this process, the thread count turned out to be an alarming 4900 which is extremely bizarre. Around 1325 of those threads were waiting to acquire a common critical section. This became a very solid point of interest and almost all of them (around 4870) were in a wait state pending a single common SynchronizationEvent i.e. 85d1eeb0.

     

    These threads wait for the message to come through via the LPC port to the server process. That also explains why the server service (user mode component: srvsvc.dll) is unable to process any remote requests.

     

    Few of those threads, waiting on the common critical section, looked like this: (Don’t get bothered by the “Kernel stack not resident” as we know memory gets swapped to disk)

     

    kd> !thread 84832af8

    THREAD 84832af8  Cid 03d8.4760  Teb: 7ef49000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3474348        Ticks: 176334 (0:00:45:55.218)

    Context Switch Count      1            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init b9fd4000 Current b9fd3c78 Base b9fd4000 Limit b9fd1000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

    ChildEBP RetAddr  Args to Child             

    b9fd3c90 808202b6 84832af8 84832ba0 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

    b9fd3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

    b9fd3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

    b9fd3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

    b9fd3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9fd3d64)

    3d6bfbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    3d6bfbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

    3d6bfc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

    3d6bfc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

    3d6bfcb8 7c82ec9f 3d6bfd28 3d6bfd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

    3d6bfd14 7c8284c5 3d6bfd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

    00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

     

    kd> !thread 847d8b40

    THREAD 847d8b40  Cid 03d8.4be0  Teb: 7ed63000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3549550        Ticks: 101132 (0:00:26:20.187)

    Context Switch Count      1            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init b98a4000 Current b98a3c78 Base b98a4000 Limit b98a1000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

    ChildEBP RetAddr  Args to Child             

    b98a3c90 808202b6 847d8b40 847d8be8 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

    b98a3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

    b98a3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

    b98a3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

    b98a3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b98a3d64)

    4503fbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    4503fbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

    4503fc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

    4503fc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

    4503fcb8 7c82ec9f 4503fd28 4503fd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

    4503fd14 7c8284c5 4503fd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

    00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

     

    kd> !thread 847a8db0

    THREAD 847a8db0  Cid 03d8.4998  Teb: 7eed1000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3487819        Ticks: 162863 (0:00:42:24.734)

    Context Switch Count      1            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init b9dc4000 Current b9dc3c78 Base b9dc4000 Limit b9dc1000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

    ChildEBP RetAddr  Args to Child              

    b9dc3c90 808202b6 847a8db0 847a8e58 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

    b9dc3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

    b9dc3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

    b9dc3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

    b9dc3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9dc3d64)

    3f4bfbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    3f4bfbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

    3f4bfc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

    3f4bfc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

    3f4bfcb8 7c82ec9f 3f4bfd28 3f4bfd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

    3f4bfd14 7c8284c5 3f4bfd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

    00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

     

    kd> !thread 848e1db0

    THREAD 848e1db0  Cid 03d8.2c10  Teb: 7f67a000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3183097        Ticks: 467585 (0:02:01:46.015)

    Context Switch Count      1             

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init f3570000 Current f356fc78 Base f3570000 Limit f356d000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident

     

    kd> !thread 84890db0

    THREAD 84890db0  Cid 03d8.31cc  Teb: 7f4e3000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3244800        Ticks: 405882 (0:01:45:41.906)

    Context Switch Count      1            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init f2ee8000 Current f2ee7c78 Base f2ee8000 Limit f2ee5000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

     

    kd> !thread 848223f0

    THREAD 848223f0  Cid 03d8.3714  Teb: 7f3d8000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

        85d1eeb0  SynchronizationEvent

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3283235        Ticks: 367447 (0:01:35:41.359)

    Context Switch Count      1            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init f2ac4000 Current f2ac3c78 Base f2ac4000 Limit f2ac1000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

     

    kd> dt ntdll!_RTL_CRITICAL_SECTION 7c8877a0

       +0x000 DebugInfo        : 0x7c8877c0 _RTL_CRITICAL_SECTION_DEBUG

       +0x004 LockCount        : -19514

       +0x008 RecursionCount   : 2

       +0x00c OwningThread     : 0x00001634

       +0x010 LockSemaphore    : 0x00000314

       +0x014 SpinCount        : 0

     

    In Microsoft Windows Server 2003 Service Pack 1 and later versions of Windows, the LockCount field is parsed as follows: (also at link http://msdn.microsoft.com/en-us/library/cc267476.aspx)

    • The lowest bit shows the lock status. If this bit is 0, the critical section is locked; if it is 1, the critical section is not locked.
    • The next bit shows whether a thread has been woken for this lock. If this bit is 0, then a thread has been woken for this lock; if it is 1, no thread has been woken.
    • The remaining bits are the ones-complement of the number of threads waiting for the lock.

    In our case, the LockCount is -19514. The lowest bit can be determined in this way:

    kd> ? 0x1 & (-0n19514)

    Evaluate expression: 0 = 00000000

     

    kd>  (0x2 & (-0n19514)) >> 1

         ^ Syntax error in ' (0x2 & (-0n19514)) >> 1'

     

    kd> ?(0x2 & (-0n19514)) >> 1

    Evaluate expression: 1 = 00000001

     

    kd> ? ((-1) - (-0n19514)) >> 2

    Evaluate expression: 4878 = 0000130e

     

     

    So, there are 4878 threads waiting for this particular critical section. Seeing the number of above threads in the waiting list, it makes lot of sense.

    In RED above, we see the offender (0x00001634) who is not ready to leave the critical section.

     

    So now, at least we know which thread is causing the server to be unresponsive. Let’s go further and find out what’s happening in that particular thread.

     

    kd> !thread 85125020

    THREAD 85125020  Cid 03d8.1634  Teb: 7ffdb000 Win32Thread: e1754ea8 WAIT: (Unknown) UserMode Non-Alertable

        8512520c  Semaphore Limit 0x1

    Waiting for reply to LPC MessageId 001e295b:

    Current LPC port e38140c8

    IRP List:

        850eff68: (0006,0094) Flags: 00000800  Mdl: 00000000

    Not impersonating

    DeviceMap                 e1001150

    Owning Process            85e021e0       Image:         svchost.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      3470768        Ticks: 179914 (0:00:46:51.156)

    Context Switch Count      93                 LargeStack

    UserTime                  00:00:00.000

    KernelTime                00:00:00.015

    Win32 Start Address RPCRT4!ThreadStartRoutine (0x77c7b0f5)

    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

    Stack Init f5424000 Current f5423c20 Base f5424000 Limit f5421000 Call 0

    Priority 10 BasePriority 8 PriorityDecrement 0

    Kernel stack not resident.

    ChildEBP RetAddr  Args to Child             

    f5423c38 808202b6 85125020 851250c8 00000500 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

    f5423c50 8081fb6e 8512520c 851251e0 85125020 nt!KiSwapThread+0x83 (FPO: [0,2,0])

    f5423c94 80915355 8512520c 00000011 80912701 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

    f5423d50 8082350b 00000a40 000e9dd8 000de270 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

    f5423d50 7c8285ec 00000a40 000e9dd8 000de270 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f5423d64)

    00a0c580 7c82787b 77e77342 00000a40 000e9dd8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    00a0c584 77e77342 00000a40 000e9dd8 000de270 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

    00a0c5bc 77e77214 01b1f978 7c840936 00a0c604 kernel32!BasepQueryModuleData+0x121 (FPO: [5,6,4])

    00a0c5dc 7c84086e 01b1f978 7c840936 00a0c604 kernel32!BaseQueryModuleData+0x3b (FPO: [5,1,0])

    00a0c82c 7c8343b7 0009ec88 0009ec88 00000000 ntdll!LdrpCheckAppDatabase+0x9c (FPO: [1,138,4])

    00a0c840 7c8333ba 0009ec88 0016ecb0 00a0ce98 ntdll!LdrpCheckNXCompatibility+0x27 (FPO: [1,1,4])

    00a0c93c 7c834311 00000000 00000000 777964d0 ntdll!LdrpRunInitializeRoutines+0x20f (FPO: [SEH])

    00a0cbd0 7c834065 00000000 0016ecb0 00a0ce98 ntdll!LdrpLoadDll+0x3cd (FPO: [SEH])

    00a0ce4c 77e41bf3 0016ecb0 00a0ce98 00a0ce78 ntdll!LdrLoadDll+0x198 (FPO: [SEH])

    00a0ceb4 776adc89 00a0cf30 00000000 00000008 kernel32!LoadLibraryExW+0x1b2 (FPO: [SEH])

    00a0ced8 776adb95 00a0cf30 00a0cefc 00a0cf00 ole32!CClassCache::CDllPathEntry::LoadDll+0xb0 (FPO: [4,1,4])

    00a0cf08 776ad2da 00a0cf30 00a0d208 00a0cf28 ole32!CClassCache::CDllPathEntry::Create_rl+0x37 (FPO: [3,3,4])

    00a0d154 776ad1fd 00000001 00a0d208 00a0d184 ole32!CClassCache::CClassEntry::CreateDllClassEntry_rl+0xd8 (FPO: [3,139,4])

    00a0d19c 776ad112 00000001 00105624 00a0d1c8 ole32!CClassCache::GetClassObjectActivator+0x1fe (FPO: [3,10,4])

    00a0d1cc 776a1b7f 00a0d208 00a0dce8 00a0d7a0 ole32!CClassCache::GetClassObject+0x24 (FPO: [1,1,0])

    00a0d240 776a19b5 77794964 00a0d7a0 00a0dce8 ole32!CServerContextActivator::GetClassObject+0xfd (FPO: [3,23,4])

    00a0d278 776a1c4e 00a0d7a0 00a0dce8 00a0d7a0 ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

    00a0d298 776a1bfa 77794978 00a0d7a0 00a0dce8 ole32!CApartmentActivator::GetClassObject+0x4d (FPO: [3,2,0])

    00a0d2b0 776acb27 77794978 00000001 00000000 ole32!CProcessActivator::GCOCallback+0x2b (FPO: [6,0,4])

    00a0d2d0 776acad8 77794960 00a0d5fc 00000000 ole32!CProcessActivator::AttemptActivation+0x2c (FPO: [7,0,0])

    00a0d30c 776a1ca1 77794960 00a0d5fc 00000000 ole32!CProcessActivator::ActivateByContext+0x4f (FPO: [6,3,0])

    00a0d334 776a19b5 77794960 00a0d7a0 00a0dce8 ole32!CProcessActivator::GetClassObject+0x48 (FPO: [3,1,4])

    00a0d36c 776a1925 00a0d7a0 00a0dce8 0073006d ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

    00a0d5b4 776a19b5 7779487c 00000001 00a0dce8 ole32!CClientContextActivator::GetClassObject+0x88 (FPO: [3,3,0])

    00a0d5ec 776a1a07 00a0d7a0 00a0dce8 7767c9b0 ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

    00a0dda4 776a187e 00a0ded8 00000001 00000000 ole32!ICoGetClassObject+0x3a5 (FPO: [7,52,0])

    00a0ddd4 776a1841 00a0ded8 00000002 00000000 ole32!CComActivator::DoGetClassObject+0xe0 (FPO: [6,0,4])

    00a0ddf4 772d7218 00a0ded8 00000001 00000000 ole32!CoGetClassObject+0x20 (FPO: [5,0,0])

    00a0de60 772d65ce 01ab48d8 01aeba70 00a0de80 urlmon!CProtMgr::FindFirstCF+0x11a (FPO: [4,17,0])

    00a0de84 772c4408 01ab4870 01aeba70 00000000 urlmon!COInetSession::CreateHandler+0x2d (FPO: [6,1,0])

    00a0deec 772d6b6c 00083ff8 01aeba70 000841b0 urlmon!CTransaction::LoadHandler+0xbd (FPO: [5,15,4])

    00a0df18 772c8302 00083ff8 0000000d 00000001 urlmon!CTransaction::DispatchReport+0x203 (FPO: [8,1,4])

    00a0df44 772c874b 00083ff8 01b092e8 00000000 urlmon!CTransaction::DispatchPacket+0x31 (FPO: [2,0,4])

    00a0df64 772c6681 00083ff8 00000000 00a0e014 urlmon!CTransaction::OnINetCallback+0x92 (FPO: [2,1,0])

    00a0df9c 7739b6e3 00c60048 00000465 00000000 urlmon!TransactionWndProc+0x33 (FPO: [SEH])

    00a0dfc8 7739b874 772c664e 00c60048 00000465 USER32!InternalCallWinProc+0x28

    00a0e040 7739ba92 00000000 772c664e 00c60048 USER32!UserCallWinProcCheckWow+0x151 (FPO: [SEH])

    00a0e0a8 773a16e5 00a0e0d0 00000001 00a0e10c USER32!DispatchMessageWorker+0x327 (FPO: [SEH])

    00a0e0b8 772de54a 00a0e0d0 00084100 00000000 USER32!DispatchMessageA+0xf (FPO: [1,0,0])

    00a0e10c 772ca8f5 00000000 00000000 01ad6588 urlmon!CTransaction::CompleteOperation+0x15a (FPO: [1,15,0])

    00a0e148 772c77ee 00083ff8 01ac6930 01ad64e0 urlmon!CTransaction::Start+0x52c (FPO: [6,9,4])

    00a0e1cc 772c744f 00a0e214 01aa2b30 772c9c00 urlmon!CBinding::StartBinding+0x4d8 (FPO: [6,22,4])

    00a0f264 772c7319 01aa7230 00000000 01aa2b30 urlmon!CUrlMon::StartBinding+0x1d8 (FPO: [6,1051,4])

    00a0f29c 772eb8f5 01aa7230 01aa2b30 00000000 urlmon!CUrlMon::BindToStorage+0x67 (FPO: [5,3,4])

    00a0f2e0 7732238b 001422e0 00a0f344 001422e0 urlmon!CBaseBSCB::KickOffDownload+0x191 (FPO: [2,8,0])

    00a0f2f4 7732296f 001422e0 00a0f344 0000000c urlmon!CFileDownload::KickOffDownload+0x2d (FPO: [2,0,4])

    00a0f30c 77322ce6 00000000 00a0f344 00a0f3c4 urlmon!URLDownloadToFileW+0x51 (FPO: [5,0,0])

    00a0f444 00a0f59d 00000000 00a0f63e 00a0f632 urlmon!URLDownloadToFileA+0xd8 (FPO: [5,68,4])

    WARNING: Frame IP not in any known module. Following frames may be wrong.

    00a0f474 71bf396b 48544950 71bf3969 554a4649 0xa0f59d

     77430b8c 77e40000 00000000 00000004 0000ffff 000000b8 WS2HELP!WahOpenHandleHelper+0xf7 (FPO: [1,114,0])

     

    Now, looking at the thread, lets list down the observations and our interpretation from it:

     

    1)      So, by looking at API URLDownloadToFileW(), it seems this thread is busy downloading a file from the internet. The API and parameters are documented at  http://msdn.microsoft.com/en-us/library/ms836094.aspx Let’s find out which file are we trying to download here:

     

    kd> du 00a0f344

    00a0f344  http://10.162.13.115:31797/x

     

    kd> du 00a0f3c4

    00a0f3c4  "x.exe"

     

    So we are trying to download an executable here? It’s worth having the customer investigate this binary?

     

    2)      This thread is waiting for a reply to a LPC call issued (LPC MessageId 001e295b), so let’s find out who do we have at the server end of this LPC call:

     

    kd> !lpc message 001e295b

    Searching message 1e295b in threads ...

    Client thread 85125020 waiting a reply from 1e295b                         

    Searching thread 85125020 in port rundown queues ...

     

    Server connection port e1395030  Name: AELPort

        Handles: 1   References: 22

        Server process  : 85e021e0 (svchost.exe)

        Queue semaphore : 85c593f8

        Semaphore state 0 (0x0)

        The message queue is empty

     

    So, as you see above, the server piece of this LPC call is this process itself hence a straightforward deadlock situation. Also, please remember that critical section is process specific.

     

    3)      The stack below URLMON looks messed up so we shall have to look at the raw stack and reconstruct the correct stack. 

     

    kd> kv =00a0f8cc 0x00a0f8cc 71c49573

     

    ChildEBP RetAddr  Args to Child             

    00a0f8cc 71c49578 000c9620 000c93ac 00104100 NETAPI32!NetpwPathCanonicalize+0x76 (FPO: [6,0,4])

    00a0f8f4 74edc916 000c93ac 00104100 0000019a NETAPI32!NetpwPathCanonicalize+0x7b (FPO: [6,0,4])

    00a0f914 77c80193 000c9398 000c93ac 00104100 srvsvc!NetprPathCanonicalize+0x1c (FPO: [7,0,0])

    00a0f944 77ce33e1 74edc8fa 00a0fb28 00000007 RPCRT4!Invoke+0x30

    00a0fd44 77ce35c4 00000000 00000000 000b9fd8 RPCRT4!NdrStubCall2+0x299 (FPO: [SEH])

    00a0fd60 77c7ff7a 000b9fd8 000a80d8 000b9fd8 RPCRT4!NdrServerCall2+0x19 (FPO: [1,1,0])

    00a0fd94 77c8042d 74ed31d7 000b9fd8 00a0fe34 RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [SEH])

    00a0fde8 77c80353 0000001f 00000000 74ee3f0c RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x11f (FPO: [4,13,4])

    00a0fe0c 77c68e0d 000b9fd8 00000000 74ee3f0c RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [4,0,4])

    00a0fe40 77c68cb3 000b9f98 000002a4 000b9f60 RPCRT4!OSF_SCALL::DispatchHelper+0x149 (FPO: [0,4,4])

    00a0fe54 77c68c2b 00000000 0000001f 000c9370 RPCRT4!OSF_SCALL::DispatchRPCCall+0x10d (FPO: [2,0,4])

    00a0fe84 77c68b5e 000c9370 030002bc 0000001f RPCRT4!OSF_SCALL::ProcessReceivedPDU+0x57f (FPO: [3,5,4])

    00a0fea4 77c6e8db 00000000 000002bc 00000000 RPCRT4!OSF_SCALL::BeginRpcCall+0x194 (FPO: [2,0,4])

    00a0ff04 77c6e7b4 00000000 000c9370 000002bc RPCRT4!OSF_SCONNECTION::ProcessReceiveComplete+0x435 (FPO: [3,17,0])

    00a0ff18 77c7b799 0008cd68 0000000c 00000000 RPCRT4!ProcessConnectionServerReceivedEvent+0x21 (FPO: [7,0,0])

    00a0ff84 77c7b9b5 00a0ffac 77c8872d 0008cd68 RPCRT4!LOADABLE_TRANSPORT::ProcessIOEvents+0x1b8 (FPO: [0,15,0])

    00a0ff8c 77c8872d 0008cd68 00000000 00000000 RPCRT4!ProcessIOEventsWrapper+0xd (FPO: [1,0,0])

    00a0ffac 77c7b110 0008b120 00a0ffec 77e64829 RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [1,2,4])

    00a0ffb8 77e64829 001262f0 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [1,0,0])

    00a0ffec 00000000 77c7b0f5 001262f0 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

     

    Our first course of action was to install the latest and greatest netapi32.dll binary which cleared up the issue.

     

     

    I hope that helps!!

     

    Thanks and regards,

    Aman

  • Ntdebugging Blog

    LPC (Local procedure calls) Part 1 architecture

    • 5 Comments

     

    Hello, my name is Roy. I’m an Escalation Engineer in the CPR platforms team.  I’ll be doing a four part series on LPC over the coming month.  You’re sure to find this interesting. That being said let’s get started.

     

    Disclaimer: The purpose of this blog is to illustrate debugging techniques with LPC. Please do not rely on this information as documentation for the LPC APIs when writing your own code. As always, this is subject to change in the future. 

    What is LPC?

     

    LPC (Local Inter-Process Communication and NOT Local Procedure Calls) is a high speed message based communication mechanism implemented in the NT kernel. LPC can be used for communication between two user mode processes, between a user mode process and a kernel mode driver or between two kernel mode drivers.  One example would be two user mode processes communicating via LPC.  Like CSRSS.exe talking to SMSS.exe over SmssWinStationApiPort while creating a logon session or any process talking to LSASS.exe over LsaAuthenticationPort for security reasons. Another example of a user mode process communicating with a kernel mode driver would be KSecDD.sys talking to LSASS.exe for EFS key encryption and decryption during read/write of an encrypted file.

     

    LPC uses two different mechanisms for passing data between the client and the server process. It uses the LPC message buffer (for data size less than 304 bytes) or it uses a shared memory Section mapped to both client and server address space (for data size more than 304 bytes).

     

    Apart from being used as the protocol of choice of Remote Procedure Calls between processes running on the same system, LPC is also used throughout the system e.g. for Win32 Application’s communication with CSRSS.exe, Security Reference Monitor’s communication with LSASS, WinLogon’s communication with LSASS etc.

     

    LPC enforces synchronous communication model between the client and the server processes. Vista deprecates the use of LPC using a new mechanism called Asynchronous Local Inter-Process Communication (ALPC). ALPC has an inherent advantage over LPC in that all calls from client to the server are asynchronous i.e. the client does not need to block/wait for the server to respond to a message. In Vista, legacy application calls to LPC APIs are automatically redirected to the newer ALPC APIs.

     

     

    LPC APIs

     

    LPC APIs are native APIs i.e. they are exported in user mode by NTDLL.dll and in kernel mode by NTOSKRNL.exe. LPC APIs are not exposed at the Win32 level hence win32 applications cannot use the LPC facility directly. Win32 applications can however use LPC indirectly when using RPC by specifying LPC as its underling transport via the protocol sequence “ncalrpc”. All LPC APIs end in the word "Port" which implies an LPC communication endpoint.

     

    API

    Description

    NtCreatePort

    Used by server to create a connection port

    NtConnectPort

    Used by client to connect to a connection port

    NtListenPort

    Used by server to listen for connection requests on the connection port.

    NtAcceptConnectPort

    Used by server to accept connection requests on the connection port

    NtCompleteConnectPort

    Used by server to complete the acceptance of a connection request

    NtRequestPort

    Used to send a datagram message that does not have a reply

    NtRequestWaitReplyPort

    Used to send a message and wait for a reply

    NtReplyPort

    Used to send a reply to a particular message

    NtReplyWaitReplyPort

    Used to send a reply to a particular message and wait for a reply to a previous message

    NtReplyWaitReceivePort

    Used by server to send a reply to the client and wait to receive a message from the client

    NtImpersonateClientOfPort

    Used by server thread to temporarily borrow the security context of a client thread

     

     

    The following diagram illustrates the steps taken by an LPC server process to listen to inbound connection request from potential client and the steps taken by clients to connect to listening servers.

     

     

    Figure [1] LPC Client Server Connection Establishment Sequence

    NOTE: Many server processes use the NtReplyWaitReceivePort( ) API instead of NtListenPort( ). NtListenPort( ) drops all LPC messages except connection requests. Hence NtListenPort( ) can only be used for the first connection. For later connection requests NtReplyWaitReceivePort( ) is used.

     

    The following diagram illustrates the steps taken by an LPC client to send a request to an LPC server that is has already established a connection to and the steps taken by the server to responds to the message.

     

     

     

    Figure [2] LPC Client Server Data Transfer Sequence

     

     

    LPC Data Structures

     

     

    LPC Port Data Structure

     

    LPC endpoints are referred to as ports. LPC implementation uses the same port structure to represent the various types of ports. The ports used by LPC are Server Connection Ports which are named ports created by the server process to accept incoming connections from clients.  Client Communication Ports which are created by the client process to connect to a server process and Server Communication Port created by the server process.

     

    Relationships 

      

     

    Figure [3] LPC Port types and their relationships

     

     

    LPCP_PORT_OBJECT is the internal data structure used by LPC to represent a LPC port. LPCP_PORT_OBJECTs are allocated out of paged pool with the tag ‘Port’.

     

    kd> dt nt!_LPCP_PORT_OBJECT

       +0x000 ConnectionPort   : Ptr32 _LPCP_PORT_OBJECT

       +0x004 ConnectedPort    : Ptr32 _LPCP_PORT_OBJECT

       +0x008 MsgQueue         : _LPCP_PORT_QUEUE

       +0x018 Creator          : _CLIENT_ID

       +0x020 ClientSectionBase : Ptr32 Void

       +0x024 ServerSectionBase : Ptr32 Void

       +0x028 PortContext      : Ptr32 Void

       +0x02c ClientThread     : Ptr32 _ETHREAD

       +0x030 SecurityQos      : _SECURITY_QUALITY_OF_SERVICE

       +0x03c StaticSecurity   : _SECURITY_CLIENT_CONTEXT

       +0x078 LpcReplyChainHead : _LIST_ENTRY

       +0x080 LpcDataInfoChainHead : _LIST_ENTRY

       +0x088 ServerProcess    : Ptr32 _EPROCESS

       +0x088 MappingProcess   : Ptr32 _EPROCESS

       +0x08c MaxMessageLength : Uint2B

       +0x08e MaxConnectionInfoLength : Uint2B

       +0x090 Flags            : Uint4B

       +0x094 WaitEvent        : _KEVENT

     

     

    Field

    Description

    ConnectedPort

    Points to the Server Communication Port

    ConnectionPort

    Points to the Server Connection Port

    MsgQueue.Semaphore

    Used to signal the server thread about the presence of  a message in MsgQueue.ReceiveHead

    MsgQueue.ReceiveHead

    Head of a doubly linked list containing all the messages that are waiting to be dequeued by the server.

    MsgQueue.NonPagedPortQueue

    Points to the LPCP_NONPAGED_PORT_QUEUE structure for the client communication port for tracking lost replies.

    LpcReplyChainHead

    Head of a doubly linked list containing all the threads that are waiting for replies to messages sent to this port.

     

     

     

    LPC Message Data Structure

     

    LPC message are data structures that carry information from the LPC client to the LPC server and can be of various types like connection, request, close etc.

     

    LPCP_MESSAGE is the internal data structure used by LPC to represent a message. LPCP_MESSAGE structures are allocated from a system wide lookaside list with the tag ‘LpcM’.

     

    kd> dt nt!_LPCP_MESSAGE

       +0x000 Entry            : _LIST_ENTRY

       +0x000 FreeEntry        : _SINGLE_LIST_ENTRY

       +0x004 Reserved0        : Uint4B

       +0x008 SenderPort       : Ptr32 Void

       +0x00c RepliedToThread  : Ptr32 _ETHREAD

       +0x010 PortContext      : Ptr32 Void

       +0x018 Request          : _PORT_MESSAGE

     

     

    Field

    Description

    Request.MessageId

    Generated from the value of a global epoch LpcpNextMessageId. Used to uniquely identify a message.

    SenderPort

    Points to the LPCP_PORT_OBJECT of the client communication port

    Entry

    Is the list entry that is used to queue the message to the Server Communication/Connection Port’s MsgQueue.ReceiveHead

    Request

    Is a copy of the message buffer that was provided as the Request parameter to the call to NtRequestWaitReplyPort() or a copy the message buffer that was provided as the Reply parameter to NtReplyWaitRecivePortEx().

     

     

    LPC related fields in Thread Data Structure

     

    kd> dt nt!_ETHREAD -y Lpc

       +0x1c8 LpcReplyChain : _LIST_ENTRY

       +0x1f4 LpcReplySemaphore : _KSEMAPHORE

       +0x208 LpcReplyMessage : Ptr32 Void

       +0x208 LpcWaitingOnPort : Ptr32 Void

       +0x228 LpcReceivedMessageId : Uint4B

       +0x23c LpcReplyMessageId : Uint4B

       +0x250 LpcReceivedMsgIdValid : Pos 0, 1 Bit

       +0x250 LpcExitThreadCalled : Pos 1, 1 Bit

     

    The following table describes the fields of the ETHREAD data structure that are used for communication between LPC Client and Server process.

     

     

    Field

    Description

    LpcReplyMessageId

    Contains the ID of the message sent to the server while the client thread is waiting on the response.

    LpcWaitingOnPort

    Used by the LPC Client Thread to stores the LPC client communication port on which it is waiting for a reply.

    LpcReplySemaphore

    Used to block the LPC Client Thread while the server is processing the LPC message.

    LpcExitThreadCalled

    Used by the Lpc APIs to determine if the thread is currently in the process of exiting and if so returns STATUS_THREAD_IS_TERMINATING from the API call.

    LpcReplyChain

    Used to queue the thread to the list of threads waiting for replies from the server communication/connection port. The list head of this list is in LPCP_PORT_OBJECT->LpcReplyChainHead.

     

     

     

    Important global LPC connection ports

     

    Field

    Description

    LsaAuthenticationPort

     Used for the following tasks:

    1. Security package management like Kerberos, NTLM etc…
    2. Credential management
    3. User Account management
    4. EFS (Encrypted File System) key encryption, decryption

     

    SmssWinStationApiPort

     

     This port is used by the CSRSS to manage Window Stations i.e. multiple sessions.

     

    ErrorLogPort

     

     This port is used by IO manager and other components to send error log entries to the EventLog service.

     

     

     

     

    Important LPC port fields in the Process

    (nt!_EPROCESS)

     

    Field

    Description

    SecurityPort

    LSA uses this port for EFS (encrypted file system) and authentication.

     

    ExceptionPort

     When a thread does not catch an exception an LPC_EXCEPTION message is sent to this port. A subsystem might register an LPC port in this field to receive second chance exception information of process running in the subsystem. Default action of CSRSS is to terminate the process.

     

    DebugPort

     The kernel dispatches user mode exceptions to the process debugger on this port. Debug outputs using OutputDebugString( ) are passed to this port as DBG_PRINTEXCEPTION_C.

     

     

     

     

    Important LPC port fields in the Thread

    (nt!_ETHREAD)

     

    Field

    Description

    TerminationPort

    This is not a single port rather a chain of ports registered with the Process Manager. The process manager notifies all ports when the thread terminates.

     

    LpcWaitingOnPort

    This field has the address of the client communication port when the client thread waits for a reply to a LPC message from a server thread.

     

     

     

     

    Stay tuned...in the next post we will roll our sleeves up and dig into the debug extensions for LPC and some common states where  you may find these calls stuck.

     

  • Ntdebugging Blog

    Remote Debugging connecting to a Remote Stub using the Microsoft Debugging Tools for Windows

    • 3 Comments

    The Microsoft Debugging Tools for Windows provide a couple ways to create a remote debugging connection including "Connecting to a remote session" and "Connecting to a remote stub". Connecting to a remote session is the most commonly used of the two, and is all you typically need, but it does not allow the client to access debugging symbols missing on the remote.

    Jeff’s blog post here has more information on some of the intricacies of debugging a remote session. Often a remote debugging session will be done within a corporate network where all users have access to symbol information, but if we are debugging outside of the secure environment where we cannot share symbols freely, debugging becomes more difficult .

    The Microsoft debugging tools package has two server side command line applications to help us do this by connecting to a remote stub: Dbgsrv.exe for user mode debugging and Kdsrv.exe for kernel mode debugging. They provide a thin server layer for the debugger to attach with full use of local symbols and source code.

    Conventional remote debug session

    Let’s illustrate the benefits of using remote stubs by showing the problems encountered when connecting to a remote session. 

     image_thumb[1][5]

    This diagram shows the conventional remote debug session. Both the debugging host and target are running windbg, though we could use KD or CDB. The goal is to debug a buggy application called Getif.exe which runs on the debugging target. We have symbols for the application on the debugging host however for security reasons the debugging target does not have symbol access to Getif.exe. On both machines we have Windows internet symbols loaded from the http://msdl.microsoft.com/download/symbols.

     

    Here is the symbol path on the debugging target machine. Because this system is outside our secure environment it does not have symbol access for the Getif.exe application. This will be problematic for debugging.

    clip_image008[4]_thumb[1][5]

     

    Here is the symbol path on the debugging host which includes a path to the symbols for the application because it’s inside the secure location.

    clip_image010[4]_thumb[1]

     

    To create the remote debugging server on the target machine, I specify the local port to use for the connection by using the .server command:

    .server tcp:port=<localport>

    clip_image012[4]_thumb[1]

     

    Next I select “Connect to Remote Session” on the debugging host.

    clip_image014[4]_thumb[1]

     

    Then enter the port and server name:

    clip_image016[4]_thumb[1]

     

    And this is where we run into the headache! Because we don’t have Getif.exe symbol access on the machine located outside of the secure environment, the stacks for getif.exe don’t display symbolic information. It makes it hard to debug the application because we can’t dump data types or view other symbolic info.

    clip_image018[4]_thumb[1]

    If we want to debug Getif.exe with symbols, we need to copy the symbol files to the debug target machine and add the location to the target’s symbol path. In our scenario this may not be possible because symbols are often restricted to in-house use and not allowed to be copied freely.

     

     

    Dbgsrv to the rescue!!

    image_thumb[3]

    By activating Dbgsrv on the debugging target machine, the debugger on the debugging host connects with full symbol access to the user mode process on the target. The diagram above illustrates the process.

    Let's run through an example using dbgsrv on the debugging target. On the debugging target enter

     <path to debugging tools>\dbgsrv -t tcp:port=<localport>

    Dbgsrv returns to a command prompt with no output in the command window and the debug port can be any open port on the system. It’s a good idea to confirm we are listening on the port we selected by using netstat. Here’s an example -  

    clip_image020[4]_thumb[1]

    Now let’s move our focus to the debugging host computer. Instead of choosing the typical “Connect a Remote Session”, we use the option, “Connect to a Remote Stub” from the File menu.

    clip_image022[4]_thumb[1]

    Next enter the port and server name.

    clip_image024[4]_thumb[1]

    After selecting OK, we are back to the empty Command window as expected. We won’t see any text until connected to the target process:

    clip_image026[4]_thumb[1]

    Next select File-Attach to a Process option.

    clip_image028[4]_thumb[1]

    It is important to note the “Attach to Process” dialog shows the list of processes running on the debugging target machine.

    clip_image030[4]_thumb[1]

    Now let’s attach to the process. The title bar confirms that we connected to the process on the kdsrv target:

    clip_image032[4]_thumb[1]

    Here you can see the benefit of connecting with a remote stub. The symbols for getif.exe are working for the application running on a machine located outside of the secure environment.

    clip_image034[4]_thumb[1]

     

     

    But what if I need to Kernel debug?

    You can do the same thing with Kernel debugging using Kdsrv.

    image_thumb[5]

    If we need to attach to a kernel debugger we can use kdsrv. Much like the previous example we enter the command:

    kdsrv -t tcp:port=<localport>

    We can see that we are listening on the local port we selected:

    clip_image036[4]_thumb[1]

    We must now start our debugger on the debugging host machine with a command line that includes the information needed to connect to the KdSrv host. As of Windbg 6.10.3.233 we cannot attach to the kdsrv remote stub from the Windbg graphical interface and then make the kernel connection to the debugging target .

    clip_image038[4]_thumb[1]

    Here is the string I used in the graphic above-

    windbg -k kdsrv:server=@{tcp:server=rodolpho,port=5004},trans=@{com:pipe,port=\\mimi\pipe\2008target}

    Note that we are debugging to a named pipe on a kernel debug target running under Microsoft Hyper-V! This is a great way to debug without the hassle of setting up a second machine and attaching with a null modem cable.

    If we wanted to attach to COM1 with a null-modem cable we would use:

    windbg -k kdsrv:server=@{tcp:server=rodolpho,port=5004},trans=@{com:port=com1,baud=11500}

    For more information on client and server syntax see http://msdn.microsoft.com/en-us/library/cc266440.aspx.

    After Windbg starts the command window will look just like if we attached with a local debugger. The title bar will confirm that we are attaching through the debug server:

    clip_image040[4]_thumb[1]

    We can also change context to the Getif.exe process after connecting to the remote stub. When we look at the application stack we have symbols for our application:

    clip_image042[4]_thumb[1]

    After we have our remote stub connection, we can then share our client as a remote session, but we will always handle the symbols on the remote stub client.

    Once you setup a remote stub a couple of times it’s as simple as setting up a remote session, and can make a remote debug go a lot smoother. For more information check out the debugging tools help, available outside of windbg as debugger.chm in the debugger directory, as well as http://msdn.microsoft.com/en-us/library/cc266434.aspx

    Security Note: These examples use TCP/IP or named pipes and are not password protected. The debugger remotes will allow SSL and Secure pipe connections with password and certificate authentication if you require greater security. See the online help or this link for more information.

  • Ntdebugging Blog

    Determining the source of Bug Check 0x133 (DPC_WATCHDOG_VIOLATION) errors on Windows Server 2012

    • 2 Comments

    What is a bug check 0x133?

    Starting in Windows Server 2012, a DPC watchdog timer is enabled which will bug check a system if too much time is spent in DPC routines. This bug check was added to help identify drivers that are deadlocked or misbehaving.  The bug check is of type "DPC_WATCHDOG_VIOLATION" and has a code of 0x133.  (Windows 7 also included a DPC watchdog but by default, it only took action when a kernel debugger was attached to the system.)  A description of DPC routines can be found at http://msdn.microsoft.com/en-us/library/windows/hardware/ff544084(v=vs.85).aspx.

     

    The DPC_WATCHDOG_VIOLATION bug check can be triggered in two ways. First, if a single DPC exceeds a specified number of ticks, the system will stop with 0x133 with parameter 1 of the bug check set to 0.  In this case, the system's time limit for single DPC will be in parameter 3, with the number of ticks taken by this DPC in parameter 2.  Alternatively, if the system exceeds a larger timeout of time spent cumulatively in all DPCs since the IRQL was raised to DPC level, the system will stop with a 0x133 with parameter 1 set to 1.  Microsoft recommends that DPCs should not run longer than 100 microseconds and ISRs should not run longer than 25 microseconds, however the actual timeout values on the system are set much higher.

     

    How to debug a 0x133 (0, …

    In the case of a stop 0x133 with the first parameter set to 0, the call stack should contain the offending driver.  For example, here is a debug of a 0x133 (0,…) kernel dump:

     

    0: kd> .bugcheck

    Bugcheck code 00000133

    Arguments 00000000`00000000 00000000`00000283 00000000`00000282 00000000`00000000  

     

    Per MSDN, we know that this DPC has run for 0x283 ticks, when the limit was 0x282.

     

    0: kd> k

    Child-SP          RetAddr           Call Site

    fffff803`08c18428 fffff803`098525df nt!KeBugCheckEx

    fffff803`08c18430 fffff803`09723f11 nt! ??::FNODOBFM::`string'+0x13ba4

    fffff803`08c184b0 fffff803`09724d98 nt!KeUpdateRunTime+0x51

    fffff803`08c184e0 fffff803`09634eba nt!KeUpdateTime+0x3f9

    fffff803`08c186d0 fffff803`096f24ae hal!HalpTimerClockInterrupt+0x86

    fffff803`08c18700 fffff803`0963dba2 nt!KiInterruptDispatchLBControl+0x1ce

    fffff803`08c18898 fffff803`096300d0 hal!HalpTscQueryCounter+0x2

    fffff803`08c188a0 fffff880`04be3409 hal!HalpTimerStallExecutionProcessor+0x131

    fffff803`08c18930 fffff880`011202ee ECHO!EchoEvtTimerFunc+0x7d                //Here is our driver, and we can see it calls into StallExecutionProcessor

    fffff803`08c18960 fffff803`097258b4 Wdf01000!FxTimer::TimerHandler+0x92

    fffff803`08c189a0 fffff803`09725ed5 nt!KiProcessExpiredTimerList+0x214

    fffff803`08c18ae0 fffff803`09725d88 nt!KiExpireTimerTable+0xa9

    fffff803`08c18b80 fffff803`0971fe76 nt!KiTimerExpiration+0xc8

    fffff803`08c18c30 fffff803`0972457a nt!KiRetireDpcList+0x1f6

    fffff803`08c18da0 00000000`00000000 nt!KiIdleLoop+0x5a

     

    Let’s view the driver’s unassembled DPC routine and see what it is doing

     

    0: kd> ub fffff880`04be3409

    ECHO!EchoEvtTimerFunc+0x54:

    fffff880`04be33e0 448b4320        mov     r8d,dword ptr[rbx+20h]

    fffff880`04be33e4 488b0d6d2a0000  mov     rcx,qword ptr [ECHO!WdfDriverGlobals (fffff880`04be5e58)]

    fffff880`04be33eb 4883631800      and     qword ptr [rbx+18h],0

    fffff880`04be33f0 488bd7          mov     rdx,rdi

    fffff880`04be33f3 ff150f260000    call    qword ptr [ECHO!WdfFunctions+0x838(fffff880`04be5a08)]

    fffff880`04be33f9 bbc0d40100      mov     ebx,1D4C0h

    fffff880`04be33fe b964000000      mov     ecx,64h

    fffff880`04be3403 ff15f70b0000    call    qword ptr[ECHO!_imp_KeStallExecutionProcessor (fffff880`04be4000)]   //Its Calling KeStallExecutionProcessor with 0x64 (decimal 100) as a parameter

    0: kd> u fffff880`04be3409

    ECHO!EchoEvtTimerFunc+0x7d:

    fffff880`04be3409 4883eb01        sub     rbx,1

    fffff880`04be340d 75ef            jne     ECHO!EchoEvtTimerFunc+0x72 (fffff880`04be33fe)     //Here we can see it is jumping back to call KeStallExecutionProcessor in a loop

    fffff880`04be340f 488b5c2430      mov     rbx,qword ptr[rsp+30h]

    fffff880`04be3414 4883c420        add     rsp,20h

    fffff880`04be3418 5f              pop     rdi

    fffff880`04be3419 c3              ret

    fffff880`04be341a cc              int     3

    fffff880`04be341b cc              int     3

     

    0: kd> !pcr

    KPCR for Processor 0 at fffff80309974000:

        Major 1 Minor 1

          NtTib.ExceptionList: fffff80308c11000

              NtTib.StackBase: fffff80308c12080

             NtTib.StackLimit: 000000d70c7bf988

           NtTib.SubSystemTib: fffff80309974000

                NtTib.Version: 0000000009974180

            NtTib.UserPointer: fffff803099747f0

                NtTib.SelfTib: 000007f7ab80c000

     

                      SelfPcr: 0000000000000000

                         Prcb: fffff80309974180

                         Irql: 0000000000000000

                          IRR: 0000000000000000

                          IDR: 0000000000000000

                InterruptMode: 0000000000000000

                          IDT: 0000000000000000

                          GDT: 0000000000000000

                          TSS: 0000000000000000

     

                CurrentThread: fffff803099ce880

                   NextThread: fffffa800261cb00

                   IdleThread: fffff803099ce880

     

                    DpcQueue:  0xfffffa80020ce790 0xfffff880012e4e9c [Normal] NDIS!NdisReturnNetBufferLists

                               0xfffffa800185f118 0xfffff88000c0ca00 [Normal] ataport!AtaPortInitialize

                               0xfffff8030994fda0 0xfffff8030972bc30 [Normal] nt!KiBalanceSetManagerDeferredRoutine

                               0xfffffa8001dbc118 0xfffff88000c0ca00 [Normal] ataport!AtaPortInitialize

                               0xfffffa8002082300 0xfffff88001701df0 [Normal] USBPORT

     

    The !pcr output shows us queued DPCs for this processor. If you want to see more information about DPCs and the DPC Watchdog, you could dump the PRCB listed in the !pcr output like this:

     

    dt nt!_KPRCB fffff80309974180 Dpc*

     

    Often the driver will be calling into a function like KeStallExecutionProcessor in a loop, as in our example debug.  To resolve this problem, contact the driver vendor to request an updated driver version that spends less time in its DPC Routine.

     

    How to troubleshoot a 0x133 (1, …

    Determining the cause of a stop 0x133 with a first parameter of 1 is a bit more difficult because the problem is a result of DPCs running from multiple drivers, so the call stack is insufficient to determine the culprit.  To troubleshoot this stop, first make sure that the NT Kernel Logger or Circular Kernel Context Logger ETW traces are enabled on the system.  (For directions on setting this up, see http://blogs.msdn.com/b/ntdebugging/archive/2009/12/11/test.aspx.)

     

    Once the logging is enabled and the system bug checks, dump out the list of ETW loggers using !wmitrace.strdump. Find the ID of the NT Kernel logger or the Circular logger.  You can then use !wmitrace.logsave (ID) (path to ETL) to write out the ETL log to a file.  Load it up with Windows Performance Analyzer and add the DPC or DPC/ISR Duration by Module, Function view (located in the Computation group) to your current analysis window:

     

     

    Next, make sure the table is also shown by clicking the box in the upper right of the view:

     

     

    Ensure that the Address column is added on the left of the gold bar, then expand each address entry to see individual DPC enters/exits for each function.  Using this data, you can determine which DPC routines took the longest by looking at the inclusive duration column, which should be added to the right of the gold bar: 

     

    In this case, these DPCs took 1 second, which is well over the recommended maximum of 100 us.  The module column (and possible the function column, if you have symbols) will show which driver is responsible for that DPC routine.  Since our ECHO driver was based on WDF, that is the module named here.

     

    For an example of doing this type of analysis in xperf, see http://blogs.msdn.com/b/ntdebugging/archive/2008/04/03/windows-performance-toolkit-xperf.aspx.

     

    More Information

    For additional information about Stop 0x133 errors, see this page on MSDN: http://msdn.microsoft.com/en-us/library/windows/hardware/jj154556(v=vs.85).aspx.

     

    For DPC timing recommendations and for advice on capturing DPC timing information using tracelog, see http://msdn.microsoft.com/en-us/library/windows/hardware/ff545764(v=vs.85).aspx.

     

    Guidelines for writing DPC routines can be found at http://msdn.microsoft.com/en-us/library/windows/hardware/ff546551(v=vs.85).aspx.

     

     

    -Matt Burrough

  • Ntdebugging Blog

    Bcdedit Tips and Tricks For Debugging Part 1

    • 6 Comments

    Hello everyone, my name is Sean Walker, and I am on the Platforms OEM team in Washington.  This article is for those people who have had a hard time switching from the old boot.ini configuration to the new BCD store (myself included). Doing the simple tasks such as enabling kernel debugging over com1 are easy to do with bcdedit.exe or the msconfig GUI, you just enable them and reboot the computer. However, if you need to do something more advanced such as break into the early boot process during resume from hibernation, things get a lot more complicated.

     

    This article has some samples for enabling and disabling debug settings that you may not be familiar with, and a list of bcdedit debug settings for Windows Vista/Server 2008 and Windows 7/Server 2008 R2.  This information has been helpful to me for quickly and accurately getting to the debug at hand rather than fumbling around with bcdedit.  Much of the following information has been taken from various sources, including the windbg help files, the OEM team blog, the MSDN bcdedit reference, and the WHDC debugger site.

     

    NOTE: For the examples below, you will need to run bcdedit.exe from an administrator (UAC-elevated) command prompt.  To output a summary view of the current state of the BCD store, just run "bcdedit.exe" from the command prompt.  To get detailed information about all of the store(s) that Windows knows about, use the following command:

    bcdedit /enum all

     

    What is a BCD store?

    A BCD store is a binary file that contains boot configuration data for Windows, basically it is a small registry file.  Boot applications use the system BCD store, located on the system partition, during the boot process.  You can also create additional BCD stores in separate files but only one store at a time can be designated as the system store.

     

    NOTE: The "/store" switch can be used to specify a particular BCD store for bcdedit commands (instead of the default store).  To enumerate all the settings in another BCD store, in this case e:\bcd_store\BCD, use the following command:

    bcdedit /store e:\bcd_store\BCD /enum all

     

    This will show you which options are currently set, and what their values are.  When /store switch is omitted, the system store is used.

     

    Using bootdebug

    To enable debugging for early boot problems, you may need to enable the bootdebug switch.  This is easy to do with bcdedit:

    bcdedit /set bootdebug on

     

    However, this only sets bootdebug for the current "boot application", which is generally winload.exe, so it does not break into the very early boot process.  There are multiple applications used for booting, hibernating, and resuming (bootmgr.exe, winload.exe and winresume.exe are examples of these).  Each application (called BCD Objects) has its own settings (called BCD Elements) in the BCD store and each can be modified globally and/or individually.

     

    So, to deal with different (or multiple) debug scenarios, you just enable boot debugging based on the boot application you are concerned with.  For early debugging, you can enable bootdebug for bootmgr:

    bcdedit /set {bootmgr} bootdebug on

     

    To set bootdebug for winload.exe (which will most often be your current, and default, boot object) all three of the following will give you the same result:

    bcdedit /set bootdebug on

    bcdedit /set {current} bootdebug on

    bcdedit /set {default} bootdebug on

     

    If you are modifying the settings in another store, or are booted into another OS on the same computer (such as WinPE), you need to specify the location of the BCD store:

    bcdedit /store d:\Boot\BCD /set {default} bootdebug on

     

    Not all of the boot objects have "friendly" names, so you may need to specify the full GUID (Globally Unique ID) to modify it.  As an example, if you wanted to enable bootdebug on resume from hibernation, you would include the identifier (see figure 1) for the "Resume from Hibernate" object:

    bcdedit /set {89a932d0-d5bc-11e0-a0af-00215add5ebc} bootdebug on

     

    image001

    Figure 1: Color coded bcdedit output

     

    Why won't my USB or 1394 debug work?

    When there are multiple debug ports of a certain type in a computer Windows may not default to the correct one for your situation.  This happens most commonly when there are either multiple 1394 host controllers or USB EHCI controllers.  When this occurs it can range from a slight inconvenience (different port is used so the cable needs to be plugged into another port), to complete failure (internal port is used, which is not accessible).  In the case of USB debugging the Intel USB 2.0 specification only provides one debug port, so debugging is not possible if the wrong host controller is used.

     

    There are several caveats with USB debugging, not the least of which is that you need to buy a separate, expensive, debug cable.  Some of the difficulties and implementation details necessary to get USB debugging to work are encompassed in the WHDC USB FAQ and in Setting Up Kernel Debugging with USB 2.0.

     

    NOTE: A correction to the WHDC USB documentation for Windows 7/Windows 2008 R2 is that the busparams switch now takes decimal rather than hexadecimal values, and the "loadoptions" parameter is no longer required.  So, to enable the busparams element (for USB or 1394 debugging) in Vista/2008, you would use something like this:

    bcdedit /set {current} loadoptions busparams=0.1D.7

     

    And the Win7/2008 R2 example would be:

    bcdedit /set {current} busparams 0.29.7

     

    In the case of loadoptions or busparams, deleting the setting is not as easy as changing a flag from yes to no. You must specifically delete the value to get rid of it, and one of the examples below can be used:

     

    For Vista/2008:

    bcdedit /deletevalue {current} loadoptions

     

    And Windows 7/2008 R2:

    bcdedit /deletevalue {current} busparams

     

    Bcdedit settings and examples

    This is just scratching the surface of using bcdedit for your troubleshooting and/or debugging needs, so there are more articles to follow. Part 2 will include some more detailed debugging scenarios, such as Hyper-V guest and host debugging.  Below is a consolidated table with many of the debugging switches/settings as well as a number of different usage examples.

     

    Table of debug-related bcdedit settings

    Option

    Description

    bootdebug

    Enables or disables the boot debugger for a specified boot entry. Although this command works for any boot entry, it is effective only for boot applications.

    Enable value(s): on, 1

    Disable value(s): off, 0

    Bcdedit /set bootdebug on

    debug

    Enables or disables the kernel debugger for a specified boot entry.

    Enable value(s): on, 1

    Disable value(s): off, 0

    /dbgsettings

    Used to modify the global settings for the debug connection (does not include hypervisor).  Values:

    Can change all settings at once instead of using the /set command to change them individually. Usage example:

    bcdedit /dbgsettings 1394 channel:30

    debugport

    Used to specify the debugger type.

    Values:

    Serial port – com1, com2, comx

    1394 port – 1394

    USB port - USB

    channel

    Specifies 1394 channel used.

    Values:

    Decimal integer between 0 and 62, inclusive.

    baudrate

    Used to specify the baud rate of a serial debug port.

    Values: 9600, 19200, 38400, 57600, 115200

    targetname

    Specifies a string to use as the identification for the USB 2.0 connection. This string can be any value.

    Usage example:

    bcdedit /dbgsettings usb targetname:usbdebug

    /hypervisorsettings

    Used the same way as /dbgsettings to configure all settings at once.

    Usage example:

    bcdedit /hypervisorsettings 1394 channel:10

    hypervisordebug

    Enables or disables hypervisor debug mode. This is for debugging a Hyper-V host system.

    Enable value(s): on, 1

    Disable value(s): off, 0

    Usage example:

    bcdedit /set {current} hypervisordebug on

    /noumex

    Specifies that the kernel debugger ignores user-mode exceptions. By default, the kernel debugger breaks for certain user-mode exceptions, such as STATUS_BREAKPOINT and STATUS_SINGLE_STEP. The /noumex parameter is effective only when there is no user-mode debugger attached to the process.

    /start

    This option specifies the debugger start policy. If a start policy is not specified, ACTIVE is the default.

    Values: active, disable, autoenable

    loadoptions

    Used to describe settings that are not covered by other types. One setting that is relevant here is busparams.

    Values: Any value followed by the setting.

    Usage example (Vista/2008):

    bcdedit /set {current} loadoptions busparams=0.1d.0

    busparams

    A boot setting (specified with loadoptions key word) used to point to the PCI address of the debugger in use. The PCI bus, device, and function are used, in the format bb.dd.ff. This is generally used to identify the location of a 1394 or USB debug port. In Vista/2008, hexadecimal values are used, whereas decimal values are used for Win7.

    Values: Decimal values between 0 and 255.

    Usage example:

    In Win7 - bcdedit /set busparams 0.29.0

    In Vista - bcdedit /set loadoptions busparams=0.1d.0

    kernel

    The loadoptions parameter used to point to a different kernel binary. This can be used to test with a checked or instrumented version of the kernel without replacing the existing one. The updated binary MUST be placed in the %windir%\system32 folder to be used

    Values: The 8.3 filename of the replacement kernel include the exe extension.

    Usage examples:

    In Win7 – bcdedit /set kernel kernchk.exe

    In Vista - bcdedit /set loadoptions kernel=kernchk.exe

    hal

    The loadoptions parameter used to point to a different hal binary. This can be used to test with a checked or instrumented version of the kernel without replacing the existing one. The updated binary MUST be placed in the %windir%\system32 folder to be used

    Values: the 8.3 filename of the replacement kernel include the .dll extension.

    Usage examples:

    In Win7 – bcdedit /set hal halchk.dll

    In Vista - bcdedit /set loadoptions hal=halchk.dll

    testsigning

    Controls whether Windows 7, Windows Server 2008, or Windows Vista will load any type of test-signed kernel-mode code. This option is not set by default, which means test-signed kernel-mode drivers on 64-bit versions of Windows 7, Windows Server 2008, and Windows Vista will not load without setting the testsigning switch

    Enable value(s): on, 1

    Disable value(s): off, 0

    Usage example:

    Bcdedit /set testsigning on

     

  • Ntdebugging Blog

    Missing System Writer Case Explained

    • 6 Comments

    I worked on a case the other day where all I had was a procmon log and event logs to troubleshoot a problem where the System Writer did not appear in the VSSADMIN LIST WRITERS output. This might be review for the folks that know this component pretty well but I figured I would share how I did it for those that are not so familiar with the System Writer.

     

    WHAT WE KNOW:

    1. System State Backups fail
    2. Running a VSS List Writers does not list the system writer

     

    Looking at the event logs I found the error shown below. This error indicates there was a failure while “Writer Exposing its Metadata Context”. Each writer is responsible for providing a list of files, volumes, and other resources it is designed to protect. This list is called metadata and is formatted as XML. In the example we are working with the error is “Unexpected error calling routine XML document is too long”.  While helpful, this message alone does not provide us with a clear reason why the XML document is too long.

     

    Event Type: Error

    Event Source: VSS

    Event ID: 8193

    Description: Volume Shadow Copy Service error: Unexpected error calling routine XML document is too long. hr = 0x80070018, The program issued a command but the command length is incorrect. . Operation: Writer Exposing its Metadata Context: Execution Context: Requestor Writer Instance ID: {636923A0-89C2-4823-ADEF-023A739B2515} Writer Class Id: {E8132975-6F93-4464-A53E-1050253AE220} Writer Name: System Writer

     

    The second event that was logged was also not very helpful as it only indicates that the writer did have a failure. It looks like we are going to need to collect more data to figure this out.

     

    Event Type: Error

    Event Source: VSS

    Event ID: 8193

    Description: Volume Shadow Copy Service error: Unexpected error calling routine CreateVssExamineWriterMetadata. hr = 0x80042302, A Volume Shadow Copy Service component encountered an unexpected error. Check the Application event log for more information. . Operation: Writer Exposing its Metadata Context: Execution Context: Requestor Writer Instance ID: {636923A0-89C2-4823-ADEF-023A739B2515} Writer Class Id: {E8132975-6F93-4464-A53E-1050253AE220} Writer Name: System Writer

     

    From the error above we learned that there was an issue with the metadata file for the System Writer. These errors are among some of the most common issues seen with this writer. There are some not so well documented limitations within the writer due to some hard set limits on path depth and the number of files in a given path. These limitations are frequently exposed by the C:\Windows\Microsoft.Net\ path. Often, this path is used by development software like Visual Studio as well as server applications like IIS. Below I have listed a few known issues that should help provide some scope when troubleshooting System Writer issues.

     

    Known limitations and common points of failure:

    • More than 1,000 folders in a folder causes writer to fail during OnIdentify
    • More than 10,000 files in a folder causes writer to fail during OnIdentify (frequently C:\Windows\Microsoft.Net)
    • Permissions issues (frequently in C:\Windows\WinSXS and C:\Windows\Microsoft.Net)
    • Permissions issues with COM+ Event System Service
      • This service needs to be running and needs to have Network Service with Service User Rights

     

    What data can I capture to help me find where the issue is?

     

    The best place to start is with a Process Monitor (Procmon) capture. To prepare for this capture you will need to download Process Monitor, open the Services MMC snap-in, as well as open an administrative command prompt which will be used in a later step of the process.

     

    You should first stop the Cryptographic Services service using the Services MMC.

     

     

    Once stopped you will want to open Procmon, note that by default Procmon will start capturing when opened. Now that you have Procmon open and capturing data you will start the cryptographic service. This will allow you to capture any errors during service initialization. Once the service is started you will use the command prompt opened earlier to run “vssadmin.exe list writers”. This will signal the writers on the system to capture their metadata, which is a common place we see failures with the System Writer. When the vssadmin command completes, stop the Procmon capture and save this data to disk.

     

    Now that we have data how do we find the errors?

     

    Open your newly created Procmon file. First, add a new filter for the path field that contains “VSS\Diag”.

     

     

    We do this because this is the registry path that all writers will log to when entering and leaving major functions. Now that we have our filtered view we need to look for an entry from the System Writer. You can see the highlighted line below shows the “IDENTIFY” entry for the System Writer. From here we can ascertain the PID of the svchost.exe that the system writer is running in. We now want to include only this svchost. To accomplish this you can right click on the PID for the svchost.exe and select “Include ‘(PID)’”. 

     

     

    Now that we have found our System Writers svchost we will want to remove the filter for “VSS\Diag”; to do that you can return to the filter tool in Procmon and uncheck the box next to the entry.

     

     

    We now have a complete view of what this service was doing at the time it started and completed the OnIdentify. Our next step is to locate the IDENTIFY (Leave) entry as this is often a great marker for where your next clue will be. While in most cases we can’t directly see the error the writer hit we can make some educated connections based on the common issues we spoke about above. If we take a look at the events that took place just before the IDENTIFY (Leave) we can see that we were working in the C:\Windows\Microsoft.NET\assembly\ directory. This is one of the paths that the System Writer is responsible for protecting. As mentioned above, there are some known limitations to the depth of paths and number of files in the “C:\Windows\Microsoft.NET” folder. This is a great example of that limitation as seen in our procmon capture. The example below shows the IDENTIFY (Leave) with the line before that being where the last work was taking place. Meaning this is what the writer was touching when it failed.

     

     

    What does this tell us and what should we do next?

     

    Given the known path limitations, we need to check out the number of files and folders in the C:\Windows\Microsoft.Net\ path and see where the bloat is. Some of these files can be safely removed, however only files located in the Temp locations (Temporary ASP.NET Files) are safe to delete.

     

    Recently we released KB2807849 which addresses the issue shown above.

     

    There are other possible causes of the event log errors mentioned above, such as issues with file permissions. For those problems follow the same steps as above and you are likely to see the IDENTIFY (Leave) just after file access error is displayed in your procmon log. For these failures you will need to investigate the permissions on the file we failed on. Likely the file is missing permissions for the writer’s service account Network Service or Local System. All that is needed here is to add back the missing permissions for your failed file.

     

    While these issues can halt your nightly backups, it is often fairly easy to find the root cause. It just takes time and a little bit of experience with Process Monitor. 

     

    Good luck and successful backups!

  • Ntdebugging Blog

    The default interactive desktop heap size has been increased on 32-bit Vista SP1

    • 5 Comments

     

    This is going to be a short blog post, but considering the amount of feedback we’ve received on the our two previous desktop heap posts, I think this is worth blogging about.  32-bit Vista SP1 and 32-bit Windows Server 2008 both have a new value for the default size of interactive desktop heaps.  Previously, this heap size was 3 MB by default, but on Vista SP1 and Server 2008 the default interactive heap size is 12 MB.  We��ve heard your comments about the problems associated with the heap size, and this new default size should go a long way towards avoiding interactive desktop heap depletion.

     

    On 32-bit systems, running Vista SP1 or Windows Server 2008, you’ll now see that the relevant portion of the registry value looks like this (by default)...

     

    HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\Session Manager\SubSystems\Windows

    SharedSection=1024,12288,512

     

    64-bit Windows still has a default interactive desktop heap size of 20MB.  Keep in mind that in Vista, session view space (the memory range that desktop heaps are allocated from) is now a dynamic address range.  This means that in Vista and Server 2008 the individual desktop heap sizes can be increased to larger sizes with less concern over exhausting session view space.

     

    - Matthew Justice

Page 4 of 25 (242 items) «23456»