Subscribe: Winterdom
Preview: Winterdom


by dæmons be driven - a site by Tomas Restrepo


The story of a TF.exe hang

Mon, 17 Jul 2017 00:00:00 +0000

This morning I was setting up to move some new code I had written as an initial experiment into a new codebase, which is stored using Team Foundation Version Control (TFVC) in Visual Studio Team Services (VSTS). Before I could do that, I needed to go and update my local workspace to the latest version. Unfortunately, Visual Studio 2017 was not being cooperative, and would get stuck with the “downloading files” dialog open everytime I tried it. So I decided to give TF.exe a try and see if the command line tool was doing the same. It was. Annoyed with it, and with my search-fu failing me, I decided to attach trusty old WinDBG to the hung instance of TF.exe. What were the threads doing? DbgId ThreadId ClrThread Apartment Kind Action ===== ======== ========= ========= ========== =================================================================================================== 0 31c4 104d2d0 STA MonitorWait: Microsoft.TeamFoundation.VersionControl.Client.AsyncOperation.WaitForCompletion(Int32) 2 1b98 105b6b8 MTA Finalizer 6 6bc 637a078 MTA Worker (idle) 7 2854 637b690 Worker (idle) 9 7f10 63adef8 MTA Background WaitHandle.WaitAny: 0x00000000040708bc 12 4ec 71f7d00 MTA IO 13 71e4 7232520 MTA Worker WaitHandle.WaitOne: 0x0000000003eacd64 Thread 12 didn’t seem to be relevant. Thread 13, however, seemed to be stuck on a file async operation: DbgId ThreadId Apartment Kind CLR GC Mode GC Suspending? 13 71e4 MTA Worker v4.7.2098.00 Preemptive no WaitHandle.WaitOne ------------------ WaitHandle Type Microsoft.Win32.SafeHandles.SafeWaitHandle WaitHandle Address 0x0000000003eacd64 SP IP Function 08b5eb44 00000000 HelperMethodFrame_1OBJ [System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)] 08b5ec28 72092f71 System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean) 08b5ec40 72092f38 System.Threading.WaitHandle.WaitOne(Int32, Boolean) 08b5ec54 72092fc2 System.Threading.WaitHandle.WaitOne() 08b5ec5c 720d16d9 System.IO.FileStreamAsyncResult.Wait() 08b5ec7c 7208769b System.IO.FileStream.EndWrite(System.IAsyncResult) 08b5ec8c 720b76ce System.IO.FileStream.FlushWrite(Boolean) 08b5ec9c 721267ee System.IO.FileStream.Dispose(Boolean) 08b5ecbc 72126786 System.IO.Stream.Close() 08b5ecc8 0f48294c Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DownloadBeginReadCallback(System.IAsyncResult) 08b5ed6c 713e83e9 System.Net.LazyAsyncResult..ctor(System.Object, System.Object, System.AsyncCallback, System.Object) 08b5ed80 713e829b System.Net.ConnectStream.BeginReadWithoutValidation(Byte[], Int32, Int32, System.AsyncCallback, System.Object) 08b5eddc 713e8193 System.Net.ConnectStream.BeginRead(Byte[], Int32, Int32, System.AsyncCallback, System.Object) 08b5ee04 0f483d6c Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DecompressAndWriteChunk(DownloadAsyncResult) 08b5ee20 0f4839e1 Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DownloadDestBeginWriteCallback(System.IAsyncResult) 08b5ee4c 720d1867 System.IO.FileStreamAsyncResult.CallUserCallbackWorker() 08b5ee58 720d1838 System.IO.FileStreamAsyncResult+<>c.b__39_0(System.Object) 08b5ee5c 720705c2 System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(System.Object) 08b5ee64 72109a4a System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 08b5eed4 72109956 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 08b5eee8 720714c0 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() 08b5eefc 72070c22 System.Threading.ThreadPoolWorkQueue.Dispatch() 08b5ef4c 72070a8a System.Threading._ThreadPoolWaitCallback.PerformWaitC[...]

