• Ntdebugging Blog

    LPC CASE2 – When things are not rosy

    • 1 Comments

    Hello, this is Roy again.  In this case we will discuss a scenario where tracing a hung client thread is not possible through LPC data structures and extensions. We would rather use hints from the LPC message sent about the operation that was taking place and other heuristics to arrive at possible reason for the hang.

     

    The issue is that whenever an Encrypted File is opened the server locks up. The initial analysis is to determine the reason for the server hang, whether it is low resource condition, deadlock or any other reason. After dumping all the threads and glancing over them I chose to pickup the following thread which looked interestingly abnormal. Below is the thread which is trying to do a CreateFile( ) and is stuck for 4hrs for a LPC reply. The file attempted to be created is an encrypted file. KSecDD.sys is the Kernel Security Device Driver which is used for handling key encryption, decryption tasks. In order to decrypt the file KSecDD makes a LPC request to LsaAuthenticationPort.

     

    2: kd> !thread fffffade6c9f1390

    THREAD fffffade6c9f1390  Cid 04b4.0790  Teb: 000007fffffd8000 Win32Thread: fffffa8008ed1d80 WAIT: (WrLpcReply) KernelMode Non-Alertable

        fffffade6c9f1710  Semaphore Limit 0x1

    Waiting for reply to LPC MessageId 01561d96:

    Current LPC port fffffa800380cc40

    IRP List:

        fffffade6d389010: (0006,03a0) Flags: 00000884  Mdl: 00000000

        fffffade6bf55c60: (0006,03a0) Flags: 00000884  Mdl: 00000000

    Impersonation token:  fffffa8002f5b620 (Level Impersonation)

    Owning Process            fffffade6f97c2b0       Image:         svchost.exe

    Wait Start TickCount      18281033       Ticks: 26423448 (4:18:41:06.375)

    Context Switch Count      11                 LargeStack

    UserTime                  00:00:00.015

    KernelTime                00:00:00.000

    Win32 Start Address 0x0000000003855c60

    Start Address 0x0000000078d6b630

    Stack Init fffffade56ea1e00 Current fffffade56e9f930

    Base fffffade56ea2000 Limit fffffade56e9b000 Call 0

    Priority 9 BasePriority 8 PriorityDecrement 0

     

    Child-SP          RetAddr           Call Site

    fffffade`56e9f970 fffff800`01054df3 nt!KiSwapContext+0x85

    fffffade`56e9faf0 fffff800`0105457f nt!KiSwapThread+0x376

    fffffade`56e9fb50 fffff800`0125555c nt!KeWaitForSingleObject+0x58e

    fffffade`56e9fbd0 fffffade`5b19e471 nt!LpcpRequestWaitReplyPort+0x672

    fffffade`56e9fc60 fffffade`5b19f88a KSecDD!EfspDecryptFek+0x131

    fffffade`56e9fec0 fffffade`5b0a4f46 KSecDD!EfsDecryptFek+0x2a

    fffffade`56e9ff10 fffffade`5b0a4b9d Ntfs!EFSPostCreate+0x323

    fffffade`56ea0060 fffffade`5b119d70 Ntfs!EFSFilePostCreate+0x1a5

    fffffade`56ea00e0 fffffade`5b1f2daa Ntfs!NtfsFsdCreate+0x425

    fffffade`56ea0270 fffffade`59976284 fltMgr!FltpCreate+0x34a

    fffffade`56ea0300 fffffade`5997ed4c SomeFSFilter+0x9284

    fffffade`56ea0360 fffffade`5997637f SomeFSFilter+0x11d4c

    fffffade`56ea0390 fffffade`5b1d759a SomeFSFilter+0x937f

    fffffade`56ea0400 fffffade`5b1f2e14 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a

    fffffade`56ea0470 fffff800`01295ede fltMgr!FltpCreate+0x3b4

    fffffade`56ea0500 fffff800`0128ea00 nt!IopParseDevice+0x108f

    fffffade`56ea06b0 fffff800`012909a7 nt!ObpLookupObjectName+0x923

    fffffade`56ea07c0 fffff800`01296a14 nt!ObOpenObjectByName+0x180

    fffffade`56ea09b0 fffff800`01296bb7 nt!IopCreateFile+0x630

    fffffade`56ea0b40 fffffade`599e2a67 nt!IoCreateFile+0x12f

    fffffade`56ea0c20 fffffade`599e3c91 SomeFSFilter+0x47a67

    fffffade`56ea0ce0 fffffade`599e62e9 SomeFSFilter+0x48c91

    fffffade`56ea0d10 fffffade`599aacd3 SomeFSFilter+0x4b2e9

    fffffade`56ea0e00 fffffade`599aad6e SomeFSFilter+0xfcd3

    fffffade`56ea0ea0 fffffade`599bea96 SomeFSFilter+0xfd6e

    fffffade`56ea0ed0 fffffade`599ae142 SomeFSFilter+0x23a96

    fffffade`56ea0f90 fffffade`599ae7f1 SomeFSFilter+0x13142

    fffffade`56ea1070 fffffade`5999c0e3 SomeFSFilter+0x137f1

    fffffade`56ea10a0 fffffade`599ae848 SomeFSFilter+0x10e3

    fffffade`56ea10d0 fffffade`599ae8c3 SomeFSFilter+0x13848

    fffffade`56ea1120 fffffade`599a9a96 SomeFSFilter+0x138c3

    fffffade`56ea1160 fffffade`599a782f SomeFSFilter+0xea96

    fffffade`56ea11a0 fffffade`599a7a02 SomeFSFilter+0xc82f

    fffffade`56ea11e0 fffffade`5997d484 SomeFSFilter+0xca02

    fffffade`56ea1230 fffffade`599800f4 SomeFSFilter+0x10484

    fffffade`56ea1260 fffffade`5998038d SomeFSFilter+0x130f4

    fffffade`56ea1290 fffffade`5997ecbc SomeFSFilter+0x1338d

    fffffade`56ea12c0 fffffade`5997637f SomeFSFilter+0x11cbc

    fffffade`56ea12f0 fffffade`5b1d759a SomeFSFilter+0x937f

    fffffade`56ea1360 fffffade`5b1f2e14 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a

    fffffade`56ea13d0 fffff800`01295ede fltMgr!FltpCreate+0x3b4

    fffffade`56ea1460 fffff800`0128ea00 nt!IopParseDevice+0x108f

    fffffade`56ea1610 fffff800`012909a7 nt!ObpLookupObjectName+0x923

    fffffade`56ea1720 fffff800`01296a14 nt!ObOpenObjectByName+0x180

    fffffade`56ea1910 fffff800`01296bb7 nt!IopCreateFile+0x630

    fffffade`56ea1aa0 fffff800`01298479 nt!IoCreateFile+0x12f

    fffffade`56ea1b80 fffff800`0104fce2 nt!NtCreateFile+0x69

    fffffade`56ea1c00 00000000`78ef17ba nt!KiSystemServiceCopyEnd+0x3

    00000000`00bbf258 00000000`00000000 0x78ef17ba

     

     

    Using the message Id mentioned in the “!thread” output we dump the LPC message. The output has two anomalies.

    1. No server thread has been listed which is processing the client request.
    2. The message queue as well as the LpcDataInfoChain is empty.

     

     

    Answers to both questions are very specific to LSASS. Most types of client requests received on LsaAuthenticationPort do not have extra data. As mentioned in CASE 1, server threads dequeue the message and chain it to LpcDataInfoChainHead only if the message contains extra information. If the message does not contain any extra data then the server does not need to store the message anywhere. The server would only need to remember the kind of request carried by the message.

     

    !lpc message searches the ETHREAD.LpcReceiveMessageId field to determine which server thread is processing the message. The way LSASS handles LPC request is that there is a single thread in LSASS that dequeues all messages from the connection port message queue and enqueues them to an LSASS specific internal queue. LSASS has a pool of worker threads that wait for requests in the internal queue. The worker threads dequeue the request, process it and reply back to the client. Hence the single LPC server thread in LSASS has its LpcReceiveMessageId overwritten by a new one every time it dequeues a message and enqueues it to the internal queue. That is the reason !lpc message fails to find a server thread for the LPC message sent to LsaAuthenticationPort.

     

     

     

     

    2: kd> !LPC MESSAGE 01561d96

    Searching message 1561d96 in threads ...

    Client thread fffffade6c9f1390 waiting a reply from 1561d96                         

    Searching thread fffffade6c9f1390 in port rundown queues ...

     

    Server communication port 0x033fc660

        Handles: 1   References: 1

        The LpcDataInfoChainHead queue is empty

            Connected port: 0xfffffa800380cc40      Server connection port: 0xfffffa800282ca40

     

    Client communication port 0xfffffa800380cc40

        Handles: 0   References: 1

        The LpcDataInfoChainHead queue is empty

     

    Server connection port fffffa800282ca40  Name: LsaAuthenticationPort

        Handles: 1   References: 83

        Server process  : fffffade6ead0040 (lsass.exe)

        Queue semaphore : fffffade6e9513c0

        Semaphore state 0 (0x0)

        The message queue is empty

        The LpcDataInfoChainHead queue is empty

    Done.  

     

     

     

    Then how do you find the server thread that is responsible for replying back to the client and why it isn’t replying? Well there are many ways to do so depending upon the scenario. The way I chose was to look at all threads in LSASS which either have function calls on the stack that relate to the KSecDD request made or other hints. The reason threads only in LSASS were checked is because we knew that the request was sent to LsaAuthenticationPort and will be processed within LSASS. The hint was in the Wait Tick Count of the thread. I found a thread which had exactly the same Wait Tick Count as the client thread that was waiting for a reply. Further investigation of the thread confirmed that it was the one responsible for processing the request from KSecDD.

     

     

     

    2: kd> !thread fffffade6fa01460

    THREAD fffffade6fa01460  Cid 03a4.0100  Teb: 000007fffff8e000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable

        fffffade6f665820  Semaphore Limit 0x1

        fffffade6f665840  NotificationEvent

    IRP List:

        fffffade6bb9a830: (0006,03a0) Flags: 00000884  Mdl: 00000000

    Impersonation token:  fffffa80044d11c0 (Level Impersonation)

    Owning Process            fffffade6ead0040       Image:         lsass.exe

    Wait Start TickCount      18281033       Ticks: 26423448 (4:18:41:06.375)

    Context Switch Count      509109            

    UserTime                  00:01:54.500

    KernelTime                00:00:33.765

    Win32 Start Address 0x0000000000c21aa0

    Start Address 0x0000000078d6b630

    Stack Init fffffade5a894e00 Current fffffade5a893e40

    Base fffffade5a895000 Limit fffffade5a88f000 Call 0

    Priority 13 BasePriority 9 PriorityDecrement 0

     

    Child-SP          RetAddr           Call Site

    fffffade`5a893e80 fffff800`01054df3 nt!KiSwapContext+0x85

    fffffade`5a894000 fffff800`0105518f nt!KiSwapThread+0x376

    fffffade`5a894060 fffffade`599a8b28 nt!KeWaitForMultipleObjects+0x66e

    fffffade`5a8940f0 fffffade`599a7808 SomeFSFilter+0xdb28

    fffffade`5a8941a0 fffffade`599a7a02 SomeFSFilter+0xc808

    fffffade`5a8941e0 fffffade`5997d484 SomeFSFilter+0xca02

    fffffade`5a894230 fffffade`599800f4 SomeFSFilter+0x10484

    fffffade`5a894260 fffffade`5998038d SomeFSFilter+0x130f4

    fffffade`5a894290 fffffade`5997ecbc SomeFSFilter+0x1338d

    fffffade`5a8942c0 fffffade`5997637f SomeFSFilter+0x11cbc

    fffffade`5a8942f0 fffffade`5b1d759a SomeFSFilter+0x937f

    fffffade`5a894360 fffffade`5b1f2e14 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a

    fffffade`5a8943d0 fffff800`01295ede fltMgr!FltpCreate+0x3b4

    fffffade`5a894460 fffff800`0128ea00 nt!IopParseDevice+0x108f

    fffffade`5a894610 fffff800`012909a7 nt!ObpLookupObjectName+0x923

    fffffade`5a894720 fffff800`01296a14 nt!ObOpenObjectByName+0x180

    fffffade`5a894910 fffff800`01296bb7 nt!IopCreateFile+0x630

    fffffade`5a894aa0 fffff800`01298479 nt!IoCreateFile+0x12f

    fffffade`5a894b80 fffff800`0104fce2 nt!NtCreateFile+0x69

    fffffade`5a894c00 00000000`78ef17ba nt!KiSystemServiceCopyEnd+0x3

     

     

    Having all the facts makes understanding the problem easier. SomeFSFilter.sys is an anti-virus driver that scans every file opened. During the open of an encrypted file it tries to scan the file before it is opened. For doing so it requests KSecDD to decrypt the file. KSecDD sends a LPC request to LsaAuthenticationPort for key decryption. LSASS as part of processing the request tries to open a file which for some reason is blocked by SomeFSFilter.sys. So we have a classic deadlock situation where SomeFSFilter.sys is waiting on LSASS to reply to the LPC message while LSASS is waiting on SomeFSFilter.sys for opening a file.

     

    In this scenario we could only use minimal help from the LPC debugger extension because of the way LPC requests were handled by LSASS. In such situations other heuristics are required to debug the problem.

     

    Finally, our journey through the world of LPC comes to an end. LPC has been the backbone of local inter-process communication since the NT4.0 days but as everything has a shell life, so did LPC. LPC has been replaced by ALPC (Asynchronous LPC) in Vista and Server 2008. The LPC APIs are now implemented over the new ALPC APIs to maintain compatibility. Although the LPC APIs are not exported, neither is there a requirement to call them directly, nevertheless having an understanding of the API helps in debugging as we have seen in the posts.

    Hope this information helps. Happy debugging!!!

     

  • Ntdebugging Blog

    Where the rubber meets the road, or in this case the hardware meets the probe.

    • 1 Comments

    Hi my name is Bob, I’m an Escalation engineer with the Microsoft critical problem resolution team.  We had one of our readers ask how much we deal with hardware.  Well in response we recently worked on an interesting problem I thought I would share with you.  In this case it was interesting because it demonstrated an issue specific to multi-processor machines and something that probably sounded innocuous to the driver writer who caused the  problem.

     

    What was the problem?

     

    The problem was that everything worked except the time in the system was not being updated. The RTC had stopped.   We spent time reviewing the semantics of how the RTC should function and even hooked up an oscilloscope to the RTC on the motherboard and were able to turn it off and on with the debugger by writing out the correct port.  The trace on the scope validated our understanding of what had to be written to the port to turn the clock off.    One we had a clear understanding of this we understood what we were looking for in a driver that might cause the problem.  Note the clock typically fires every 10ms so you do not need a fast scope to do this.

     

     

    Special keyboard driver written

     

    In order to catch a dump in state we had to modify the keyboard driver.  It would cause an “Int 3” in its ISR instead of calling “bug check” for an E2 stop.    Because the RTC was not running the idle thread was not getting quantums and as a result a normal break in would not work.  However the system would respond to ISRs. 

     

    What was found

     

    All RTC interrupts were stopped - the clock was not running.  We checked all the obvious places to see if the RTC was disabled.

     

    We looked at the ICR in the I/O APIC.  This is the interrupt configuration register. There is a register for every interrupt pin on the APIC. These registers are used to tell the APIC what vector to send the processor so the processor can service the interrupt.  It also has configuration information about level and if it edge triggered and a mask bit.  The mask bit was not set.

    Below is a reenactment.

     

    0: kd> ed ffd01000

    ffd01000 00000034 20 ß Select register 20 which is pin 8.

     

     

    0: kd> ed ffd01010

    ffd01010 000008d1    ß Contents ß Vect D1 Bit 16 the interrupt mask bit is not set so it is OK.

     

     

    Next check the RTC status register which are I/O ports 70 and 71.  Port 70 is the address port.  Port 71 is the data port.  This information is from an old BIOS book.

     

    0: kd> ob 70 b       ß ‘B’ is a control register.   

    0: kd> ib 71

    00000071: 42         ß The value 42 means that the RTC is enabled.  Bit 6 is the enable.

     

     

    So what was it?

     

    The way the RTC works is it will interrupt at a certain interval.  When the interrupt is serviced, the status register has to be read to start it again.

     

    We discovered another driver that was reading  the clock, this was done by disassembly various drivers in the dump and looking for the I/O operation to ports 70 or 71.  The lower addresses selected by port 70 will yield the time when read.  That is what the driver was doing.

     

    You would think that simply reading the time in this way would not hurt anything.  However, in a multi-processor system, access has to be serialized.  There is only one set of I/O ports for the system.

     

    Since it takes two accesses to perform an operation on the clock, one address & one data, a collision between two processors can cause undetermined results.

     

    Below is a timing diagram of the issue;

     

     

    Proc 0 running OS RTC handler                         Proc 1 running XYZ driver

     

      T1          Set register select to status register

     

      T2                                                                                          Set register select to read time

     

      T3          Read status register to restart clock

     

     

    So at T3 the OS RTC handler reads the wrong register so the clock does not start. 

     

     

    Conclusion

     

    I thought this was an interesting problem that illustrates the need for serialization.  And it demonstrates what to look out for in a multi-proc environment.  You always have to think “What happens if the other processor does…….”

     

    For more information consult any BIOS developer manuals you may have lying around or this link we found http://www.geocities.com/SiliconValley/Campus/1671/docs/rtc.htm

    See the “Status Register C” section, “All future interrupts are disabled until this register is read - your interrupt handler *must* do it.”

  • Ntdebugging Blog

    NonPagedPool Depletion

    • 1 Comments

    I recently was engaged on an issue where a server was depleting NonPagedPool over a period of a few days.  Ordinarily, we would just use a tool like PoolMon to identify the offending pool tag and then find the driver that uses that pool tag using the method in this article

     

    However, what made this case interesting was the pool tag and that we were unable to identify the driver using the normal methodology.  You’ll see what I mean in a moment.  The engineer supplied me with a kernel dump of the server while it was in-state and this is what I found.

     

    Let’s start by taking a look at the virtual memory usage:

     

    2: kd> !vm

     

    *** Virtual Memory Usage ***

           Physical Memory:      851420 (   3405680 Kb)

           Page File: \??\C:\pagefile.sys

             Current:   3584000 Kb  Free Space:   3568552 Kb

             Minimum:   3584000 Kb  Maximum:      3584000 Kb

           Available Pages:      573277 (   2293108 Kb)

           ResAvail Pages:       800628 (   3202512 Kb)

           Locked IO Pages:        1067 (      4268 Kb)

           Free System PTEs:      25102 (    100408 Kb)

           Free NP PTEs:            335 (      1340 Kb)

           Free Special NP:           0 (         0 Kb)

           Modified Pages:           22 (        88 Kb)

           Modified PF Pages:        22 (        88 Kb)

           NonPagedPool Usage:    31369 (    125476 Kb)    ß Very high

           NonPagedPool Max:      31986 (    127944 Kb)

           ********** Excessive NonPaged Pool Usage *****

           PagedPool 0 Usage:     19071 (     76284 Kb)

           PagedPool 1 Usage:       735 (      2940 Kb)

           PagedPool 2 Usage:       747 (      2988 Kb)

           PagedPool 3 Usage:       720 (      2880 Kb)

           PagedPool 4 Usage:       746 (      2984 Kb)

           PagedPool Usage:       22019 (     88076 Kb)

           PagedPool Maximum:     38912 (    155648 Kb)

     

           ********** 3 pool allocations have failed **********

     

    So we can see that NPP usage is very high given the server is using the /3GB switch which limits NPP to 128MB by default.  We need to identify what pool tag is associated with the high NPP usage:

     

    2: kd> !poolused /t2 2

       Sorting by  NonPaged Pool Consumed

     

      Pool Used:

                NonPaged            Paged

     Tag    Allocs     Used    Allocs     Used

     None   246479 50827424         0        0      call to ExAllocatePool

     MmCm     1198 18462512         0        0      Calls made to MmAllocateContiguousMemory , Binary: nt!mm

     

    Interesting, so the offending tag is “None”.  This means that these allocations were made by calling the function ExAllocatePool instead of ExAllocatePoolWithTag.  ExAllocatePool is obsolete and should no longer be used. 

     

    Now, I need to find out which driver is calling this function.  First, I need to know where ExAllocatePool lives:

     

    2: kd> x nt!ExAllocatePool

    e0894d1f nt!ExAllocatePool

     

    Next, I need to search all the drivers to see which one is importing this function:

     

    2: kd> !for_each_module s-d @#Base @#End e0894d1f

    f50b8058  e0894d1f e0828e04 e089b708 e084011b  .M..............

     

    Hmm, looks suspiciously like an import table, let’s see:

     

    2: kd> dps f50b8058

    f50b8058  e0894d1f nt!ExAllocatePool

    f50b805c  e0828e04 nt!_wcsnicmp

    f50b8060  e089b708 nt!ExFreePoolWithTag

    f50b8064  e083e30a nt!KeInitializeEvent

    <SNIP>

     

    Yep, that’s an import table.  You can also verify that this is the import table of a particular module by checking the header (!dh on the module’s base address and look for “Import Address Table Directory”).

     

    As you can see, we have only one driver that imports ExAllocatePool.  Let’s see which driver this is:

     

    2: kd> !lmi f50b8058

    Loaded Module Info: [f50b8058]

             Module: {XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX}

       Base Address: f50b3000

         Image Name: {XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX}.sys

           <SNIP>

     

    I’ve removed the incriminating identifiers from module information displayed above to protect the guilty.  It is interesting to note that the driver name was a GUID and that this driver did not exist on the disk.  This was because the driver is dynamically created when its parent program loads.  

     

    The software package was removed and the server was happy again. 

     

    -         David

  • Ntdebugging Blog

    The Case of the Low Hanging Filter Driver Fruit

    • 1 Comments

     

    Written By Jeff Dailey:

     

    Not all our cases are crashes, leaks, or high CPU.  Sometimes the problems we are faced with are purely a question of why a given application runs slow on a particular version of Windows versus another version of windows.  In other cases an application may just start running slow for no reason.   OK, not likely.  There is ALWAYS SOME RESASON.  Something changed!  In this case, the customer reported that an application started running slow when booted into “Normal Mode”, but when the OS was booted in safe mode, the application would run fast.  In this particular case the customer reported that a given operation went from taking just a few seconds (safe mode) to several minutes (normal mode).   Further research found that the problem was related to accessing the registry and registry performance in general.  At this point I’m already thinking, “Registry Access?” and “Safe Mode”.  What could affect registry access that does not run in safe mode?  Well lots of services DO NOT start in safe mode.  What kind of services could affect registry calls?  Antivirus?  Maybe…  Let’s look deeper.

     

    One of the first things I typically do in such cases is to ask for a kernrate log of the slow and fast scenario. http://download.microsoft.com/download/8/e/c/8ec3a7d8-05b4-440a-a71e-ca3ee25fe057/rktools.exe  Kernrate is a sampling profiler.   It basically checks the location of the instruction pointer at regular intervals and stores the results in a hash table.   We can then get a breakdown of the %time spent in each module that is executing.    Even better you can zoon in to each module.  Zooming in shows utilization at a function level within the module and requires symbols to be present in a flat symbol directory on the machine being profiled.  I recommend downloading the symbol pack for this (http://www.microsoft.com/whdc/devtools/debugging/symbolpkg.mspx) or use symchk.exe (included in the debugging tools) to download the symbols.  We’ll talk more about symbols and symchk.exe in an upcoming post.

     

    In a lot of cases kernrate data is only a starting point.   We will find some code that is running a lot longer in one case verses another and that in turn requires a follow up code review and multiple debugs to further isolate the problem.  This case however was different.  The following is output from beyond compare that shows a comparison between the module execution time in kernel.   The slow test run is on the right, and the fast test run is on the left.  Keeping in mind that I was looking for something different between safe mode and normal mode, I simply started by looking at the modules listed on the slow side (Right) there were not on the fast side (Left).   What was loaded during the normal run that was not a factor during the safe mode run.  Right away FILTERDRVXYZ just above the HAL jumped off the page.  (Some names were changed to protect the innocent. J)  I did a http://www.live.com search to find out what this driver was.  It was a file system filter driver for an antivirus program.

     

    To understand why a filter driver can slow things down you need to understand that a filter driver basically installs itself between the application and the underlying file system and intercepts nearly every call being made to the underlying I/O subsystem.   Most of the time filter drivers are just fine and run with no problems at all.   However, what do they do?  An antivirus filter driver may have several tasks that it needs to do for each I/O.  This may involve looking up information about a process or file when it’s being accessed.   If the data source associated with this information changes it can change the amount of time that these operations take.   The interesting thing is that the timing change may only be a hundred or so extra milliseconds per call to the registry or file system.  Under most cases a user would not even notice this.  If however you have some aspect of your application needs to make many thousands of calls and they each take 250+ milliseconds vs. 10 milliseconds, all of a sudden the problem compounds.  The classic example of this is a VIRUS PROFILE gets uploaded or pushed to servers and all of a sudden the customer starts seeing performance problems because the data set or comparison for the filter driver changes.   In this case I simply recommended that the customer remove the suspect filter driver to see if it was the root of the problem.  IT WAS…  They contacted the product vendor to get an update and the case was resolved.

     

    Good luck and happy debugging….

  • Ntdebugging Blog

    Disassemble the MBR

    • 1 Comments

     

    UPDATE:  This is why we *LOVE* our readers!  After posting a 32-bit disassembly of 16-bit MBR code, I was gently informed of my misstep by three sharp-eyed readers.  I’ve corrected the original post below.  Thanks go out to Ramon Sola, Jeroen Frijters and 'pedantic gnome' for keeping us honest.  Thanks guys!

     

     

    Hi Everyone,

     

    One of our readers, Pete, asked a very interesting question about disassembling the MBR and I'd like to take a moment to show you the quick & dirty way to do this.

     

    First, dump the MBR to a file using a low-level sector editor such as the Microsoft Resource Kit utility DiskProbe.  Once you've saved the file, launch a program (like Notepad) and attach to it using Windbg (the Windows Debugger). 

     

    Next, find a valid, but unoccupied range of memory (the default heap is a good candidate).  The memory range needs to be at least 512 (0x200) bytes.  For example, here's where I found mine:

     

    000120a0  00000000 00000000 00000000 00000000

    000120b0  00000000 00000000 00000000 00000000

    000120c0  00000000 00000000 00000000 00000000

    000120d0  00000000 00000000 00000000 00000000

    000120e0  00000000 00000000 00000000 00000000

    000120f0  00000000 00000000 00000000 00000000

    00012100  00000000 00000000 00000000 00000000

    00012110  00000000 00000000 00000000 00000000

    00012120  00000000 00000000 00000000 00000000

    <snip>...

     

    Once you've found a good memory range in your process, read the file contents into that memory location using the following command:

     

    0:001> .readmem c:\<<path>>\sector00.bin 120a0 120a0+0x1ff

     

    Tada!  You now have the MBR in memory and it is fully examinable just like any other assembly code. 

     

    0:001> db 000120a0 

    000120a0  33 c0 8e d0 bc 00 7c 8e-c0 8e d8 be 00 7c bf 00  3.....|......|..

    000120b0  06 b9 00 02 fc f3 a4 50-68 1c 06 cb fb b9 04 00  .......Ph.......

    000120c0  bd be 07 80 7e 00 00 7c-0b 0f 85 10 01 83 c5 10  ....~..|........

    000120d0  e2 f1 cd 18 88 56 00 55-c6 46 11 05 c6 46 10 00  .....V.U.F...F..

    000120e0  b4 41 bb aa 55 cd 13 5d-72 0f 81 fb 55 aa 75 09  .A..U..]r...U.u.

    000120f0  f7 c1 01 00 74 03 fe 46-10 66 60 80 7e 10 00 74  ....t..F.f`.~..t

    00012100  26 66 68 00 00 00 00 66-ff 76 08 68 00 00 68 00  &fh....f.v.h..h.

    00012110  7c 68 01 00 68 10 00 b4-42 8a 56 00 8b f4 cd 13  |h..h...B.V.....

     

    Since this is 16-bit assembly, you can unassemble using ‘ur’:

    0:001> ur 120a0
    000120a0 33c0            xor     ax,ax
    000120a2 8ed0            mov     ss,ax
    000120a4 bc007c          mov     sp,7C00h
    000120a7 8ec0            mov     es,ax
    000120a9 8ed8            mov     ds,ax
    000120ab be007c          mov     si,7C00h
    000120ae bf0006          mov     di,600h
    000120b1 b90002          mov     cx,200h
    <snip>...

     

    Have fun Pete!

     

    DiskProbe:       http://technet.microsoft.com/en-us/library/bb457122.aspx

    WinDbg:           http://www.microsoft.com/whdc/devtools/debugging/default.mspx

     

      - David

  • Ntdebugging Blog

    How to Find the Owner of a Named Pipe

    • 1 Comments

    This is a follow-up on the LPC hang blog. The same hang troubleshooting techniques apply to this, but when a named pipe is involved you’ll have to use a slightly different method to following the chain from a client application to the server application. For the purpose of this exercise I’ll use the named pipe server (http://msdn2.microsoft.com/en-us/library/aa365588.aspx) and client (http://msdn2.microsoft.com/en-us/library/aa365592.aspx) given by MSDN.

     

     

    Here is a diagram of our scenario.

    named_pipes

     

    Here we have the client application that is waiting on a read operation to a named pipe. We need to determine what process will be putting data into the named pipe which will let the client application move forward.

    Here is the thread in the client application.

     

     

    THREAD 81e70858  Cid 06bc.06c0  Teb: 7ffdf000 Win32Thread: 00000000 WAIT: (Executive) UserMode Non-Alertable

        81baaf7c  NotificationEvent

    Not impersonating

    DeviceMap                 e25176b8

    Owning Process            81b3a020       Image:         client.exe

    Attached Process          N/A            Image:         N/A

    Wait Start TickCount      73194          Ticks: 1599 (0:00:00:24.984)

    Context Switch Count      21            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address client (0x00401376)

    Start Address kernel32!BaseProcessStartThunk (0x77e617f8)

    Stack Init f7450000 Current f744fc04 Base f7450000 Limit f744d000 Call 0

    Priority 10 BasePriority 8 PriorityDecrement 2

    ChildEBP RetAddr  Args to Child             

    f744fc1c 808202b6 81e70858 81e70900 00000700 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

    f744fc34 8081fb6e 8207dac0 00000000 81baaf20 nt!KiSwapThread+0x83 (FPO: [Non-Fpo])

    f744fc78 8092deb3 81baaf7c 00000000 81f93601 nt!KeWaitForSingleObject+0x2e0 (FPO: [Non-Fpo])

    f744fca0 80924ca9 81f936e0 00000103 81baaf20 nt!IopSynchronousServiceTail+0x180 (FPO: [Non-Fpo])

    f744fd38 8082350b 00000024 00000000 00000000 nt!NtReadFile+0x5d5 (FPO: [Non-Fpo])

    f744fd38 7c8285ec 00000024 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f744fd64)

    0012eed4 7c82776b 77e418b2 00000024 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    0012eed8 77e418b2 00000024 00000000 00000000 ntdll!NtReadFile+0xc (FPO: [9,0,0])

    0012ef40 004010ab 00000024 0012ef60 00001000 kernel32!ReadFile+0x16c (FPO: [Non-Fpo])

    0012ff78 0040131f 00000001 00323038 00323078 client+0x10ab

    0012ffc0 77e6f23b 00000000 00000000 7ffd8000 client+0x131f

    0012fff0 00000000 00401376 00000000 78746341 kernel32!BaseProcessStart+0x23 (FPO: [Non-Fpo])

     

    We have highlighted the first parameter to the ReadFile function. This parameter is the handle to the file we are trying to read.

    Knowing this we can use the !handle extension to display details on this handle. The !handle extension takes three parameters: 1. The handle to get details on, 2: a flag controlling the level of verbosity the extension will display (f being the most verbose level), and 3: the process address.

     

    kd> !handle 00000024 f 81b3a020

    processor number 0, process 81b3a020

    PROCESS 81b3a020  SessionId: 0  Cid: 06bc    Peb: 7ffd8000  ParentCid: 0f2c

        DirBase: 1d486000  ObjectTable: e252bbc8  HandleCount:  10.

        Image: client.exe

    Handle table at e2845000 with 10 Entries in use

    0024: Object: 81baaf20  GrantedAccess: 0012019f Entry: e2845048

    Object: 81baaf20  Type: (823ceca0) File

        ObjectHeader: 81baaf08 (old version)

            HandleCount: 1  PointerCount: 3

            Directory Object: 00000000  Name: \mynamedpipe {NamedPipe}

    We have highlighted the object address (yellow) and the type of the object (green) above. The object is of type file which is defined by the FILE_OBJECT structure. So we can examine that using the dt (Display Type) command. The dt command can take 3 parameters: 1. The structure you want to cast the data as, 2: the address of the object, and 3: the field in the structure to be displayed.

     

    kd> dt nt!_FILE_OBJECT 81baaf20 FsContext2

       +0x010 FsContext2       : 0x81b5cc90

     

    The FsContext2 field points to an NPFS CCB structure. The importance of this structure is that it is charged to the server process which created it. The !pool extension can be used to display information about the ownership of the memory the file object is stored in.

     

    kd> !pool 0x81b5cc90  2

    Pool page 81b5cc90 region is Nonpaged pool

    *81b5cc88 size:   50 previous size:  140  (Allocated) *NpFc Process: 81be0d88

                  Pooltag NpFc : CCB, client control block, Binary : npfs.sys

    PROCESS 81be0d88  SessionId: 0  Cid: 07b4    Peb: 7ffd4000  ParentCid: 0160

        DirBase: 02b6f000  ObjectTable: e234a530  HandleCount:  10.

        Image: server.exe

     

     

    Now you have the established the link from the client application and the server application. Now you will be able to move forward in your debugging and figure out why the server process isn’t writing data back to the client.

     

    - Bryan

  • Ntdebugging Blog

    WE ARE HIRING

    • 1 Comments

    Want to debug the most difficult problems against the largest, most complex piece of software ever written? Are you fluent in C and assembly? Do you carry a spare debugger cable in your bag? Can you represent Microsoft in critical, time sensitive solution delivery? Writing code is easy, finding bugs in someone else’s code you’ve never seen before is a real challenge.

     

    Want to hear more?

     

    http://blogs.msdn.com/jobsblog/archive/2007/01/26/jobcast-life-as-an-escalation-engineer.aspx

     

    http://blogs.msdn.com/jobsblog/archive/2007/11/21/life-as-an-escalation-engineer-part-ii.aspx

     

     

    Candidate must be a strong critical thinker, and enjoy solving very difficult problems (often involving code level analysis).  Escalation Engineers within GES are frequently involved with the highest profile issues, and therefore must be able to handle both pressure and complex situations. Candidates must also have strong customer service, accurate logical problem solving and communication skills, and the ability to work in a team environment. Programming and debugging skills are required, preferably in C or C++.  Also, the ability to read and analyze network traces and solid protocol analysis is a plus. The ideal candidate may have a four year degree in C.S. or Engineering and a minimum of four years product support experience or the equivalent in work experience. Prior knowledge of the product to be supported, and other networking products and/or networking operating systems is required. If you enjoy being the problem-solver in the spotlight of critical problems, then this position will excite and challenge you.

     

     

    Applicants that possess the experience, and desire will be considered and are encouraged to apply using the below link. After applying, please submit a copy of your resume to benjammc@microsoft.com

     

    Job Details - Microsoft Careers job code is 209923 and can be found on the Microsoft Career page.

     

     

  • Ntdebugging Blog

    LPC part 2 Kernel Debugger Extensions

    • 1 Comments

    Hello my name is Roy, I’m an EE on the Microsoft global escalation services / CPR team.   This blog is a follow on to my first LPC blog.  We will be discussing debugger extensions that allow you to look at LPC related issues.

     

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

     

    LPC Kernel Debugger Extensions

     

     

    Command

    Description

    !lpc                    

    Display the list and description of all the !lpc commands

    !lpc message [MessageId]

    Display the message with a given ID and all related information by attempting to match the given Message ID to the EHTREAD->LpcReceivedMessageId and to the ETHREAD->LpcReplyMessageId of all threads in the system.

    If the MessageId parameter is omitted then it attempts to display all the outstanding messages in the system by searching for the tag ‘LpcM’ in the pools.

    !lpc port [PortAddress] 

    Displays port information. If a server connection port address is specified then only information about that port is displayed. If either a client or server communication port is specified it prints information about the specified communication port, the peer communication port and the server connection port.

    If the PortAddress parameter is omitted then it attempts to walk the list of all objects of type “Port” and “WaitablePort” and display them. Note that for this feature to work the GFlags option “+otl” i.e. “Maintain a list of objects for each type” must be enabled.

    !lpc scan PortAddress   

    Displays port information. It attempts to walk the list of all objects of type “Port” and “WaitablePort” and display the one matching the specified port address. Note that for this feature to work the GFlags option “+otl” i.e. “Maintain a list of objects for each type” must be enabled.

    !lpc thread [ThreadAddr]

    If  ThreadAddr is specified it walks the list of threads in the ETHREAD-> LpcReplyChain to locate the list head i.e. a “Port” or “WaitablePort” object on which the thread is waiting for a reply.

    If the ThreadAddr parameter is omitted then it attempts to find all LPC server threads by looking for threads with a non-NULL EHTREAD->LpcReceivedMessageId and all client threads by looking for threads with a non-NULL ETHREAD->LpcReplyMessageId and displays them.

    !lpc PoolSearch

    Toggles a setting that controls whether the “lpc message” command will search for LPC message tag (‘LpcM’) in the kernel pools or not.

     

     

     

    LPC Kernel Debugger Extension Usage

     

     

    LPC Connection Port information from call stack

     

    On the call stack of any client or server threads blocked on LPC data transfer or LPC connection there will be a frame containing either one of the functions  NtRequestWaitReplyPort() or NtReplyWaitReceivePortEx() . The first parameter to either one of these functions is the handle to the port they are blocked on.

     

    kd> !thread 810de2a8 

    THREAD 810de2a8  Cid 01dc.01f4  Teb: 7ffde000 Win32Thread: 00000000 WAIT: (WrLpcReceive) UserMode Non-Alertable

        81131188  Semaphore Limit 0x7fffffff

        810de398  NotificationTimer

    Not impersonating

    DeviceMap                 e196c460

    Owning Process            810ddda0       Image:         rpclpcs.exe

    Wait Start TickCount      64555          Ticks: 402 (0:00:00:04.025)

    Context Switch Count      2            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.000

    Win32 Start Address 0x77e76bf0

    Start Address 0x7c810856

    Stack Init f8e28000 Current f8e27c4c Base f8e28000 Limit f8e25000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0

    ChildEBP RetAddr  Args to Child             

    f8e27c64 804dc6a6 810de318 810de2a8 804dc6f2 nt!KiSwapContext+0x2e (FPO: [Uses EBP] [0,0,4])

    f8e27c70 804dc6f2 e1084108 8055a540 e1084108 nt!KiSwapThread+0x46 (FPO: [0,0,0])

    f8e27c98 8056a50a 00000001 00000010 00000001 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])

    f8e27d48 804df06b 000007c4 002bff70 00000000 nt!NtReplyWaitReceivePortEx+0x3dc (FPO: [Non-Fpo])

    f8e27d48 7c90eb94 000007c4 002bff70 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f8e27d64)

    002bff80 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

     

    kd> !handle 7c4 3 810ddda0       

    processor number 0, process 810ddda0

    PROCESS 810ddda0  SessionId: 0  Cid: 01dc    Peb: 7ffd9000  ParentCid: 01b4

        DirBase: 058cd000  ObjectTable: e1a13278  HandleCount:  18.

        Image: rpclpcs.exe

     

    Handle table at e107d000 with 18 Entries in use

    07c4: Object: e1084108  GrantedAccess: 001f0001 Entry: e107df88

    Object: e1084108  Type: (812b5c80) Port

        ObjectHeader: e10840f0 (old version)

            HandleCount: 1  PointerCount: 4

            Directory Object: e14c72c8  Name: rpclpc

     

    kd> !lpc port e1084108

     

    Server connection port e1084108  Name: rpclpc

        Handles: 1   References: 4

        Server process  : 810ddda0 (rpclpcs.exe)

        Queue semaphore : 81131188

        Semaphore state 0 (0x0)

        The message queue is empty

        The LpcDataInfoChainHead queue is empty

     

     

    LPC Messages that are waiting to be picked up by the server thread

     

    When a message is queued to the server connection port and the server thread has not yet not been signaled to pull out the message the ‘!lpc port <Port>” displays the following output that includes the message.

     

    kd> !lpc port e10d8388

     

    Client communication port 0xe10d8388

        Handles: 1   References: 2

        The LpcDataInfoChainHead queue is empty

            Connected port: 0xe106dc00      Server connection port: 0xe15512e0

     

    Server communication port 0xe106dc00

        Handles: 1   References: 1

        The LpcDataInfoChainHead queue is empty

     

    Server connection port e15512e0  Name: rpclpc

        Handles: 1   References: 9

        Server process  : ffbbebe8 (rpclpcs.exe)

        Queue semaphore : 81250848

        Semaphore state 0 (0x0)

            Messages in queue:

            0000 e10513f8 - Busy  Id=000048d8  From: 05f4.0108  Context=80020000  [e15512f0 . e15512f0]

                       Length=0054003c  Type=00000001 (LPC_REQUEST)

                       Data: 00000001 00000241 00000000 00000000 f877bc04 804ec10e

        The message queue contains 1 messages

        The LpcDataInfoChainHead queue is empty

     

     

    LPC Messages being processed by the server

     

    When an LPC message has been queued by the client, dequeued by the sever and being worked upon by the server both the client and the server thread have the message ID associated with them

     

    kd> !lpc message 16fa

    Searching message 16fa in threads ...

        Server thread 810de2a8 is working on message 16fa                        

    Client thread 810dc930 waiting a reply from 16fa                         

    Searching thread 810dc930 in port rundown queues ...

     

    Server connection port e1084108  Name: rpclpc

        Handles: 1   References: 3

        Server process  : 810ddda0 (rpclpcs.exe)

        Queue semaphore : 81131188

        Semaphore state 0 (0x0)

        The message queue is empty

        The LpcDataInfoChainHead queue is empty

    Done.                                             

     

    kd> !thread 810de2a8

    THREAD 810de2a8  Cid 01dc.01f4  Teb: 7ffde000 Win32Thread: 00000000 RUNNING on processor 0

    Not impersonating

    DeviceMap                 e196c460

    Owning Process            810ddda0       Image:         rpclpcs.exe

    Wait Start TickCount      65732          Ticks: 10 (0:00:00:00.100)

    Context Switch Count      4            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.010

    Win32 Start Address 0x000016fa

    LPC Server thread working on message Id 16fa

    Start Address kernel32!BaseThreadStartThunk (0x7c810856)

    Stack Init f8e28000 Current f8e27728 Base f8e28000 Limit f8e25000 Call 0

    Priority 9 BasePriority 8 PriorityDecrement 0 DecrementCount 0

    ChildEBP RetAddr  Args to Child             

    f8e27d64 7c90eb94 badb0d00 002bfe24 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f8e27d64)

    002bfe18 7c90e399 77e76703 000007c4 002bff70 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    002bfe1c 77e76703 000007c4 002bff70 00000000 ntdll!NtReplyWaitReceivePortEx+0xc (FPO: [5,0,0])

    002bff80 77e76c22 002bffa8 77e76a3b 00084540 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0xf4 (FPO: [Non-Fpo])

    002bff88 77e76a3b 00084540 7c90ee18 0006fb10 RPCRT4!RecvLotsaCallsWrapper+0xd (FPO: [Non-Fpo])

    002bffa8 77e76c0a 00083f20 002bffec 7c80b50b RPCRT4!BaseCachedThreadRoutine+0x79 (FPO: [Non-Fpo])

    002bffb4 7c80b50b 00084718 7c90ee18 0006fb10 RPCRT4!ThreadStartRoutine+0x1a (FPO: [Non-Fpo])

    002bffec 00000000 77e76bf0 00084718 00000000 kernel32!BaseThreadStart+0x37 (FPO: [Non-Fpo])

     

    kd> !thread 810dc930

    THREAD 810dc930  Cid 01e4.01ec  Teb: 7ffde000 Win32Thread: 00000000 READY

    Waiting for reply to LPC MessageId 000016fa:

    Pending LPC Reply Message:

        e16b8538: [e16b8538,e16b8538]

    Not impersonating

    DeviceMap                 e196c460

    Owning Process            810e9860       Image:         rpclpcc.exe

    Wait Start TickCount      65731          Ticks: 11 (0:00:00:00.110)

    Context Switch Count      26            

    UserTime                  00:00:00.000

    KernelTime                00:00:00.020

    Win32 Start Address rpclpcs!pre_c_init (0x01001a91)

    Start Address kernel32!BaseProcessStartThunk (0x7c810867)

    Stack Init fbe0e000 Current fbe0dc28 Base fbe0e000 Limit fbe0b000 Call 0

    Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16

    ChildEBP RetAddr  Args to Child             

    fbe0dc40 804ea3a4 00000000 810dc930 e107f388 nt!KiUnlockDispatcherDatabase+0x77 (FPO: [Uses EBP] [0,0,4])

    fbe0dc58 80586255 81131188 00000001 00000001 nt!KeReleaseSemaphore+0x70 (FPO: [Non-Fpo])

    fbe0dd10 80598c58 000847b0 0006f8c0 0006f8c8 nt!NtSecureConnectPort+0x635 (FPO: [Non-Fpo])

    fbe0dd3c 804df06b 000847b0 0006f8c0 0006f8c8 nt!NtConnectPort+0x24 (FPO: [Non-Fpo])

    fbe0dd3c 7c90eb94 000847b0 0006f8c0 0006f8c8 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ fbe0dd64)

    0006f8d0 7c93040b ffffffff 00000000 7c859e48 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    0006f9b0 7c8107fd 00000000 00084718 7c90e642 ntdll!DbgPrint+0x1b (FPO: [Non-Fpo])

    0006fe68 77ea11a8 00000022 00084540 00000000 kernel32!CreateRemoteThread+0x284 (FPO: [Non-Fpo])

    000847a8 00000000 00000001 00000000 00000000 RPCRT4!LRPC_ADDRESS::CompleteListen+0x84 (FPO: [Non-Fpo])

     

     

    Finding all threads in the system involved in LPC communication

     

    To get a consolidated list of all client threads in the system waiting on LPC replies and a list of server threads working on received LPC requests use the “!lpc threads” command without any parameters

     

    0: kd> !lpc thread

    Searching message 0 in threads ...

    Client thread 89a4cdb0 waiting a reply from 15f6                         

        Server thread 898c6a50 is working on message 63f09                        

        Server thread 89671020 is working on message 63f75                        

        Server thread 89904a48 is working on message 63f10                        

        Server thread 88d6bdb0 is working on message 3d6b1                        

        Server thread 89973db0 is working on message 63f32                         

        Server thread 896d32b8 is working on message 3454                        

        Server thread 8995d020 is working on message 63f76                        

        Server thread 8960f020 is working on message 63f77                         

        Server thread 898cd350 is working on message 61bd9                        

        Server thread 8900edb0 is working on message 3832f                        

        Server thread 8900fbf0 is working on message 33c2e                        

        Server thread 88d539a8 is working on message 3343f                        

    Client thread 89be4020 waiting a reply from 6077e                         

    Client thread 89012990 waiting a reply from 39239                         

        Server thread 89012990 is working on message 39232                        

    Client thread 89531020 waiting a reply from 3923d                         

        Server thread 89531020 is working on message 39236                        

    Client thread 88d13b40 waiting a reply from 3c96e                            

     

     

     

    Quick Tips

     

    8 No thread in the system is doing a NtListenPort( ) does that mean no LPC connection  port is open for connections?

     

    !stacks 2 NtListenPort does not return any thread because NtListenPort( ) calls NtRequestWaitReplyPort( ) to wait for an incoming LPC_CONNECTION_REQUEST message. Instead of calling NtListenPort( ) for listening for incoming connections most LPC connection threads directly call NtRequestWaitReplyPort( ).

     

    8 !lpc message does not show any message?

     

    !poolfind LpcM 1 should do the trick.

     

     

    0: kd> !lpc message

     

    Scanning large pool allocation table for Tag: LpcM (8974e000 : 8976e000)

     

    Searching Paged pool (e1000000 : f7000000) for Tag: LpcM

     

     

    0: kd> !poolfind LpcM 1

     

    Scanning large pool allocation table for Tag: LpcM (8974e000 : 8976e000)

     

     

    Searching Paged pool (e1000000 : f7000000) for Tag: LpcM

     

    e1061000 size:  168 previous size:    0  (Allocated) LpcM

    e1090758 size:  168 previous size:    8  (Allocated) LpcM

    e10a7a40 size:  168 previous size:    8  (Allocated) LpcM

    e1188468 size:    8 previous size:   20  (Free)      LpcM

    e1261000 size:  168 previous size:    0  (Allocated) LpcM

    e1297428 size:  168 previous size:    8  (Allocated) LpcM

     

    Once you have the pool blocks listed with the “LpcM” tag dump the ones that are “Allocated”. On a 32-bit machine add 8bytes to the pool address listed on the left most column. On a 64-bit machine add 16bytes i.e. 0x10. Dump the message as below to retrieve the message id.

     

    0: kd> dt nt!_LPCP_MESSAGE e1061000+8

       +0x000 Entry            : _LIST_ENTRY [ 0xe295fa80 - 0xe29279e8 ]

       +0x000 FreeEntry        : _SINGLE_LIST_ENTRY

       +0x004 Reserved0        : 0xe29279e8

       +0x008 SenderPort       : 0xe2327020

       +0x00c RepliedToThread  : (null)

       +0x010 PortContext      : 0x8021000d

       +0x018 Request          : _PORT_MESSAGE

     

    0: kd> dt nt!_LPCP_MESSAGE e1061000+8 Request.

       +0x018 Request  :

          +0x000 u1       : __unnamed

          +0x004 u2       : __unnamed

          +0x008 ClientId : _CLIENT_ID

          +0x008 DoNotUseThisField : 9.8460604703041575e-311

          +0x010 MessageId : 0x4617f

          +0x014 ClientViewSize : 0

          +0x014 CallbackId : 0

     

    0: kd> !lpc message 0x4617f

    Searching message 4617f in threads ...

        Server thread 88f91c08 is working on message 4617f                        

    Client thread 88f0f5f8 waiting a reply from 4617f                         

    Searching thread 88f0f5f8 in port rundown queues ...

     

    Server communication port 0xe2300a38

        Handles: 1   References: 1

        The LpcDataInfoChainHead queue is empty

            Connected port: 0xe2327020      Server connection port: 0xe13734b0

     

    Client communication port 0xe2327020

        Handles: 1   References: 9

        The LpcDataInfoChainHead queue is empty

     

    Server connection port e13734b0  Name: epmapper

        Handles: 1   References: 93

        Server process  : 896e1450 (svchost1.exe)

        Queue semaphore : 8995ac10

        Semaphore state 0 (0x0)

        The message queue is empty

     

     

    8   The number of server threads shown by !lpc thread processing requests is much more than the number of client threads waiting for reply.

     

    !lpc thread interprets stale data in ETHREAD structure as valid LPC information. An indication of the stale data is the ETHREAD.LpcExitThreadCalled will be set. This field is only set when the thread is exiting.

     

    0: kd> !lpc thread

    Searching message 0 in threads ...

    Client thread 89a4cdb0 waiting a reply from 15f6                         

        Server thread 898c6a50 is working on message 63f09                        

        Server thread 89671020 is working on message 63f75                         

        Server thread 89904a48 is working on message 63f10                        

        Server thread 88d6bdb0 is working on message 3d6b1                        

        Server thread 89973db0 is working on message 63f32                        

        Server thread 896d32b8 is working on message 3454                        

        Server thread 8995d020 is working on message 63f76                        

        Server thread 8960f020 is working on message 63f77                        

        Server thread 898cd350 is working on message 61bd9                        

        Server thread 8900edb0 is working on message 3832f                        

        Server thread 8900fbf0 is working on message 33c2e                        

        Server thread 88d539a8 is working on message 3343f     

     

    0: kd> !lpc message 3454

    Searching message 3454 in threads ...

        Server thread 896d32b8 is working on message 3454                        

    Done. 

     

     

    0: kd> dt nt!_ETHREAD 896d32b8 Lpc.

       +0x1c0 LpcReplyChain :  [ 0x896d3478 - 0x896d3478 ]

          +0x000 Flink : 0x896d3478 _LIST_ENTRY [ 0x896d3478 - 0x896d3478 ]

          +0x004 Blink : 0x896d3478 _LIST_ENTRY [ 0x896d3478 - 0x896d3478 ]

       +0x1ec LpcReplySemaphore :

          +0x000 Header : _DISPATCHER_HEADER

          +0x010 Limit : 1

       +0x200 LpcReplyMessage :

       +0x200 LpcWaitingOnPort :

       +0x220 LpcReceivedMessageId : 0x3454

       +0x234 LpcReplyMessageId : 0

       +0x248 LpcReceivedMsgIdValid : 0x1 ''

       +0x248 LpcExitThreadCalled : 0x1 ''

     

    8 Finding all client threads in the system waiting for LPC reply.

     

    !lpc thread

  • Ntdebugging Blog

    Join us on Facebook

    • 0 Comments

    We’ve set up a new Facebook group named “Windows Debugging” as a community for Windows Debugging industry experts.  If Windows debugging is an interest of yours, please consider joining the group!  Many of the regular contributors to this blog will be there as well.  Just login to Facebook and search for “Windows Debugging” to find us, or go here:

    http://www.facebook.com/n/?group.php&gid=23775552268.

  • Ntdebugging Blog

    Windows NT Debugging Blog Live Chat 2

    • 0 Comments

    Windows NT Debugging Blog Live Chat

    Microsoft Platform Global Escalation Services is hosting our second live group debug chat session for the debugging community on March 17, 2009 at 11 AM Pacific Time.  We will be focusing on debugging techniques and any questions you may have about anything we’ve previously blogged about. 

    Details about the “PGES-Windows NT Debugging Blog Live Chat” can be found here: http://www.microsoft.com/communities/chats/default.mspx

Page 21 of 24 (240 items) «1920212223»