I recently built a timed lock picking competition, based on a similar design created by @dossman33. It consists of four deadbolts (plus two spares), all pinned identically, that, when opened, trigger a switch wired to a Raspberry Pi. The Pi has a UI written in Python that shows the current elapsed time, plus the time that each station opened. I’ve shared the code at https://github.com/mburrough/locktimer.
As both a locksport enthusiast and a professional red teamer, I spend a good deal of time thinking about locks. One fascinating subset of locks is master keyed systems. These are primarily used by large businesses to create a hierarchy of locks and keys: individuals can have a key that works for the building front door and their own offices, managers can have keys that work on any of their subordinates’ offices, janitors can have keys to their assigned floors’ offices, while security guards and maintenance can have keys to any room.
Depending on how these systems are implemented, they may suffer from an inherent weakness. Often, the bitting (key cuts) used for the top master key (e.g. the one used by security) cannot be used in any individual user key. For example, if the top master key code is 6-3-4-2-2, a valid user key may be 4-1-6-4-5, but could not be 4-1-6-2-5. This means that given the codes for enough user keys, an attacker could eliminate most/all possibilities except for the master key bitting, thereby decoding the master key.
This may sound like it would take a large number of keys to find the master (especially for keys with 6 or 7 cuts and 7+ possible cut depths per position), there is another feature of many key systems that helps narrow the space: MACS. MACS are the Maximum Adjacent Cut Specification for a given brand/model. These are standards that say a key cannot go from a very small cut in one position to a very large cut in the next position, as the key could be too weak and might break off in a lock (or pocket, or purse).
Similar to MACS, some systems also restrict user keys from being within a certain offset (e.g. +/- 1) of the master. In such a system, 4-1-6-1-5 might also be invalid with the above example master key.
For this kind of attack, the attacker would either need to covertly view users’ keys and eliminate cuts, or work with insider co-conspirators to view their keys. But would the number of keys needed to be viewed be feasible? To answer this, I created a computer model that simulates the attack and displays the number of keys needed for that attack. Simply input the specifications for the key system in question, plus the number of runs desired for the model, and it will display the average, minimum, and maximum number of keys needed across the test executions.
I’m excited to announce my first book, PenTesting Azure Applications, is available for preorder from Amazon and No Starch’s site. This title aims to provide a reference guide for security professionals looking to assess cloud deployments. It offers practical advice for how to properly lock down subscriptions and their services, and make use of Azure’s monitoring and security features.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
Recently, I was contacted by a customer who was advised by an ISV to set a registry value under one of the sub keys in HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager. Let’s call it UseQuantumComputing = 1 (value name has been changed to protect the ISV). The customer wanted to know what this value actually did and no one could find any documentation explaining it. These issues often come to our team because we have access to the Windows source code. I did a bit of code review to find out what this value does. As it turns out, nowhere in Windows source code between Windows 2000 and Windows Server 2012 do we ever check for or set UseQuantumComputing.
I can think of a few reasons the ISV would suggest setting this value. Perhaps they were under the impression this did something but got confused about the value name. It’s possible they hoped making a registry change would have a placebo effect. Or, perhaps their software actually checks this value, not Windows.
The latter of these possibilities is probably the worst case scenario. An ISV should not create a registry value inside of keys used for Windows’ own internal use. Why? The first reason is that there’s no guarantee that Microsoft won’t end up coincidentally using that same value name later. This would cause a conflict between the two users of the value. Second, we have to consider the scenario where two different ISVs both decide to use the same value. That would be bad too. Lastly, there’s no guarantee that the key in use will still exist in later versions, or that it will be writable or readable by the ISV due to permission changes. In addition to all these reasons, there is the common sense issue that it is just confusing. Now the ISV’s software and uninstaller needs to look all over the registry, not just in their own keys.
On a similar note, I also recently had a case where a “Windows Tips” blog (not created, endorsed, or run by Microsoft) suggested using a registry value that was implemented in Windows but was not documented by Microsoft. It turns out this value wasn’t thoroughly tested (because it was undocumented and wasn’t intended to be used in production), and using it would cause server hangs under certain conditions. These hangs were only discovered after a large customer decided to implement the undocumented value across their enterprise.
Here are a few tips for IT Pros, developers, and users alike:
Don’t implement random registry settings if you can’t find documentation for that setting on an official Microsoft site, like MSDN, TechNet, or support.microsoft.com(information on forums or answer boards (e.g. social.*.microsoft.com or answers.*.microsoft.com) is not official documentation). At best these unknown registry settings they will do nothing, at worst they will cause you headaches later.
If a key/value isn’t documented, changes to it likely are not tested, and could put your machine in a state that makes it difficult or impossible to support.
If you are a developer, keep any of your registry settings in your own key. Don’t pollute in others’ keys.
If an ISV or Microsoft suggests you implement a setting, make sure you understand the implications of that setting.
I’ll leave you with the warning displayed in many of our KBs – it’s there for a reason!
“WARNING: If you use Registry Editor incorrectly, you may cause serious problems that may require you to reinstall your operating system. Microsoft cannot guarantee that you can solve problems that result from using Registry Editor incorrectly. Use Registry Editor at your own risk.”
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
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:
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)] //It's 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.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
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 – so 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 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 the viewers when one of the viewers in the chain was 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 new viewer in line about an update, rendering that 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:
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:
Note the spwndClipViewer, spwndClipboardListener, and spwndClipOwner fields. 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 for spwndClipViewer, spwndClipboardListener, and spwndClipOwner. First, dt the value as a tagWND. We’ll use the spwndClipViewer for this demonstration:
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:
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.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
Recently, I had the opportunity to debug the clipboard in Windows, and I thought I’d share some of the things I learned. The clipboard is one of those parts of Windows that many of us use dozens (hundreds?) of times a day and don’t really think about. Before working on this case, I had never even considered how it works under the hood. It turns out that there’s more to it than you might think. In this first article, I’ll describe how applications store different types of data to the clipboard and how it is retrieved. My next post will describe how applications can hook the clipboard to monitor it for changes. In both, I’ll include debug notes to show you how to access the data from the debugger.
Let’s start by discussing clipboard formats. A clipboard format is used to describe what type of data is placed on the clipboard. There are a number of predefined standard formats that an application can use, such as bitmap, ANSI text, Unicode text, and TIFF. Windows also allows an application to specify its own formats. For example, a word processor may want to register a format that includes text, formatting, and images. Of course – this leads to one problem – what happens if you want to copy from your word processor and paste into Notepad, which doesn’t understand all of the formatting and pictures?
The answer is to allow multiple formats to be stored in the clipboard at one time. When I used to think of the clipboard, I thought of it as a single object (“my text” or “my image”) but in reality, the clipboard usually has my data in several different forms so when I paste, the destination program gets a format it can use.
So how does this data end up on the clipboard? Simple – an application first takes ownership of the clipboard via the OpenClipboard function. Once it has done that, it can empty the clipboard with EmptyClipboard. Finally, it is ready to place data on the clipboard using SetClipboardData. SetClipboardData takes two parameters – the first is the identifier of one of the clipboard formats we discussed above. The second is a handle to the memory containing the data in that format. The application can continue to call SetClipboardData for each of the various formats it wishes to provide going from best to worst (since the destination application will select the first format in the list it recognizes). To make things easier for the developer, Windows will automatically provide converted formats for some clipboard format types. Once the program is done, it calls CloseClipboard.
When a user hits paste, the destination application will call OpenClipboard and one of these functions to determine what data format(s) are available: IsClipboardFormatAvailable, GetPriorityClipboardFormat, or EnumClipboardFormats. Assuming the application finds a format it can use, it will then call GetClipboardData with the desired format identifier as a parameter to get a handle to the data. Finally, it will call CloseClipboard.
Now let’s take a look at how you can find what data being written to the clipboard using the debugger. (Note that all of my notes are taken from a Win7/2008 R2 system – so things might vary slightly in different versions of the OS.) Since the clipboard is part of Win32k.sys, you’ll need to use a kernel debugger. I like to use win32k!InternalSetClipboardData+0xe4 as a breakpoint. The nice thing about this offset is that it is right after we’ve populated the RDI register with data from SetClipboardData in a structure known as tagCLIP.
Fmt is the clipboard format. 0xd is 13, which indicates this data is Unicode text. We can’t just ‘du’ the value in hData, however, because this is a handle, not a direct pointer to the data. So now we need to look up the handle. To do that, we need to look at a win32k global structure – gSharedInfo:
aheList in gSharedInfo contains an array of handle entries, and the last 2 bytes of hData multiplied by the size of a handle entry the address of our handle entry:
If we look in phead at offset 14, we’ll get our data:
kd> du fffff900`c0de0fb0 + 0x14
fffff900`c0de0fc4 "Hi NTDebugging readers!"
Let’s consider one other scenario. I copied some text out of Wordpad, and a number of SetClipboardData calls were made to accommodate different formats. The Unicode format entry looks like this:
hData is null! Why is that? It turns out that the clipboard allows an application to pass in null to SetClipboardData for a given format. This indicates that the application can provide the data in that format, but is deferring doing so until it is actually needed. Sure enough, if I paste the text into Notepad, which needs the text in Unicode, Windows sends a WM_RENDERFORMAT message to the WordPad window, and WordPad provides the data in the new format. Of course, if the application exits before populating all of its formats, Windows needs all of the formats rendered. In this case, Windows will send the WM_RENDERALLFORMATS message so other applications can use the clipboard data after the source application has exited.
That’s all for now. Next time we’ll look at how applications can monitor the clipboard for changes using two hooks. If you want to know more about using the clipboard in your code, this is a great reference.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
Matt Burrough here again. On rare occasions when debugging, we’ll actually know (or strongly suspect) what the root cause of a problem is at the beginning of our analysis – but we still need to investigate to confirm our assertion. The following is a case study for an issue I worked on recently where the print spooler was hanging.
This customer had recently upgraded their print servers from Windows 2003 to Windows 2008 R2. After the upgrade, the spooler would frequently go unresponsive, and no jobs could be printed. Rebooting the server provided some relief, but the problem would reoccur as the jobs started coming in again.
One of my peers had completed an initial analysis of a user mode memory dump of the spooler process, and found that spooler seemed to be blocked waiting on PrintIsolationHost.exe. For those not familiar with recent changes to the print spooler’s design – Print Isolation Host was added in Windows 7/2008 R2 as a way to isolate print drivers from each other and from the spooler process so a crash in one driver doesn’t take down the entire printing environment. Given the large number of print drivers found on some print servers, this can be a great help for stability and availability of the spooler. See http://blogs.technet.com/b/askperf/archive/2009/10/08/windows-7-windows-server-2008-r2-print-driver-isolation.aspx if you would like more details on Print Isolation Host.
Unfortunately for my team mate, the data collected did not include dumps of Print Isolation Host, so he requested that the next time the problem happened that both spooler and PrintIsolationHost dumps would be gathered. The customer had configured his server for the “Isolated” Print Isolation Host option during troubleshooting, which places each driver in its own process. (The default is shared which places all drivers in one PrintIsolationHost.exe instance. Driver isolation is configured using the Print Management Console.)
The next morning, the newly requested data came in, and since the problem was urgent, I began looking at the new dumps immediately. This dataset included both a spoolsv.exe dump, as well as nearly two dozen PrintIsolationHost dumps! I knew from the past analysis that I should start with the PrintIsolationHost data – but where to begin? In order to triage the dumps, I wrote a small batch file to open each dump (luckily, they were sequentially numbered), write the call stacks in each thread to a file, and close the log. On every iteration, the script created a new cmd.txt file, which contained a set of commands that were passed to the debugger. This allowed me to name the debugger output files sequentially with names that matched their dump (e.g. PrintIsolationHost1.txt contained output from PrintIsolationHost1.dmp).
set x=1
:Top
echo .reload > c:\data\cmd.txt
echo .logopen c:\data\PrintIsolationHost%x%.txt >> c:\data\cmd.txt
echo ~*kc >> c:\data\cmd.txt
echo .logclose >> c:\data\cmd.txt
echo qq >> c:\data\cmd.txt
c:\debuggers\kd.exe -cf c:\data\cmd.txt -z "c:\data\PrintIsolationHost%x%.DMP"
set /A x+=1
IF %x% LEQ 23 GOTO Top
Now that I had a directory full of text files, I used my favorite differencing tool to compare the stacks in each text file. I used the first PrintIsolationHost file as a reference. It only had four stacks, and these were common to all of the other files:
I was able to rule out a number of other PrintIsolationHost instances that were either identical to this one (aside from the process/thread IDs and Tebs), or which just had one or two additional idle worker threads (like thread 3 above).
Things got interesting when I looked at two of the PrintIsolationHost dumps. Both had these two stacks not found in any other the other dumps (note that I do not have symbols for the 3rd-party print processor ProseWarePrintProcessor):
2 Id: 20a4.1328 Suspend: 0 Teb: 000007ff`fffda000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
ntdll!LdrLockLoaderLock
*** ERROR: Symbol file could not be found. Defaulted to export symbols for ProseWarePrintProcessor.dll -
KERNELBASE!GetModuleFileNameW
ProseWarePrintProcessor
ProseWarePrintProcessor
ProseWarePrintProcessor!ControlPrintProcessor
PrintIsolationProxy!sandbox::PrintProcessor::ControlPrintProcessor
rpcrt4!Invoke
rpcrt4!Ndr64StubWorker
rpcrt4!NdrStubCall3
ole32!CStdStubBuffer_Invoke
ole32!SyncStubInvoke
ole32!StubInvoke
ole32!CCtxComChnl::ContextInvoke
ole32!AppInvoke
ole32!ComInvokeWithLockAndIPID
ole32!ThreadInvoke
rpcrt4!DispatchToStubInCNoAvrf
rpcrt4!RPC_INTERFACE::DispatchToStubWorker
rpcrt4!RPC_INTERFACE::DispatchToStub
rpcrt4!RPC_INTERFACE::DispatchToStubWithObject
rpcrt4!LRPC_SCALL::DispatchRequest
rpcrt4!LRPC_SCALL::HandleRequest
rpcrt4!LRPC_ADDRESS::ProcessIO
rpcrt4!LrpcIoComplete
ntdll!TppAlpcpExecuteCallback
ntdll!TppWorkerThread
kernel32!BaseThreadInitThunk
ntdll!RtlUserThreadStart
6 Id: 20a4.1668 Suspend: 0 Teb: 000007ff`fffac000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
ProseWarePrintProcessor
ProseWarePrintProcessor
ProseWarePrintProcessor
ntdll!LdrpInitializeThread
ntdll!_LdrpInitialize
ntdll!LdrInitializeThunk
Interesting. Thread 6 is running the DllMain code for the ProseWarePrintProcessor DLL which holds the loader lock. It is waiting on a critical section. Meanwhile, thread 2 is waiting on the loader lock. So who holds the critical section that thread 6 wants? First, let’s find what lock thread 6 wants:
0:006> kn
# Child-SP RetAddr Call Site
00 00000000`0104eb18 00000000`777fe4e8 ntdll!ZwWaitForSingleObject+0xa
01 00000000`0104eb20 00000000`777fe3db ntdll!RtlpWaitOnCriticalSection+0xe8
02 00000000`0104ebd0 00000000`750c5d6b ntdll!RtlEnterCriticalSection+0xd1
03 00000000`0104ec00 00000000`750c6256 ProseWarePrintProcessor+0xabf
04 00000000`0104ec30 00000000`750c7015 ProseWarePrintProcessor+0xfaa
05 00000000`0104f090 00000000`777dc76c ProseWarePrintProcessor+0x1d69
06 00000000`0104f1f0 00000000`777dc42f ntdll!LdrpInitializeThread+0x17c
07 00000000`0104f2f0 00000000`777dc32e ntdll!LdrpInitialize+0x9f
08 00000000`0104f360 00000000`00000000 ntdll!LdrInitializeThunk+0xe
0:006> .frame /c /r 2
02 00000000`0104ebd0 00000000`750c5d6b ntdll!RtlEnterCriticalSection+0xd1
rax=0000000300d1001a rbx=00000000750ca330 rcx=00000000001d0000
rdx=0000000000000040 rsi=0000000000000001 rdi=0000000000000004
rip=00000000777fe3db rsp=000000000104ebd0 rbp=00000000ff000000
r8=00000000002c6a00 r9=00000000002c6a10 r10=0000000000000073
r11=0000000000000001 r12=000007fffffd6000 r13=00000000778e2660
r14=0000000000000001 r15=000000007780a280
iopl=0 nv up ei pl zr na po nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246
ntdll!RtlEnterCriticalSection+0xd1:
00000000`777fe3db 83f801 cmp eax,1
0:006> ub 00000000`750c5d6b <----------- Let's see what gets passed to RtlEnterCriticalSection
ProseWarePrintProcessor+0xaa2:
00000000`750c5d4e f9 stc
00000000`750c5d4f ff743f33 push qword ptr [rdi+rdi+33h]
00000000`750c5d53 d2ff sar bh,cl
00000000`750c5d55 15aeb4ffff adc eax,0FFFFB4AEh
00000000`750c5d5a 85c0 test eax,eax
00000000`750c5d5c 7533 jne ProseWarePrintProcessor+0xae5 (00000000`750c5d91)
00000000`750c5d5e 488d0dcb450000 lea rcx,[ProseWarePrintProcessor+0x5084 (00000000`750ca330)] <----- Critical section is in rcx
00000000`750c5d65 ff15bdb3ffff call qword ptr [ProseWarePrintProcessor+0x1128 (00000000`750c1128)]
0:006> u ntdll!RtlEnterCriticalSection
ntdll!RtlEnterCriticalSection:
00000000`77802fc0 fff3 push rbx
00000000`77802fc2 4883ec20 sub rsp,20h
00000000`77802fc6 f00fba710800 lock btr dword ptr [rcx+8],0
00000000`77802fcc 488bd9 mov rbx,rcx <------------------ Critical section is saved in RBX. RBX isn't modified between here and our current position
00000000`77802fcf 0f83e9b1ffff jae ntdll!RtlEnterCriticalSection+0x31 (00000000`777fe1be)
00000000`77802fd5 65488b042530000000 mov rax,qword ptr gs:[30h]
00000000`77802fde 488b4848 mov rcx,qword ptr [rax+48h]
00000000`77802fe2 c7430c01000000 mov dword ptr [rbx+0Ch],1
0:006> r rbx
Last set context:
rbx=00000000750ca330<----- This is the address of the critical section thread 6 is waiting for
Now let’s look at the threads in this process, and the held locks:
That’s not good! We can see that thread 6 indeed owns the loader lock, which thread 2 is waiting for. But thread 2 owns the ProseWarePrintProcessor lock – and thread 6 is waiting for it! This is a classic deadlock. In fact, Raymond Chen even described this on his blog. More information about LdrInitialize can be found here.
So we know that there is a deadlock in the Print Isolation Host, but why exactly does this cause spooler to hang? Here’s where we work backwards. We know that thread 6 is handling DLL initialization, but what is thread 2 doing? From the stack we can see it is handling an RPC request that called into ProseWarePrintProcessor. Let’s determine who called into this thread.
I know that the code in frame 19 deals with processing the RPC and has a record of the calling process’ PID and TID. In fact, from a bit of code review, I know that at this portion of the code, we get back a value that contains a ntdll!_CLIENT_ID structure at offset 8:
Reviewing the assembly, from ProcessIO+0xe6 to where we are now (ProcessIO+0x3bf), we don’t modify rdi again – and rdi is nonvolatile – so if we switch to that frame and check out rdi+8, we’ll know who called this thread!
So now we know that the caller was process 0x2694 and thread 0x5e8, or 9876 and 1512 in decimal, respectively. Our current process (PrintIsolationHost.exe) is PID 20a4 (see above ~ output), or 8356 decimal. So who is 9876? I happen to have a Process Listing from the dump of the data collection:
It’s calling into the print isolation host as we expect. It looks like it is doing that to end a print job, based on an RPC call it received. Using our same method as last time, let’s pull out the PID and TID he is responding to:
Perfect. So now we know that localspl was printing a document, which resulted in all of these RPC calls between spooler and Print Isolation Host, and ultimately the deadlock in Print Isolation Host is holding up this thread. Just out of curiosity, are there any other threads blocked on this wait chain?
Yes there are. Thread 5e8, which we looked at earlier, is holding a lock that 104 other threads are waiting for! This dump had 177 threads, so we know now that thread 5e8, 14cc, and 104 others in spooler are all hung on this deadlock. With about 60% of all the threads in spooler hung, the deadlock in ProseWarePrintProcessor is clearly the cause of our issue. Here’s the final wait chain diagram:
To resolve the issue, ProseWarePrintProcessor needs to avoid calling GetModuleFileName while its DllMain routine is still running, since the former requires, and the latter holds, the Loader Lock.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
Hi all, Matt here again. One of our team’s main functions is to work with our development teams to create hotfixes when customers run into issues that can only be resolved through a code change. The developers will often prepare a private hotfix that either tests the proposed change, or adds additional instrumentation to help pinpoint the issue. The private hotfix is sent to the customer reporting the problem so they can confirm that it does indeed correct (or identify) the flaw.
When testing a private hotfix, customers frequently ask, why does my desktop now show a message on the lower right corner of the desktop, and what does it mean? The message reads “For testing purposes only”, and looks like this:
Often, users are concerned that his message means that they aren’t allowed to use the server in production, or maybe that it is now “unsupported.” These aren’t the case! Since this message appears as a result of installing a fix during the course of a Microsoft Support case, the servers are, by definition, being supported.
The purpose of this message is simply to remind users that code that Microsoft Support has asked them to test has been installed on the system, and this code may not have yet undergone the full suite of quality assurance testing that fixes that are made public do.
For comparison, let’s look at some of the other watermarks you may find in the lower corner of the desktop – as these can often be confused for the above message, and may explain some of the fears around these messages.
First up is the old trusty text you see when a box is booted into ‘Safe Mode’. I’m sure every IT Pro has seen this at one time or another, so I won’t go into detail, but rest assured, the testing purposes text is completely unrelated to booting in safe mode or having a subset of services running.
Next up is our ‘Evaluation copy’ watermark. This message is shown on the desktops of copies of Windows that have a “time bomb” (ones that will cease to function after a certain date.) This message is typically seen on beta versions of Windows which are designed to stop functioning sometime after the desired beta testing period ends.
Third, we have our Windows is not genuine message. This is shown if, for example, a copy of Windows is not activated during the grace period after the installation process, or if a number of hardware changes have been made and Windows needs to be re-activated. This has nothing to do with the ‘testing purposes’ message. See http://technet.microsoft.com/en-us/library/dd979803.aspx for more information about this message.
Fourth, we have the general Windows build stamp. This is enabled via the registry using the PaintDesktopVersion DWORD (http://technet.microsoft.com/en-us/library/cc782257(WS.10).aspx). Some administrators like to enable this option so they always know what version of Windows they are using, sort of like a mini-bginfo. Unlike all of the others, this message does not indicate anything else about a server’s state.
And finally, we have ‘Test Mode’. This is actually somewhat related to the testing purposes message. This ‘Test Mode’ text is shown when test signing is enabled on a PC. This is done by running “bcdedit /set testsigning on” from an UAC-elevated command prompt. Test signing is used to allow developers to load drivers they are still working on that have not yet been code signed with an official certificate. This is actually one of the steps we need to do when loading our test fixes. For more information on Test Signing, see http://msdn.microsoft.com/en-us/library/ff553484%28v=VS.85%29.aspx.
So now that you know what causes these various watermarks to appear, perhaps you’re wondering how to make the “For testing purposes only” message disappear. This is a question we are frequently asked. While you are running a test hotfix, there is no way to disable this message. Your only option is to remove the test hotfix from your system. This is something your engineer will ask you to do before you install the final, public version of a hotfix. You can easily identify and uninstall test hotfixes by going into Control Panel, Programs and Features, View Installed Updates, then look for hotfixes with the words FOR TESTING PURPOSES ONLY in their name, like the one shown in the image below. You may also notice that the KB number listed for these fixes is often a place holder, and not a real KB article ID.
If the ‘For testing purposes only’ message is still displayed even after uninstalling the test hotfix, there is one more place to check. If a system has the Microsoft Test Root Authority certificate installed into its Trusted Root Certification Authorities store, the text will be displayed. We use this certificate to allow a PC to run test code that has been signed by our development team, but not yet fully tested and signed off with the official Microsoft certificate. To remove this certificate from your system, go to Start -> Run, and enter certmgr.msc and hit enter. In the Certificate Manager MMC, browse to Trusted Root Certification Authorities, then into Certificates. You should see one labeled Microsoft Test Root Authority, as shown below. This will need to be deleted and the system rebooted to remove the testing purposes message. Don’t do this if you still have a test hotfix installed though, as it would prevent that binary from continuing to function and may mean you can no longer boot in to Normal or Safe mode.
If you reboot and find that ‘Text Mode’ has replaced the ‘For testing purposes only’ text, you’ll need to launch a command prompt with administrative privileges, then run “bcdedit /set testsigning off” and reboot. You can always check if test signing is enabled by running “bcdedit /enum” and looking for this line:
That’s all for today. Hopefully this post helped clear up any confusion about our different desktop watermarks.
This is an archive post of content I wrote for the NTDebugging Blog on MSDN. Since the MSDN blogs are being retired, I’m transferring my posts here so they aren’t lost. The post has been back-dated to its original publication date.
A customer recently reported a rather peculiar problem. They were working on a roll out of Windows 7, and one of the policies they employed on their domain was the “Show only specified control panel applets” setting. As its name implies, this policy allows an administrator to specify the names of any Control Panel icons they want their users to see, and all others are not shown. This company chose to allow a few of the Control Panel items included with Windows as well as the Mail icon that is added when Microsoft Office (specifically Outlook) is installed, which allows users to configure their Outlook profiles.
The problem the customer noticed was that, with the policy was in place, the first time a user opened the Control Panel on a computer, all of the allowed icons appeared except for Mail. If the user closed Control Panel and reopened it, the icon suddenly appeared. In fact, from that point on, the Mail icon would appear for that user on that computer. However, if that user logged on to a different computer, or a different user logged in to the first user’s computer, the icon was missing until Control Panel was opened for a second time.
Control Panel isn’t something we get many cases on, so I had to figure out how it worked, and what would cause it to fail only the first time. One of the first things I discovered as I debugged the issue was that the Control Panel is actually loaded in two passes – a “fast” pass and a “slow” pass. This is done so icons we know will be loaded quickly can be displayed first so a user doesn’t get stuck with an empty window waiting for some of the slower icons to load. What makes an icon fast or slow? It turns out shell maintains a cache of Control Panel items, so it can display them quickly without having to query the actual item for its name, description, icon, etc. If we have to ask the item for its information, that will take longer, so it is loaded during the second, slow phase:
Luckily for these icons, they won’t stay relegated to slow loading status forever. During the slow loading phase, one of the things we do is add the item’s information to the Control Panel cache, so we can load it during the fast phase in the future.
This explains why the item was being loaded on subsequent opens of Control Panel – the item was added to the user’s cache on the first run, so the next time, it was loaded during the fast pass:
But that only answers half the question – while we now know why the icon appears every other time, we still don’t know why it doesn’t show up the first time. To figure this out, I debugged a system with the “Show only specified control panel applets” policy applied and one without the policy set, both as they opened Control Panel for the first time, and compared where the return codes from the functions diverged.
Starting with CControlPanelEnum::_NextNonCachedCpl, in the non-working case, we can see that it returns 0:
0:003> bp shell32!CControlPanelEnum::_NextNonCachedCpl
0:003> g
Breakpoint 0 hit
eax=14c5fa8c ebx=14c5fa7c ecx=11224630 edx=00000000 esi=11224630 edi=14c5fa8c
eip=76977e11 esp=14c5f9b4 ebp=14c5f9c8 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
shell32!CControlPanelEnum::_NextNonCachedCpl:
76977e11 8bff mov edi,edi
0:020> k
ChildEBP RetAddr
14c5f9b0 76977dff shell32!CControlPanelEnum::_NextNonCachedCpl
14c5f9c8 768a854d shell32!CControlPanelEnum::Next+0x5a
14c5fa18 769710d2 shell32!CRegFolderEnum::Next+0x22e
14c5fa94 769783e7 shell32!CControlPanelAppletList::_AddAppletsToCategories+0x35
14c5fac4 76978353 shell32!CControlPanelAppletList::LoadSlowApplets+0x68
14c5faec 76974db4 shell32!CControlPanelDataWorkItem::_LoadSlowData+0x2e
14c5fb00 769e06ad shell32!CControlPanelDataWorkItem::DoWork+0x4b
14c5fb18 768d83a6 shell32!CFrameTask::InternalResumeRT+0x14
14c5fb38 7691639b shell32!CRunnableTask::Run+0xce
14c5fb54 76918c1f shell32!CShellTask::TT_Run+0x167
14c5fb9c 76918d53 shell32!CShellTaskThread::ThreadProc+0xa3
14c5fba4 760cb2b1 shell32!CShellTaskThread::s_ThreadProc+0x1b
14c5fbb4 77c8d877 shlwapi!ExecuteWorkItemThreadProc+0xe
14c5fc28 77c90842 ntdll!RtlpTpWorkCallback+0x11d [d:\w7rtm\minkernel\threadpool\compat\worker.c @ 284]
14c5fd80 00000000 ntdll!TppWorkerThread+0x572
0:020> gu * <------------- This steps out to the instruction after the call to CControlPanelEnum::_NextNonCachedCpl in CControlPanelEnum::Next.
ModLoad: 35c70000 35c8b000 c:\progra~1\common~1\system\msmapi\1033\mlcfg32.cpl
eax=00000000 ebx=14c5fa7c ecx=bea347f1 edx=006d2904 esi=11224630 edi=14c5fa8c
eip=76977dff esp=14c5f9bc ebp=14c5f9c8 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
shell32!CControlPanelEnum::Next+0x5a:
76977dff 84c0 test al,al
But on the machine without the policy set, it returns 1:
So we know something in this function is causing us to return FALSE in the failing case and TRUE in the working case. An easy way to see where the return result of function calls is the wt (watch trace) debugger command with the -oR switch to see the return values. I set the level (-l) to 1 so I’d only see functions directly called from CControlPanelEnum::_NextNonCachedCpl. Here were the results.
Here, we can see that the function CControlPanelEnum::_CanEnumerateApplet returns true in the working case, but false in the failing case. This is what is causing the return value from _NextNonCachedCpl to differ, which is ultimately what causes the icon to load/not load. So let’s take a look at _CanEnumerateApplet. Using wt inside this function showed something rather interesting:
Looking at the two, we can see that they both call GetDetailsEx, but in the failing case we seem to get an error result: 80070002, and in the working case we get 0, and then proceed to call CPL_DoesPolicyAllow. CPL_DoesPolicyAllow is not called on the machine with the policy applied. A quick code review of CPL_DoesPolicyAllow showed that this function checks if a policy prevents or allows an item from being displayed. So if we can just get to that function, the icon will load. Now we need to know why GetDetailsEx fails, preventing us from calling CPL_DoesPolicyAllow. If we look up the error code, it is pretty generic:
0:020> !error 80070002
Error code: (HRESULT) 0x80070002 (2147942402) - The system cannot find the file specified.
Next I stepped through and into GetDetailsEx. I’ll save you the tedious steps and output, since the procedure is similar to what I’ve already shown above. Anyway, I was able to trace the error 2 as being returned by a call to the registry a few functions deep into GetDetailsEx:
This is good news, because it means we can find out what we’re looking for that we aren’t finding. First I stepped out to get back to CControlPanelFolder::_InitExtPropRegValNameCache. Sure enough, eax was 2, which is our ‘cannot find the file’ error.
0:020> gu
eax=00000002 ebx=00000000 ecx=778ac2da edx=00000002 esi=14c5eff0 edi=00000000
eip=76975ead esp=14c5ed40 ebp=14c5efc4 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
shell32!CControlPanelFolder::_GetExtPropRegKey+0xb1:
76975ead 50 push eax
0:020> !error 2
Error code: (Win32) 0x2 (2) - The system cannot find the file specified
Since we know that RegOpenKeyEx takes the subkey it is looking for as the second parameter, let’s look back at the assembly before the call to see what we passed in:
Remember that function parameters are passed in in reverse order, so the second parameter is the second to last value passed to the function. In this case, we can see that it was stored in eax. Of course, eax has been overwritten by our return value of 2, but we can see that just before pushing eax, we get the value from ebp-0x270. Dumping that out as a Unicode string, we get the key we were looking for:
Aha! So now we know we were trying to access “HKLM\ Software\Microsoft\Windows\CurrentVersion\Control Panel\Extended Properties\System.ApplicationName” which didn’t exist, so we were unable to proceed with loading the icon.
What’s that key for, you ask? MSDN tells us that it is used to store the Canonical Name of the Control Panel item. Canonical Names were added to the Control Panel in Windows Vista as a better way to organize and name the items in the Control Panel. By convention, the canonical name of “Mail” is “Microsoft.Office.Outlook.Profiles.” Because the “Show only specified control panel applets” policy can now accept either the legacy name (“Mail”) or the canonical name, we are checking the registry for this string. Since the key is not present, GetDetailsEx cannot determine the canonical name, and the icon does not load.
As a test, I created the key HKLM\ Software\Microsoft\Windows\CurrentVersion\Control Panel\Extended Properties\System.ApplicationName and added a REG_SZ to it with a name of the file location of the Mail CPL file (“C:\Program Files\Common Files\SYSTEM\MSMAPI\1033\MLCFG32.CPL”) and a value of “Microsoft.Office.Outlook.Profiles”. Sure enough, the icon loads up on the first try for new users.
While new Control Panel items should implement a canonical name, that doesn’t work for existing CPLs, like Mail from Outlook 2003. Since the canonical name isn’t actually required (CPL_DoesPolicyAllow works with both name formats), we’re following up with the development team to allow CPL_DoesPolicyAllow to be called even if a canonical name is not found.