Moved to Jekyll

Wed, 06 Apr 2016 00:00:00 +0000

I’ve updated my site, moving away from Wordpress. Instead it is now a static site build with Jekyll.

If you are still using an RSS aggregator to follow this, please make sure you update it to point to the new feed.


What's new in IIS 10.0

Thu, 13 Aug 2015 01:45:48 +0000

A new version of IIS is included in Windows 10, which was recently released. I was expecting it to be called "IIS 9.0" to follow the model used until now, but we've jumped all the way to "IIS 10.0". However, not much information seems to be available about what has changed, and the documentation at IIS.NET has yet to be updated. I'll outline some changes I've noticed on this post. Most of them where found simply by going over the configuration schemas in %WINDIR%\System32\inetsrv\config\schema on my own. Wildcard Host Header Support This is a very useful feature that allows you to create a Web Site with a host header value of "*.", meaning that you don't have to create separate bindings for each subdomain you need to bind to the same Web Site! You can read more about this feature here. IISAdministration PowerShell Module The WebAdministration module for managing IIS from PowerShell was introduced in IIS 7.5. However, it suffers from several issues, including the fact that it often doesn't feel very "PowerShelly". With IIS 10.0, a new alternative PowerShell module has been added, called IISAdministration. You can read more about this here. Environment Variables In IIS 10.0, you can now easily specify a custom set of environment variables for an Application Pool, which will be defined for any worker process created from it. This is not supported in the UI, but you can easily add them using the Configuration Editor, or using AppCmd. For example, the following command will add a new environment variable to the ".NET v4.5" application pool named "MYVARIABLE": appcmd set apppool ".NET v4.5" /+environmentVariables.add[@start,name='MYVARIABLE',value='C:\temp'] I think this is a very nice, useful feature, particularly for complex hosting environments with many application pools and where you might not want to define the variables at the machine level. Log Event On Recycle Defaults Up to IIS 8.5, the logEventOnRecycle property of application pools had a default value of "Time, Memory, PrivateMemory". This means that when an application pool was recycled for any other reason, WAS (Windows Process Activation Services) would not leave an audit event on the System Event Log telling you about it. With IIS 10.0, the default value of logEventOnRecycle property has been changed to "Time, Requests, Schedule, Memory, IsapiUnhealthy, OnDemand, ConfigChange, PrivateMemory", which is much more useful and aligned with our recommended practices. Support for Permanent Redirects When using the "HTTP Redirection" feature, you can now tell IIS to respond with an status code of 308 Permanent Redirect. Remove the Server Header One feature that the old UrlScan tool had that was missing from the Request Filtering module introduced in IIS 7.0 was the option to remove the IIS Server version header ("Server: Microsoft-IIS/10.0"). The option to do so has now been added back in IIS 10.0 with the removeServerHeader option. I don't think this has been exposed in the Management Console yet, but you can use the AppCmd.exe to enable it, like this: appcmd.exe set config "Default Web Site" /section:system.webServer/security/requestFiltering /removeServerHeader:True Tracing after Timeout in FREB IIS 7.0 introduced a fantastic feature known as Failed Request Tracing (aka FREB). However, one issue with FREB was that if you had rules configured for collecting traces based on request execution time, the trace file would get written as soon as the time limit expired. That meant you usually ended up with a "partial trace" that didn't include all events until the request completed. There is a new attribute you can configure on your rules called traceAllAfterTimeout in IIS 10.0. When it is enabled, IIS will wait until the request is actually completed before writing the trace file. This option, however, is not exposed in the User Interface, but you can still use command line tools to enable it. The following[...]

WCF: Be careful with allowCookies="true"

Mon, 03 Aug 2015 13:18:02 +0000

