The Case of the Slow Keynote Demo
A couple of weeks ago I participated for the first time in the keynote at Microsoft’s Teched US conference to a room of over 5,000 attendees. Bill Veghte, the Senior Vice President of Windows marketing, led the keynote and gave a tour of the user-focused features of Windows 7, Iain McDonald, General Manager for Windows Server, demonstrated new functionality in Hyper-V and Windows Server 2008 R2, and I demonstrated IT Pro-oriented enhancements in Windows 7 and Microsoft Desktop Optimization Pack (MDOP).
I showed features like BitLocker To Go group policy settings, PowerShell v2’s remoting capabilities, PowerShell’s ability to script group policy objects, Microsoft Enterprise Desktop Virtualization (MEDV) and how the combination of App-V, roaming user profiles and folder redirection enable a replaceable PC scenario with minimal downtime. One point I reinforced was the fact that we made every effort to ensure that application-compatibility fixes (called shims) that IT Pros have developed for Vista applications work on Windows 7. I also demonstrated Windows 7’s new AppLocker feature, which allows IT Pros to restrict the software that users can run on enterprise desktops with flexible rules for identifying software.
In the weeks leading up to the keynote I worked with Jason Leznek, the owner of the IT Pro portion of the keynote, to identify the features I’d showcase and to design the demos. We used dry runs to walk through the script, tweaking the demos and creating transitions, trimming content to fit the time allotted to my segment, and tightening my narration to focus on the benefits of the new technologies. For the application-compatibility demo, we decided to use a sample program used internally at Microsoft, called Stock Viewer, that’s intentionality incompatible with Vista and Windows 7 in ways representative of actual line-of-business software that doesn’t run without assistance on these newer operating systems. In my demo, I would launch Stock Viewer on Windows 7 and show how its trends report function fails with an obscure error message caused by incompatibility:
Then I’d show how I could deploy an application compatibility shim that enables the application to work correctly on Vista and then rerun the application successfully.
We also wanted to show how AppLocker’s rule creation wizard makes it easy to allow software to run based on the publisher or version if the software is digitally signed. Originally, we planned on showing AppLocker after the application compatibility demo and enabling Adobe Acrobat Reader, an application commonly used in enterprises. We rehearsed this flow a couple of times, but found the transitions a little awkward, so I suggested that we sign the Stock Viewer executable and move the AppLocker demo before the shim demo. I’d be able to enable Stock Viewer to run with an AppLocker rule and then show how the shim helps it run correctly, using it for both demos.
I went back to my office, signed Stock Viewer with the Sysinternals signing certificate and sent it to Jason. A few hours later he emailed me saying that something was wrong with the demo system because Stock Viewer, which had previously launched instantly, now took over a minute to start. We were counting down to TechEd and he was panicked because we needed to nail down the demos. I had heard at some point in the past that .NET does authenticode signature checks when it loads digitally signed assemblies, so my first suspicion was that it was related to that. I asked Jason to capture a Process Monitor trace and he emailed it back a few minutes later.
After opening the log, the first thing I did was filter events for StockViewer.exe by finding its first operation and right-clicking to set a quick filter:
Then I looked at the timestamps on the first item, 2:27:20, and the last item, 2:28:32, which correlated with the minute delay Jason had observed. As I scrolled through the trace I saw many references to cryptography (crypto) Registry keys and file system directories, as well as references to TCP/IP settings, but I knew that there had to be at least one major gap in the timestamps to account for the long delay. I scanned the log from the beginning and found a gap of roughly 10 seconds at 2:27:22:
The operations immediately before were references to the Rasadhlp.dll, a networking-related DLL, and a little earlier there were lots of references to Winsock registry keys, with accesses to crypto Registry keys immediately after the 10 second delay. It appeared that the system was not connected to the Internet and that the application was held up by some networking timeout of roughly 10 seconds. I looked forward in order to find the next gap and came across a 12-second interval:
Again, networking-related activity before, and crypto related activity after. The subsequent gap, also of 12-seconds, was identical:
In fact, the next few gaps looked virtually identical. In each case there was a reference to HKCU\Software\Microsoft\Windows\CurrentVersion\Internet Settings\Connections immediately before the pause, so I set a filter for that path and RegOpenKey and sure enough, could easily see six gaps of exactly 12-seconds each:
The sum of the gaps – 12 times 6 – equaled the delay Jason was seeing. Next, I wanted to verify that the repeated attempts to access the network were caused by signing verification so I started looking at the stacks of various events by selecting them and typing Ctrl+K to open the stack properties dialog. The stack for events related to the Internet connection settings revealed that crypto was the reason:
One final piece of evidence I wanted to check for was that .NET was ultimately responsible for these checks. I rescanned the log and I saw events in the trace that confirmed that Stock Viewer is a .NET application:
I also looked at the stacks of some of the early events referencing crypto Registry keys and saw that it was the .NET runtime performing the call to WinVerifyTrust, the Windows function for checking the digital signature on a file, that started the cascade of attempted Internet accesses:
Confident now that the cause of the startup delay was due to .NET seeing that Stockviewer.exe was signed and then checking to see if the signing certificate had been revoked, I entered Web searches looking for a way to make .NET to skip the check, since I knew that the keynote machines probably wouldn’t be connected to the Internet during the actual keynote. After a couple of minutes of reading through articles by others with similar experiences, I found this KB article:
The article describes exactly the symptoms we were seeing and notes that .NET 2.0, which is the version of .NET I could see Stock Viewer was using based on the paths of the .NET DLLs it accessed during the trace, supports a way to turn off its obligatory checking of assembly digital signatures: create a configuration file in the executable’s directory with the same name as the executable except with “.config” appended (e.g. StockViewer.exe.config) containing the following XML:
<?xml version="1.0" encoding="utf-8"?>
A total of about 15 minutes since I had received Jason’s email, I sent him a reply explaining my conclusion with the configuration file attached. Shortly after, he wrote back confirming the delays were gone and expressing amazement that I had figured out the problem and solution so quickly. It might have seemed like magic to him, but I had simply used basic Process Monitor troubleshooting techniques and the Web to solve the case. Needless to say, the revised demo flow and transition between AppLocker and application compatibility came off great.