I always enjoy a good troubleshooting challenge, and recently my good friend and colleage Martin Jalaf came up with an interesting one. A customer was load testing a Web application. Like many others, it consisted of farm of load-balanced servers running an ASP.NET application front-end application, which then talked to a set of WCF services running on a second server farm. In both cases, an F5 device was used to load balanced HTTP traffic. When the customer started increasing the load as part of their load tests, they would notice that calls to the WCF services would get slower, and would sometimes take upwards of 10 minutes to complete. However, the servers running the WCF services, as well as the SQL Server used showed little CPU usage. Reviewing a few memory dumps of the front-end servers, all that could be observed was threads stuck calling the WCF service. Given this, our first suspicion was that WCF throttling was incorrectly configured. However, dumps of the WCF service revealed this was not the case. In fact, only a single call to the WCF service was running at any given time, and throttling settings were too high to be causing any issues. This could be easily observed using the excellent netext debugging extension: 0:000> !wservice Address State EndPoints BaseAddresses Behaviors Throttled Calls/Max Sessions/Max ConfigName,.NET Type 000000e9229c78d8 Opened 0n1 0n1 0n10 True 0n1/0n2000 0n0/0n400 "WCFSecurity.SecurityService",WCFSecurity.SecurityService The WCF service was configured with InstanceContextMode=Single, and ConcurrencyMode=Multiple. However, this did not appear to be related at all. Another unexpected symptom was that despite the fact that the WCF servers were behind a load balancer device, all requests ended up being processed by the same server most of the time. I immediately suspected that the F5 device was configured with session affinity enabled, even though the customer had initially denied it. Since the WCF service was exposed using an HTTP-based binding, I asked Martin to check the ASP.NET HttpContext instances, just in case they were somehow relevant. We immediately found that there were hundreds of HttpContext instances in the dump that had yet to complete! 0:000> !whttp HttpContext Thread Time Out Running Status Verb Url 000000e622a12850 -- 00:00:00 00:20:52 200 POST /WCFSecurity/SecurityService.svc 000000e622a18e58 -- 00:00:00 00:20:47 200 POST /WCFSecurity/SecurityService.svc 000000e622a23c58 -- 00:00:00 00:20:39 200 POST /WCFSecurity/SecurityService.svc .... Looking closely, we realized that all HTTP calls were stuck in the AcquireRequestState stage of the ASP.NET pipeline, which meant we were actually observing an instance of the infamous ASP.NET Session Lock issue (see the section titled Concurrent Requests and Session State)! Session: cq2uoplja4aqu2aoobw3f1pf HttpContext Thread Poll (ms) Time Path ================ ====== ========= ==== =================================== 000000e622a12850 500 1253 /WCFSecurity/SecurityService.svc 000000e622a18e58 500 1248 /WCFSecurity/SecurityService.svc 000000e622a23c58 500 1240 /WCFSecurity/SecurityService.svc 000000e622a25d50 500 1238 /WCFSecurity/SecurityService.svc 000000e622a27b60 500 1236 /WCFSecurity/SecurityService.svc 000000e622a283f8 500 1236 /WCFSecurity/SecurityService.svc .... Why was ASP.NET Session being used here? The service was configured with: aspnetCompatibilityEnabled="true" /> This meant that the service was enabling access to the ASP.NET services, but the service itself was not using session state. What was really unexpected in this case was that all the requests from a single front-end server were ending up with the exact same ASP.NE[...]

Processing IIS ETW events using Azure Stream Analytics

Sun, 16 Nov 2014 02:21:29 +0000

Updated 2015/07/23: I've updated this post with some up-to-date information on Stream Analytics and some additional comments. This blog post continues my series of blog posts about ETW logging in IIS 8.5. One of the things that I wanted to do from the start was using this as an excuse to dig into some Azure services. In the last entry, I updated the sample code to push ETW events collected from IIS in near real-time to an Azure Event Hub. Now, I’d like to take that a bit further and actually process the events that make it to the hub. Naturally, I could write my own Event Hub listener that processes said events, but the Azure Stream Analytics service sounded like a pretty interesting way to do this, so I decided to give it a try! The collector code serializes each ETW event into a flat JSON structure, using the header_ and event_ prefixes as necessary. Note, however, that Stream Analytics now supports hierarchical JSON structures (i.e. with nested objects), so you could use a different representation if you wanted Configuring the Stream Analytics job. The first step to use Stream Analytics is creating a job in the management portal: Once your Stream Analytics job is created, we will want to connect it to our existing Event Hub that is receiving events from the collector service. Creating an Input Before doing this, we need to add a new SAS policy that Stream Analytics can use to read the events from the hub. To do this, go to your Event Hub configuration page, look for the “shared access policies” section and add a new one with Manage permissions: Then click on the Save button to persist the changes. Now go back to the Stream Analytics instance and select the Add Inputs option. Here’re we will want to connect it to our existing Event Hub instance: The type of the input should be Data Stream, Event Hub, and then enter an alias for the input and select the existing event hub and the right shared access policy: Then select the serialization format and encoding: Creating a Query Now that we have a way to get data into our Stream Analytics job, we can define one or more queries on top of the data. For example, let’s say we want to create a summary of the successful hits within a 5 minute window: Creating an Output Now let’s define an output for our query. In this case, I want to store the job output into a SQL Database on azure, which I have already created. Notice that you will want your DB to be on the same region as the Stream Analytics job! In this database, we’ll create a simple table to store the results: Go to the Output section of your Stream Analytics job and select the Add an Output option. Then select “SQL Database” as the destination, and enter your database details: Note: If you use a database that has ‘-’ characters as part of the name, trying to create the output will result in an error, at least when I tried it. Running the job Now we can start our Stream Analytics job and test the results! After the job has been running for a while, and we’re feeding data to the Event Hub, we start seeing the results in our database table: Overall, getting this working was surprisingly easy. Since I did my original tests, Stream Analytics and the documentation has improved substantially, making it even easier! Supporting other event types While my original idea was to handle IIS log information, there is no reason the same technique cannot be used to collect and process other ETW events. I've recently updated the code to make the core code independent of the IIS log provider, and now you can add/replace the existing ETW providers/parsers used with your own using MEF. This was very easy since the collector is based on the excellent TraceEvent library to collect ETW events. [...]

Playing with Roslyn and VSIX

Tue, 11 Nov 2014 02:52:51 +0000

I have been playing a bit with the Roslyn APIs in Visual Studio "14". Since I am a big fan of VS editor extensions, my first attempt was building something simple: A Visual Studio tagger that would colorize uses of parameter variables and field variables in code:


The code is ugly as it is, and does not use the Roslyn Async API, which is something I'd like to look into later on. I'm also not entirely sure if there's a better way to build such a thing (Roslyn has it's own concept of classification, but not sure if that is extensible). It was fun, though!

Code can be found here


ETW Logging in IIS 8.5 (2)

Sun, 09 Nov 2014 02:41:27 +0000

A few days ago I posted a sample on capturing ETW log events generated by IIS 8.5.

This turned out to be a good excuse to play around with the new Event Hubs service in Microsoft Azure, so I've now extended the sample with a collector application that can capture the ETW log events generated by IIS and push them in JSON format to an Azure Event Hub.


From here, I could process events in a number of ways, and it will be interesting to play with other Azure services to do just that later on. The sample code is updated on the github repository, but be aware it is very rough, but I'll keep improving it.


ETW Logging in IIS 8.5

Thu, 06 Nov 2014 01:54:43 +0000

One of the coolest features in IIS 8.5 (Windows Server 2012 R2) is the option to write W3SVC log entries to ETW (Event Tracing for Windows) instead of the normal W3C log files. I've published a sample on how to capture these events. Check out the readme for more details.


Invalid application pool name error in WebDeploy

Wed, 05 Nov 2014 01:18:32 +0000

I was helping out a customer a few weeks ago to use the Web Deployment Tool to migrate applications and sites from IIS 6.0 to IIS 7.x/8.x, and ran into an error I had not seen before. I thought I'd document it here in case I, or anyone else, runs into it again. During our work, we exported an entire IIS 8.5 server to a ZIP package using the Web Deployment Tool tasks integrated into the IIS Management Console (inetmgr). When we tried to restore the server archive on the same server, we got the following error: Error: Invalid application pool name After investigating the issue for a while, I realized the problem was that the IIS configuration of the server was invalid before we exported the server package! IIS is very robust at dealing with some invalid configurations, and this was such a case: The server appeared to work perfectly fine even though there was one slight configuration error, that would have only caused trouble under very specific circumstances! To figure it out I had to attempt the restore operation using the command line msdeploy.exe tool rather than the UI. Capturing the full log, I noticed that the last relevant entry was: Info: Updating applicationDefaults (MSDeploy.webServer/webServer/appHostConfig[@path='']/location[@path='']/section[@name='system.applicationHost/sites']/sites/site[@name='Default Web Site']/applicationDefaults). The problem turned out to be that for some reason, the applicationPool attribute of the section for all sites was not set. When the full server archive was created, Web Deploy exported a blank value for this property. When I looked at the archive.xml included in the ZIP file, this could be seen clearly: How to fix it Once I had this nailed down, working around it was easy: I simply extracted the entire ZIP archive to a folder, modified the archive.xml file to set a applicationPool='DefaultAppPool', and then simply imported the server backup directly from the extracted folder by using the archiveDir provider as the source. Alternatively, I could've created the ZIP file again and import it as usual. [...]

Viasfora 2.0 Released!

Sun, 13 Jul 2014 23:59:35 +0000

Today I've released version 2.0 of my Viasfora extension for Visual Studio, which supports VS2010, VS2012 and VS2013. Lots of work went into this release, not only to add some cool new features, but also to clean up the existing codebase a little bit and fix bugs reported by users. Two new features in this release extend Rainbow Braces to make it more useful: Commands to navigate from the caret position to the opening/closing brace Rainbow tooltips, which allow you to quickly check the line where the matching brace is located Working on Rainbow ToolTips was very interesting because I wanted to end up with something that looked similar to the preview tooltip in the map mode scrollbar in VS2013. The first problem was figuring out the right way to create the text view for the tooltip, and then making it look good. One particularly frustrating part of it was having to write a custom IIntellisensePresenter to avoid having a very wide border around the tooltip! Another significant change in this release is that I have removed the support for Visual Studio "14" CTP, which was introduced in v1.9. Unfortunately, there is problem with the Visual Studio Gallery at this time, which makes extensions 'invisible' to Visual Studio 2013 if support for VS14 is present in the manifest [1]. Because of this, very few people running VS2013 have been able to update to v1.9 unless they explicitly went to the VS Gallery and downloaded the VSIX manually. Unfortunately, it is not clear if and when this problem might be fixed. In the worst case, extension developers will just have to make separate releases for VS 14 and publish them as separate extensions in the VS Gallery. This is a lot of work that, at this point, is not worth the effort for me. I will reevaluate this when VS 14 is officially released if the problem still exists. For now, if I get enough interest in VS 14 support, I'll figure some out of band mechanism for sharing VS14-enabled builds. Finally, I'd like to say that working on Viasfora has been very rewarding personally. It has given me an excellent opportunity to learn a lot about Visual Studio extensibility, and both the Web Essentials and VsVim sources have been extremely useful for this. I'd also like to say thanks to all my twitter contacts, not only for putting up with my frequent rants, but also for often helping me figure out how to accomplish something in VS (in particular, the feedback from Jared Parsons was always very appreciated). [1] Disclaimer: I do not know if the problem is enabling VS 14 support in the manifest, or enabling support for 4 VS versions at the same time. I also do not know what plans the team responsible for the VS Gallery has regarding the issue, or even if any exist at this point. [...]