Never doubt thy debugger

A few days ago I was working on a repro I got from a customer as I very often do, and for some reason after a while my IIS started to behave oddly, pages where not served, the application pool was stuck doing “something” and whenever I tried to open the IIS Manager I got the error “There was an error when trying to connect. Do you want to retype your credentials and try again? Cannot create a file when that file already exists”:

Needless to say that being IIS on my local machine and I have not made any changes to the security/ACLs/DCOM etc… there should be no need to retype my credentials; and by the way, even retyping them did not help.

By the way, if I tried to remotely connect to another machine of mine, I got the message “The type initializer for ‘Microsoft.Web.Management.Remoting.HttpChannel’ threw an exception”:

My next step has been to try to restart the World Wide Web Publishing Service: it was (oddly?) stopped, but again I got an error “Windows could not start the World Wide Web Publishing Service service on Local Computer. Error 1068: The dependency service or group failed to start”:

The W3SVC service has a dependency on WAS (Windows Process Activation Service), I tried to start it manually and got “Windows could not start the Windows Process Activation Service service on Local Computer. Error 183: Cannot create a file when that file already exists.”:

That is the same message I got from IIS Manager, so I thought to have a look at the event log to find out more: I was wrong! I got “MMC could not create the snap-in. The snap-in might not have been installed correctly”:

I quickly found out that virtually every MMC snap-in was broken on my machine (“Server Manager” “Certificates”, “Local Users and Groups”, just name one) but why?!? 

Well… on Windows 2008, MMC is based on .NET as of course is IIS and when the problem first appeared I was tampering my machine.config file to try different ThreadPool settings…

The golden rule in computing reads “Always back-up sensitive data!”… after restoring my clean machine.config all the problems above went away!

For curiosity I had a deeper look at it and found the following lines:

<system.web>

        <processModel autoConfig="true"/>

        <processModel autoConfig="false" minWorkerThreads="100" 
            minIoThreads="100" maxWorkerThreads="404" maxIoThreads="404"/>

        <httpRuntime minFreeThreads="152" minLocalRequestFreeThreads="152"/>

[...]

Easy to spot it now, eh? For my repro I had set autoConfig=”false” but then I decided to set it to “true”, for some reason I added a new <processModel> element with its own autoConfig=”true” and forgot to remove the “old” <processModel>… At least I learnt something new from my foolishness!

Note: there might be other reasons if you get the errors above, but always keep a clean backup of your configuration files at hand, just in case…

Carlo

The .shell command in Windbg allows to pipe the output of a debugger command to an external process and automatically print its output back inside the debugger window; a useful example is the command FIND, for example if we want to parse the stack for every thread and find every call where the word “isapi” is involved:

0:036> .shell -ci "~*kpL1000" find /i "isapi"
013cff78 1004f94e ISAPI_Rewrite!TerminateFilter+0x3cef
013cffb0 1004f9f3 ISAPI_Rewrite!TerminateFilter+0x4462e
013cffec 00000000 ISAPI_Rewrite!TerminateFilter+0x446d3
0144ff78 1004f94e ISAPI_Rewrite+0x7763
0144ffb0 1004f9f3 ISAPI_Rewrite!TerminateFilter+0x4462e
0144ffec 00000000 ISAPI_Rewrite!TerminateFilter+0x446d3
.shell: Process exited

Incidentally also LogParser (one of my favorite debugging tools) can accept data to be parsed from the input stream using the STDIN keyword, so for example refactoring a script I posted some time ago we can find out if there are any duplicated assemblies in our application pool that should be moved to the GAC:

0:000> .shell -ci "!peb" logparser "select extract_filename(text) as Duplicated_Assemblies, count(Duplicated_Assemblies) as Hits from STDIN where index_of(text, 'temporary asp.net files') > 0 group by Duplicated_Assemblies having count(Duplicated_Assemblies) > 1" -i:textline -o:nat -rtp:-1
Duplicated_Assemblies        Hits 
---------------------------- ----
errormanager.dll             2
winformsui.dll               2
externallibraryinterface.dll 2
ptshopengine.dll             2
schemas.dll                  2
dbengine.dll                 2
flowservice.dll              2

Statistics:
-----------
Elements processed: 182
Elements output:    7
Execution time:     0.02 seconds

.shell: Process exited

Following the same principle, we can find out if there are strong named assemblies in our /bin folder as follows:

0:000> .shell -ci "!dumpdomain" find /i "shared domain"
Shared Domain: 0x793f2aa8
.shell: Process exited



0:000> .shell -ci "!dumpdomain 0x793f2aa8" logparser "SELECT DISTINCT EXTRACT_FILENAME(text) as Strong_Named_Assemblies_In_/bin FROM STDIN WHERE INDEX_OF(to_lowercase(text), 'temporary asp.net files') > 0" -i:TEXTLINE -o:NAT -RTP:-1
Strong_Named_Assemblies_In_/bin 
-----------------------------------------
crypto.dll
radplaceholder.dll
scms.dll
sqldac.dll
scontrollibrary.dll
spell.dll
editor.dll
scms.resources.dll

Statistics:
-----------
Elements processed: 164
Elements output:    8
Execution time:     0.01 seconds

.shell: Process exited

Instead of typing the whole command you can save it in a text file and execute it directly within Windbg with a command like “$><c:\debuggers\snassemblies.txt”.

Carlo

The application pool for this site was getting disabled quite frequently and we found quite a few entries like the following in the event log:

Event Type: Error
Event Source: W3SVC
Event Category: None
Event ID: 1002
Date: 19/11/2008
Time: 15:20:23
User: N/A
Computer: <computername>
Description: Application pool 'DefaultAppPool' is being automatically disabled due to a series of failures in the process(es) serving that application pool

In this case the customer already had some debugging skills so when he called CSS he already had a few dumps available to analyze; they were some process shutdown dumps (taken on Kernel32!TerminateProcess), strangely we had no second chance dumps (maybe because of one of these reasons?) but they’ve been a good point to start from anyway.

First, let’s have a look at the exceptions:

0:000> !dumpheap -type Exception -stat 

[...]

Statistics:
      MT    Count    TotalSize Class Name
79333ed4        1           12 System.Text.DecoderExceptionFallback
79333e90        1           12 System.Text.EncoderExceptionFallback
79330d44        1           72 System.ExecutionEngineException
79330cb4        1           72 System.StackOverflowException
79330c24        1           72 System.OutOfMemoryException
7931ffd4        1           72 System.NullReferenceException
6610c7fc        1           84 System.Web.HttpUnhandledException
79330dd4        2          144 System.Threading.ThreadAbortException
79318afc        2          144 System.InvalidOperationException
7931740c        5          160 System.UnhandledExceptionEventHandler
Total 16 objects

Remember, a few special exceptions are loaded when the AppDomain is first created (see here) so let’s try to see if there is still something significant on the threads:

0:000> !threads
ThreadCount: 21
UnstartedThread: 0
BackgroundThread: 21
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception
  17    1  950 000f2580   1808220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  27    2 1bfc 00100018      b220 Enabled  00000000:00000000 000eed48     0 MTA (Finalizer)
  28    3  300 00117068    80a220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Completion Port)
  29    4 1cf4 0011a458      1220 Enabled  00000000:00000000 000eed48     0 Ukn
   9    5  ec0 001702e0       220 Enabled  00000000:00000000 000eed48     0 Ukn
  31    6 2414 00171f68   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  32    7 1f24 00172338   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  33    8  97c 001729e0   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  34    9 13bc 00173088   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  35    a 22f8 00173a50   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  36    b 1e60 00174540   180b220 Disabled 12445a64:124475b8 0011ab48     1 MTA (Threadpool Worker) System.StackOverflowException (1a0a00a4)
  37    c 1c8c 00174cf8   180b220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Worker)
  15    d 1934 0017d040   880a220 Enabled  00000000:00000000 000eed48     0 MTA (Threadpool Completion Port)
   7    e 2028 0017ece8       220 Enabled  00000000:00000000 000eed48     0 Ukn
   8    f  dbc 0016f280       220 Enabled  00000000:00000000 000eed48     0 Ukn
   4   10 2298 05007008       220 Enabled  00000000:00000000 000eed48     0 Ukn
   6   11 20c0 05004278       220 Enabled  00000000:00000000 000eed48     0 Ukn
   3   12  c9c 05003b70       220 Enabled  00000000:00000000 000eed48     0 Ukn
   5   13 1a84 04ff7a60       220 Enabled  00000000:00000000 000eed48     0 Ukn
   2   14 253c 0d378ee0       220 Enabled  00000000:00000000 000eed48     0 Ukn
  42   15 1760 0d38b3d8       220 Enabled  00000000:00000000 000eed48     0 Ukn

Dumping the managed stack for thread 36, the recursion is quite obvious:

0:036> !clrstack
OS Thread Id: 0x1e60 (36)
ESP       EIP     
04e94acc 77e42004 [FaultingExceptionFrame: 04e94acc] 
04e95058 77e42004 [HelperMethodFrame: 04e95058] 
04e950c4 65230cc1 System.Data.RBTree`1+TreePage[[System.__Canon, mscorlib]]..ctor(Int32)
04e950d4 65230abe System.Data.RBTree`1[[System.__Canon, mscorlib]].AllocPage(Int32)
04e950f8 652309fc System.Data.RBTree`1[[System.__Canon, mscorlib]].InitTree()
04e95108 65230961 System.Data.DataRowCollection..ctor(System.Data.DataTable)
04e95118 652307c2 System.Data.DataTable..ctor()
04e95134 65230535 System.Data.Common.DataTableMapping.GetDataTableBySchemaAction(System.Data.DataSet, System.Data.MissingSchemaAction)
04e95150 6523037c System.Data.ProviderBase.SchemaMapping..ctor(System.Data.Common.DataAdapter, System.Data.DataSet, System.Data.DataTable, System.Data.ProviderBase.DataReaderContainer, Boolean, System.Data.SchemaType, System.String, Boolean, System.Data.DataColumn, System.Object)
04e9519c 6522fbac System.Data.Common.DataAdapter.FillMappingInternal(System.Data.DataSet, System.Data.DataTable, System.String, System.Data.ProviderBase.DataReaderContainer, Int32, System.Data.DataColumn, System.Object)
04e951d0 6522fc1e System.Data.Common.DataAdapter.FillMapping(System.Data.DataSet, System.Data.DataTable, System.String, System.Data.ProviderBase.DataReaderContainer, Int32, System.Data.DataColumn, System.Object)
04e95218 6522f9e6 System.Data.Common.DataAdapter.FillFromReader(System.Data.DataSet, System.Data.DataTable, System.String, System.Data.ProviderBase.DataReaderContainer, Int32, Int32, System.Data.DataColumn, System.Object)
04e95270 6522f942 System.Data.Common.DataAdapter.Fill(System.Data.DataSet, System.String, System.Data.IDataReader, Int32, Int32)
04e952b4 65230105 System.Data.Common.DbDataAdapter.FillInternal(System.Data.DataSet, System.Data.DataTable[], Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
04e9530c 65230010 System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet, Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
04e95350 6559401d System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet, System.String)
04e95384 6678d11f System.Web.UI.WebControls.SqlDataSourceView.ExecuteSelect(System.Web.UI.DataSourceSelectArguments)
04e95424 6668f498 System.Web.UI.DataSourceView.Select(System.Web.UI.DataSourceSelectArguments, System.Web.UI.DataSourceViewSelectCallback)
04e95434 66792c0f System.Web.UI.WebControls.DataBoundControl.PerformSelect()
04e9544c 6679285e System.Web.UI.WebControls.BaseDataBoundControl.DataBind()
04e95458 667dcf35 System.Web.UI.WebControls.GridView.DataBind()
04e9545c 660e1ac3 System.Web.UI.WebControls.BaseDataBoundControl.EnsureDataBound()
04e95488 668ecdcd System.Web.UI.WebControls.BaseDataBoundControl.set_RequiresDataBinding(Boolean)
04e95498 667da23b System.Web.UI.WebControls.GridView.set_PageIndex(Int32)
04e954a8 0ad3e096 ASP.search_aspx.Gridview1_DataBound(System.Object, System.EventArgs)
04e959a8 667928ce System.Web.UI.WebControls.BaseDataBoundControl.OnDataBound(System.EventArgs)
04e959bc 66792b45 System.Web.UI.WebControls.DataBoundControl.OnDataSourceViewSelectCallback(System.Collections.IEnumerable)
04e959cc 6668f4a4 System.Web.UI.DataSourceView.Select(System.Web.UI.DataSourceSelectArguments, System.Web.UI.DataSourceViewSelectCallback)
04e959dc 66792c0f System.Web.UI.WebControls.DataBoundControl.PerformSelect()
04e959f4 6679285e System.Web.UI.WebControls.BaseDataBoundControl.DataBind()
04e95a00 667dcf35 System.Web.UI.WebControls.GridView.DataBind()
04e95a04 660e1ac3 System.Web.UI.WebControls.BaseDataBoundControl.EnsureDataBound()
04e95a30 668ecdcd System.Web.UI.WebControls.BaseDataBoundControl.set_RequiresDataBinding(Boolean)
04e95a40 667da23b System.Web.UI.WebControls.GridView.set_PageIndex(Int32)
04e95a50 0ad3e096 ASP.search_aspx.Gridview1_DataBound(System.Object, System.EventArgs)
04e95f50 667928ce System.Web.UI.WebControls.BaseDataBoundControl.OnDataBound(System.EventArgs)
04e95f64 66792b45 System.Web.UI.WebControls.DataBoundControl.OnDataSourceViewSelectCallback(System.Collections.IEnumerable)
04e95f74 6668f4a4 System.Web.UI.DataSourceView.Select(System.Web.UI.DataSourceSelectArguments, System.Web.UI.DataSourceViewSelectCallback)
04e95f84 66792c0f System.Web.UI.WebControls.DataBoundControl.PerformSelect()
04e95f9c 6679285e System.Web.UI.WebControls.BaseDataBoundControl.DataBind()
04e95fa8 667dcf35 System.Web.UI.WebControls.GridView.DataBind()
04e95fac 660e1ac3 System.Web.UI.WebControls.BaseDataBoundControl.EnsureDataBound()
04e95fd8 668ecdcd System.Web.UI.WebControls.BaseDataBoundControl.set_RequiresDataBinding(Boolean)
04e95fe8 667da23b System.Web.UI.WebControls.GridView.set_PageIndex(Int32)
04e95ff8 0ad3e096 ASP.search_aspx.Gridview1_DataBound(System.Object, System.EventArgs)

[...]
04ebea70 0ad3e096 ASP.search_aspx.Gridview1_DataBound(System.Object, System.EventArgs)
04ebef70 667928ce System.Web.UI.WebControls.BaseDataBoundControl.OnDataBound(System.EventArgs)
04ebef84 66792b45 System.Web.UI.WebControls.DataBoundControl.OnDataSourceViewSelectCallback(System.Collections.IEnumerable)
04ebef94 6668f4a4 System.Web.UI.DataSourceView.Select(System.Web.UI.DataSourceSelectArguments, System.Web.UI.DataSourceViewSelectCallback)
04ebefa4 66792c0f System.Web.UI.WebControls.DataBoundControl.PerformSelect()
04ebefbc 6679285e System.Web.UI.WebControls.BaseDataBoundControl.DataBind()
04ebefc8 667dcf35 System.Web.UI.WebControls.GridView.DataBind()
04ebefcc 660e1ac3 System.Web.UI.WebControls.BaseDataBoundControl.EnsureDataBound()
04ebeff8 660e1a57 System.Web.UI.WebControls.BaseDataBoundControl.OnPreRender(System.EventArgs)
04ebf008 667e07da System.Web.UI.WebControls.GridView.OnPreRender(System.EventArgs)
04ebf030 660abc21 System.Web.UI.Control.PreRenderRecursiveInternal()
04ebf048 660abc7c System.Web.UI.Control.PreRenderRecursiveInternal()
04ebf060 660abc7c System.Web.UI.Control.PreRenderRecursiveInternal()
04ebf078 660abc7c System.Web.UI.Control.PreRenderRecursiveInternal()
04ebf090 660abc7c System.Web.UI.Control.PreRenderRecursiveInternal()
04ebf0a8 660a7c4b System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
04ebf200 660a77a4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
04ebf238 660a76d1 System.Web.UI.Page.ProcessRequest()
04ebf270 660a7666 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
04ebf27c 660a7642 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
04ebf290 0ad37afe ASP.search_aspx.ProcessRequest(System.Web.HttpContext)
04ebf2a0 660adb16 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
04ebf2d4 6608132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
04ebf314 6608c5c3 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
04ebf364 660808ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
04ebf380 66083e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
04ebf3b4 66083ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
04ebf3c4 66082c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
04ebf5d8 79f68cde [ContextTransitionFrame: 04ebf5d8] 
04ebf60c 79f68cde [GCFrame: 04ebf60c] 
04ebf768 79f68cde [ComMethodFrame: 04ebf768] 

The next step is to find out why the OnDataBound event is firing over and over; here is the source code for the faulting page (simplified to show only the relevant bits):

Sub Page_Load(ByVal Sender As Object, ByVal E As EventArgs)

        Dim cmd As String = "select * from products"

        If Not IsPostBack Then

            ' when there is a blank search, display all products
            If SearchString = "" Then

                SqlDataSource1.SelectCommand = cmd
                GridView1.DataBind()

            Else
                ' when there are keywords (not a blank search)

                ' some logic to change the sql query
                GridView1.DataBind()

                If GridView1.Rows.Count < 3 Then ' displays suggestions if results are less then 3
                    For i = 0 To Keywords.Count - 1
                        ' some logic to change the sql query
                        GridView1.DataBind()
                    Next

                    For i = 0 To FoundNewKeywords.Count - 1
                        For s = 0 To Keywords.Count - 1
                            ' some logic to change the sql query
                            GridView1.DataBind()
                        Next

                        For j = i To FoundNewKeywords.Count - 1
                            ' some logic to change the sql query
                            GridView1.DataBind()

                            If j = FoundNewKeywords.Count - 1 And FoundNewKeywords.Count > 2 Then
                                For m = j - 1 To 1 Step -1
                                    ' some logic to change the sql query
                                    GridView1.DataBind()
                                Next

                                If i < 1 Then
                                    For m = 2 To j - 1
                                        ' some logic to change the sql query
                                        GridView1.DataBind()
                                    Next
                                End If
                            End If
                        Next
                    Next
                End If
            End If
        End If
    End Sub



    Sub Gridview1_DataBound(ByVal sender As Object, ByVal e As EventArgs)
        ' Some custom logic here
    End Sub

From a high level perspective the intention was to start with a “return everything” query and refine it step by step taking into account keywords specified by the user and add logic to suggest other records that might interest the user. From an operation standpoint calling DataBind() multiple times means the whole data binding logic is executed over and over, such as the custom DataBound event handler: that way, depending on what we’re doing, we could exhaust the stack space which is what was happening in this case.

The solution is simple: there is no need to call DataBind() many times, just call it once after we have refined our query.

Carlo

Have you ever found yourself patiently waiting for a problem to reproduce with your debugger ready, and when it happens you just find there are no signs of your dump anywhere? If you are using adplus you likely had the text logs, but nothing more…

In such situations it is possible that the OS is terminating the process before the dump is fully written. If you are tying to dump an IIS process and you want to save some time and headaches, try this small cunning: temporarily disable the “Enable pinging” and “Enable rapid-fail protection” flags in the Health tab for your application pool:

Sometimes can be useful to tell IIS to not kill a failing worker process but rather leave it orphaned:

Features of Worker Process Isolation Mode

Orphaning Worker Processes

You can configure worker process isolation mode to orphan a worker process that the WWW service deems to be failing. The WWW service usually terminates a failing worker process and replaces it. If you enable orphaning, the WWW service allows a failing worker process to continue running, but separates it from the application pool (making it an orphan) and starts a new worker process in its place. You can configure the WWW service to run a command on the orphaned worker process — for example, launching a debugger.

For more information about orphaning worker processes, including how to configure this feature, see Running IIS 6.0 as an Application Server in this book and OrphanWorkerProcess Metabase Property metabase property.

In IIS 6 there the following three metabase properties can be handy to run some custom actions in case of an application pool failure:

• OrphanWorkerProcess: The OrphanWorkerProcess property, when set to true, notifies the World Wide Web Publishing Service (WWW Service) not to terminate a worker process that fails to respond to pings, but to instead orphan the worker process in the application pool if the worker process suffers fatal errors
• OrphanActionParams: The OrphanActionParams property specifies command-line parameters for the executable specified by the OrphanActionExe Metabase Property. To specify the process ID of the orphaned process, use %1%.
• OrphanActionExe: The OrphanActionExe property specifies an executable to run when the World Wide Web Publishing Service (WWW service) orphans a worker process. You can use the OrphanActionParams Metabase Property to send parameters to the executable

The article How to generate a dump file when ASP.NET deadlocks in IIS 6.0 explains how to use the properties above and despite its title, you can use this technique to run the custom actions you need/want not only in case of an ASP.NET deadlock but in every circumstance that fits your needs.

In IIS 7 you can easily use the Advanced Settings dialog or your application pool:

Finally, while w3wp.exe cannot run without Data Execution Prevention, if you are debugging a custom process you may want to add it to the exclusion list:

Carlo

I wrote about why GDI+ is not supported in a service a couple of years ago but this is still a debated topic (or I should better say a misunderstood topic), then WPF (Windows Presentation Foundation) came into the game and it brought some more uncertainties with it.

Recently I worked on a custom application which basically was meant to made of a Windows Form client and a WCF Web Service used to get some data from a database, create a 3D image (a sort of chart) and send it to the client as a jpg image; the graphic part was done using classes such as Viewport3D, PerspectiveCamera, ModelVisual3D, RenderTargetBitmap and others taken from the System.Windows.Media.*  and System.Drawing namespaces.

Everything was working fine as long as the project was being developed and debugged against the ASP.NET Development Server (Cassini), but when the project was deployed to IIS7 the image returned was missing the 3D part and the fancy transparency and shadow effects added through WPF classes, it merely had a blue background, nothing more.

The first thing I thought to, are the differences between Cassini and IIS: the former is a process (not a service), it runs under the credentials of the logged on user and also has Administrator rights as Visual Studio does (or should, to work properly). In IIS7 is really easy to test if this was a permission or missing user desktop issue, I changed the Identity property for the application pool to run it under my domain account and changed the Load User Profile to true to have access the my system variables, registry etc…

No luck.

I’ll save you the other tests I’ve done, what is important to know is that there actually is another difference between IIS and Cassini on Windows 2008 / Vista, or I should better say one of the differences I have mentioned before has an important implication on those platforms: services now run in an isolated session (Session 0) while processes run in the session assigned to the user logged on the machine:

Application Compatibility: Session 0 Isolation

In Windows XP®, Windows Server® 2003, and earlier versions of the Windows® operating system, all services run in the same session as the first user who logs on to the console. This session is called Session 0. Running services and user applications together in Session 0 poses a security risk because services run at elevated privilege and therefore are targets for malicious agents that are looking for a means to elevate their own privilege levels.

The Windows Vista® and Windows Server® 2008 operating systems mitigate this security risk by isolating services in Session 0 and making Session 0 non-interactive. In Windows Vista and Windows Server 2008, only system processes and services run in Session 0. The first user logs on to Session 1, and subsequent users log on to subsequent sessions. This approach means that services never run in the same session as users' applications and are therefore protected from attacks that originate in application code.

Specific examples of affected driver classes include:

• Printer drivers, which are loaded by the spooler service
• All drivers authored with the User Mode Driver Framework (UMDF) because these drivers are hosted by a process in Session 0

Application classes affected by this feature include:

• Services that create UI
• A service that tries to use window-message functions such as SendMessage and PostMessage to communicate with an application
• Applications creating globally named objects

This can easily been verified adding the “Session ID” column in Task Manager: as you can see, the WinForm client (Test3DInService.exe) is running in Session 2, w3wp.exe is running in Session 0 (despite the fact that the process is running as my domain account and it has loaded the user profile) and finally WebDev.WebServer.exe (Cassini) is running in Session 2:

Even more important is this document: Impact of Session 0 Isolation on Services and Drivers in Windows Vista:

Because Session 0 is no longer a user session in Windows Vista, services that are running in Session 0 do not have access to the video driver in Windows Vista. This means that any attempt that a service makes to render graphics fails. In current builds of Windows Vista, querying the display resolution and color depth in Session 0 reports the correct results for the system up to a maximum of 1920x1200 at 32 bits per pixel (bpp).

Got it!

Well, almost, but we’re pretty close. I said the blue background was actually created, and other simple 2D shapes could be successfully rendered as well, so the statement “any attempt that a service makes to render graphic fails” is not fully correct, is should read as “any attempt that a service makes to render graphics that relies on the video driver fails”. Not all graphics need to interact with the video driver so generally speaking, GDI can be used (that’s a different set of libraries than GDI+) and “simple” graphic rendering should normally work fine (as if did in my sample with 2D graphics): the trick is never call (or try to call) into the video driver. This unfortunately means the fancy WPF shadows, transparencies and effects are off limits from a service. It is possible to use BIDs and BIDSection.

I could think to 3 possible solutions (in order of my preference) to this case, not all of them very nice but if nothing else can be done… if you have anything to add, feel free :

• If it is possible to move the logic to create the 3D image, the Web Service call could just return to the client the data needed to build the image and do the “hard work” in WPF either in a Windows Forms client or in Silverlight if you wish
• Create a sort of custom web server using the hostable web core provided by IIS 7, embed it into a usermode process (not in a service) and use it to run your code and serve the 3D image: this means there must be an account always logged on the server to keep this process running
• Rely only on “safe and simple” drawing objects or work directly with bytes structures to design your graphic “point by point”: this is the hard way of doing graphics and you’ll need to code it in C++ I think, you’ll likely have to renounce using effects such as transparencies but at least it should work

Carlo

I got two FEEE cases in a row last week, both of them for the same cause so I thought to blog about it hoping to save some stress and headshakes to someone else.

The affected platform is 64 bit Framework (32 bit works fine), either Web or Windows application: randomly the application crashes and if you check your event log you’ll find messages like the following:

Event Type:      Error
Event Source:   .NET Runtime
Date:                12-02-2009 10:58:36
User:                N/A
Computer:       <computername>
Description: .NET Runtime version 2.0.50727.3082 - Fatal Execution Engine Error (000006427F8A5DC8) (80131506)

The stack of the faulting thread looks like this:

0:025> kpL1000
Child-SP          RetAddr           Call Site
00000000`0643e350 00000642`78acb013 mscorwks!COMCryptography::_DecryptData+0x329
00000000`0643e590 00000642`801f4b87 mscorlib_ni!System.Security.Cryptography.CryptoAPITransform.TransformFinalBlock(<HRESULT 0x80004001>)+0x123
00000000`0643e620 00000642`801f25c7 CryptoSample!MyCryptoClass.Decrypt(<HRESULT 0x80004001>)+0xf7
00000000`0643e960 00000642`bc8e449b System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute(<HRESULT 0x80004001>)+0x257
00000000`0643ea10 00000642`bc8f2215 System_Web_ni!System.Web.HttpApplication.ExecuteStep(<HRESULT 0x80004001>)+0xab
00000000`0643eab0 00000642`bc8e3553 System_Web_ni!System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(<HRESULT 0x80004001>)+0x1a5
00000000`0643eb60 00000642`bc8e7874 System_Web_ni!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(<HRESULT 0x80004001>)+0xd3
00000000`0643ebc0 00000642`bc8e745c System_Web_ni!System.Web.HttpRuntime.ProcessRequestInternal(<HRESULT 0x80004001>)+0x1c4
00000000`0643ec50 00000642`bc8e608c System_Web_ni!System.Web.HttpRuntime.ProcessRequestNoDemand(<HRESULT 0x80004001>)+0x7c
00000000`0643ec90 00000642`7f602322 System_Web_ni!System.Web.Hosting.ISAPIRuntime.ProcessRequest(<HRESULT 0x80004001>)+0x18c
00000000`0643edc0 00000642`7f503bb3 mscorwks!CallDescrWorker+0x82
00000000`0643ee20 00000642`7f5251f8 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`0643eec0 00000642`7f525563 mscorwks!ForwardCallToManagedMethod+0x160
00000000`0643ef60 00000642`7f544738 mscorwks!COMToCLRWorkerBody+0x35b
00000000`0643f1c0 00000642`7f50c8ae mscorwks!COMToCLRWorkerDebuggerWrapper+0x50
00000000`0643f230 00000642`7f60249e mscorwks!COMToCLRWorker+0x366
00000000`0643f520 00000642`fff58293 mscorwks!GenericComCallStub+0x5e
00000000`0643f5d0 00000642`fff58633 webengine!HttpCompletion::ProcessRequestInManagedCode+0x2a3
00000000`0643fa80 00000642`fff9abf4 webengine!HttpCompletion::ProcessCompletion+0x63
00000000`0643fac0 00000642`7f48dc77 webengine!CorThreadPoolWorkitemCallback+0x24
00000000`0643faf0 00000642`7f4a289a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x157
00000000`0643fb90 00000642`7f41f0ac mscorwks!ThreadpoolMgr::WorkerThreadStart+0x1ba
00000000`0643fc30 00000000`77d6b6da mscorwks!Thread::intermediateThreadProc+0x78
00000000`0643ff80 00000000`00000000 kernel32!BaseThreadStart+0x3a





0:025> !clrstack
OS Thread Id: 0x1258 (25)
Child-SP         RetAddr          Call Site
000000000643e590 00000642801f4b87 System.Security.Cryptography.CryptoAPITransform.TransformFinalBlock(Byte[], Int32, Int32)
000000000643e620 00000642801f25c7 MyCryptoClass.Decrypt(System.String, System.String, Boolean)
000000000643e960 00000642bc8e449b System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
000000000643ea10 00000642bc8f2215 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
000000000643eab0 00000642bc8e3553 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
000000000643eb60 00000642bc8e7874 System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
000000000643ebc0 00000642bc8e745c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
000000000643ec50 00000642bc8e608c System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
000000000643ec90 000006427f602322 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

If in your code you are calling Convert.FromBase64String (or CryptoAPITransform.TransformFinalBlock directly) assure you are not passing an empty string as the value to convert, for example:

Public Function Decrypt(ByVal Source As String) As String
    
    Dim byteArr As Byte() = System.Convert.FromBase64String(Source)
    
    [...]
    
End Function

should instead look like this:

Public Function Decrypt(ByVal Source As String) As String
    'convert from Base64 to binary

    If IsNullOrEmpty(Source) Then
        Return String.Empty
    End If
    
    Dim byteArr As Byte() = System.Convert.FromBase64String(Source)
    
    [...]
    
End Function

Carlo

Recently I had an interesting discussion with a friend of mine about IIS logging: basically he configured his web server to create a new log every day and then wanted to use a third party tool to extract some statistics and graphics from the logs. Unfortunately the tool often has troubles and gets weird results because sometime at the end of the old log file (the one about the ending day) they have some records whose date and time is into the new day. Something like the following:

#Software: Microsoft Internet Information Services 7.0
#Version: 1.0
#Date: 2009-03-06 23:59:53
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger.htm - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/global.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/light_sidebar_left_wide.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/customcss.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/vjr6phmypy.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/msAnalytics.cache - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 3 50 0
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/PopupPanel.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/style.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 15
2009-03-06 23:59:59 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/trans_pixel.gif - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 200 0 0 0
2009-03-07 00:00:01 ::1 GET /Themes/Blogs/luxinterior/style/print.css - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 404 0 2 15
2009-03-07 00:00:01 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/Modal.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0
2009-03-07 00:00:02 ::1 GET /MidnightTest/Never+doubt+thy+debugger_files/InlineEditor.js - 80 - ::1 Mozilla/4.0+(compatible;+MSIE+7.0;+Windows+NT+6.0;+WOW64;+Trident/4.0;+SLCC1;+.NET+CLR+2.0.50727;+InfoPath.2;+FDM;+.NET+CLR+3.5.21022;+.NET+CLR+1.1.4322;+.NET+CLR+3.5.30729;+.NET+CLR+3.0.30618;+OfficeLiveConnector.1.3;+OfficeLivePatch.0.0;+MS-RTC+EA+2;+MS-RTC+LM+8) 304 0 0 0

Even if this is not easy to reproduce (I had to try quite a few times to get enough load on IIS and obtain the result above) this behavior is expected: when a client requests a web page, very likely IIS will have to serve multiple files as part of that same request (the page itself plus any linked/included image, CSS style, script etc…), we can say those resources are all part of a single logical request and therefore are treated as a single unit. So if for example you get a request at 23:59:59 very likely the page execution will take more than 1 second, let alone serving the images and other files that might be several Kb large… If we are around midnight we’ll very likely have a few resources served into the new day but logged in the previous day’s file, which is the one there the start of the logical request belongs. Usually this is a “gap” just a few seconds long, normally 2-3 seconds into the new day, even if a longer timeframe in theory cannot be excluded.

A possible solution for this friend of mine is to customize the IIS logging mechanism (see Customize IIS logging), but this could have an impact on performance (one of the requirements here was to not affect the current performance in any way) even simply because of the time needed for the information to transit from kernel mode (IIS default) to user mode. This was not an option in our case.

Anyway you can LogParser to extract your statistics (I have some sample scripts here), or as my friend finally chose, you can use LogParser to reformat your IIS log files and exactly dividing the records as you (or your statistical application) prefer. For example:

logparser "select date, time, s-ip, cs-method, cs-uri-stem, cs-uri-query, s-port, cs-username, c-ip, 
            cs(User-Agent), sc-status, sc-substatus, sc-win32-status, time-taken into day_1.csv from *.log 
            where to_timestamp(date,time) between timestamp('2009/03/06 00:00:00', 'yyyy/MM/dd hh:mm:ss') 
            and timestamp('2009/03/06 23:59:59', 'yyyy/MM/dd hh:mm:ss')" 
            -i:iisw3c -o:tsv -headers:on -oSeparator:space

As usual note that the command must be on a single line, I’m breaking the line here only to improve readability.

The script above is quite simple and “static”, it takes into account only a specific day and output log file, anyway it should not be too difficult to include is in a vbscript or batch file to dynamically parse and output all of your IIS log files at once.

By the way, do not forget the –consolidateLogs parameter for the IISW3C input file type if you have multiple virtual sites and want to consolidate your data:

consolidateLogs

Values: ON | OFF

Default: OFF

Description: Return entries from all the input log files ordering by date and time.

Details:
When a from-entity refers to log files from multiple IIS virtual sites, specifying ON for this parameter causes the IISW3C input format to parse all the input log files in parallel, returning entries ordered by the values of the "date" and "time" fields in the log files; the input records returned will thus appear as if a single IISW3C log file was being parsed.
Enabling this feature is equivalent to executing a query with an "ORDER BY date, time" clause on all the log files. However, the implementation of this feature leverages the pre-existing chronological order of entries in each log file, and it does not require the extensive memory resources otherwise required by the ORDER BY query clause.

Carlo

Consider this scenario: you are browsing a web site which at some point switches from http to https, and your browser show you a warning.

In Firefox you get:

Connection Partially Encrypted
Parts of the page you are viewing were not encrypted before being transmitted over
the Internet.
Information sent over the Internet without encryption can be seen by other people
while it is in transit

In Internet Explorer you get:

This page contains both secure and nonsecure items.
Do you want to display the nonsecure items?

 

You can check KB #910444 for SSL termination in ASP.NET; if this does not help, check this post, that was the situation I had to deal with a few days ago.

Just an additional note: if you wish to control how your browser behaves in such situations, you can check (and change) the following settings in Internet Explorer and Firefox:

Internet Explorer

Firefox

Carlo

A couple of days ago I was helping a colleague of mine with some tests and I had the need to change the ThreadPool configuration; more precisely, I wanted to increase the minWorkerThreads value. Everything was working fine at first, because I was changing the value by code using the SetMinThreads method, but I also wanted to test it changing the values from my machine.config.

First thing, to be on the safe side I set autoConfig=”false” (see why here) and set my <processModel> element as follows:

<processModel autoConfig=”false” minWorkerThreads=”23” />

Why set it to 23? Simply because I did not want it to match any default.

I run my test page, attached Windbg to the process and had a look at !threadpool output: something was definitely wrong, as it was telling that minWorkerThreads was set to 2 (the default value is 1 * CPU number = 2 for my machine):

0:029> !threadpool
CPU utilization 48%
Worker Thread: Total: 2 Running: 0 Idle: 2 MaxLimit: 40 MinLimit: 2
Work Request in Queue: 0
--------------------------------------
Number of Timers: 8
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 4 CurrentLimit: 0 MaxLimit: 40 MinLimit: 2

Now I see from here and with some reasoning, it is already possible to understand why I was not seeing MinLimit=46 as I was expecting… Who has the eagle eye?

I was in a hurry (as usual) and I tried a few other things, one of them was to set autoConfig back to true, here is what I got:

0:030> !threadpool
CPU utilization 7%
Worker Thread: Total: 2 Running: 0 Idle: 2 MaxLimit: 200 MinLimit: 46
Work Request in Queue: 0
--------------------------------------
Number of Timers: 8
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 4 CurrentLimit: 0 MaxLimit: 200 MinLimit: 2

This time I’m getting it as I wanted! I’m sure someone already got it…

But before going to the solution, let’s just explain why this cannot be because of autoConfig as you may think

Here is how MSDN defines autoConfig:

Specifies whether to automatically configure the following settings to achieve optimal performance based on the machine configuration:

• The maxWorkerThreads attribute
• The maxIoThreads attribute
• The minFreeThreads attribute of the httpRuntime element.
• The minLocalRequestFreeThreads attribute of the httpRuntime element
• The maxConnection attribute of the <connectionManagement> Element (Network Settings) element.

The values are set according to the KB article at http://support.microsoft.com/?id=821268.
This attribute does not affect the .NET Framework client applications; only ASP.NET applications.
The autoConfig attribute can be one of the following values.

• True: Indicates that ASP.NET automatically configures the attributes in the preceding list to achieve optimal performance based on the machine configuration.
• False: Indicates that ASP.NET should use the explicitly defined values for the attributes in the preceding list.

The default in the Machine.config file is True, unless there is a previously existing configuration.

minWorkerThreads is not one of the values automatically configured by the runtime, so whether autoConfig is true or false does not make any difference.

Not quite…

Have another look at the !threadpool output above: with autoConfig=”true” the ThreadPool limit for maxWorkerThreads is 200 (100 * 2 CPUs), while with autoConfig=”false” maxWorkerThreads is set to 40 (default 20 * 2 CPUs).

As you can imagine, it is not possible to set minWorkerThreads higher than maxWorkerThreads… The runtime detects the inconsistency and simply set the “min” value to its default.

So I have 3 points to make:

1. Always keep an eye on default values
2. Keep the other eye on how default values influence each other
3. Ok, I lied, just a bit… autoConfig does not directly influence minWorkerThreads and minIoThreads, but they are instead affected by their counterparts such as maxWorkerThreads and maxIoThreads

Carlo

I got a couple of cases of this kind recently, one where the web pages were served by PerformancePoint and the other one was a completely custom web site, but both of them shared the same common root issue: browsing some specific pages, the CPU on client got constantly at 100% and the GUI was completely frozen

From the Internet Explorer dump we captured it was very clear that thread 2 was the one burning the CPU:

0:000> !runaway
 User Mode Time
  Thread       Time
   2:1654      0 days 0:07:55.954
   0:1610      0 days 0:00:00.420
   7:142c      0 days 0:00:00.070
   9:1788      0 days 0:00:00.050
   4:1388      0 days 0:00:00.010
  17:8f0       0 days 0:00:00.000
  16:11cc      0 days 0:00:00.000
  15:1180      0 days 0:00:00.000
  14:11ec      0 days 0:00:00.000
  13:1778      0 days 0:00:00.000
  12:f8        0 days 0:00:00.000
  11:7dc       0 days 0:00:00.000
  10:e0c       0 days 0:00:00.000
   8:1784      0 days 0:00:00.000
   6:1420      0 days 0:00:00.000
   5:1478      0 days 0:00:00.000
   3:1338      0 days 0:00:00.000
   1:1634      0 days 0:00:00.000

And thread 2 has his stack:

0:002> kpL1000
ChildEBP RetAddr  
01bcf0bc 43d0e4d7 mshtml!CFormatInfo::GetMatchedBy
01bcf170 43cf914f mshtml!CStyleSelector::Match+0x34d
01bcf694 43d12175 mshtml!CStyleSheetArray::Apply+0x1e1
01bcf6f4 43d17298 mshtml!CElement::ApplyDefaultFormat+0x490
01bcf708 43cf8958 mshtml!CAnchorElement::ApplyDefaultFormat+0x9f
01bcf748 43cf53e2 mshtml!CElement::ComputeFormatsVirtual+0xaa3
01bcf764 43d0cb08 mshtml!CElement::ComputeFormats+0x3a
01bcf9f4 43d3876b mshtml!CTreeNode::GetFancyFormatHelper+0x4b
01bcfb10 43e167ab mshtml!CElement::UpdateFormats+0x2da
01bcfb2c 43d3d908 mshtml!CElement::HandleMouseHoverForStyle+0x1a7
01bcfbac 43e3f53c mshtml!CDoc::PumpMessage+0xa3f
01bcfcf8 43d3c4a1 mshtml!CDoc::OnMouseMessage+0x4df
01bcfe1c 43d7e137 mshtml!CDoc::OnWindowMessage+0x748
01bcfe48 7e398734 mshtml!CServer::WndProc+0x78
01bcfe74 7e398816 user32!InternalCallWinProc+0x28
01bcfedc 7e3989cd user32!UserCallWinProcCheckWow+0x150
01bcff3c 7e398a10 user32!DispatchMessageWorker+0x306
01bcff4c 4367e6c3 user32!DispatchMessageW+0xf
01bcffb4 7c80b683 ieframe!CTabWindow::_TabWindowThreadProc+0x189
01bcffec 00000000 kernel32!BaseThreadStart+0x37

Something similar also happens if you have a .NET control inside a table using percentage width and height for the control, and using percentage width for the wrapping table cell:

ChildEBP RetAddr 
018a84f8 77f17fda ntdll!KiFastSystemCallRet 
018a854c 629c31f7 gdi32!NtGdiExtTextOutW+0xc 
018a8588 629c322c lpk!InternalTextOut+0x1d4 
018a85bc 77f31dc4 lpk!LpkExtTextOut+0x29 
018a860c 436761bc gdi32!ExtTextOutW+0x26a 
018a8890 43676038 mshtml!XHDC::ExtTextOutW+0x13e 
018a88b8 43675ffa mshtml!ExtTextOutW+0x24 
018a8e64 43675f06 mshtml!LSReExtTextOut+0x79 
018a8f38 436763a5 mshtml!CLSRenderer::TextOutW+0x7fe 
018a90d8 436b03e4 mshtml!CLSRenderer::BlastLineToScreen+0x4a7 
018a9150 436aff59 mshtml!CLSRenderer::RenderLine+0x3f7 
018a94b8 436afc4b mshtml!CDisplay::Render+0x4e0 
018a94d0 436b004f mshtml!CFlowLayout::Draw+0x1c 
018a9504 436ad37e mshtml!CLayout::DrawClient+0x52 
018a98e0 436abdc0 mshtml!CDispLeafNode::DrawSelf+0x42c 
018a9bc4 436ace26 mshtml!CDispNode::Draw+0x10d 
018a9be4 436ac529 mshtml!CDispContainer::DrawChildren+0x3f 
018a9f80 436abdc0 mshtml!CDispContainer::DrawSelf+0x290 
018aa264 436ace26 mshtml!CDispNode::Draw+0x10d 
018aa284 436ad86a mshtml!CDispContainer::DrawChildren+0x3f 
018aa620 436abdc0 mshtml!CDispContainer::DrawSelf+0x2be 
018aa904 436ace26 mshtml!CDispNode::Draw+0x10d 
018aa924 436ad86a mshtml!CDispContainer::DrawChildren+0x3f 
018aacc0 436abdc0 mshtml!CDispContainer::DrawSelf+0x2be 
018aafa4 43667b64 mshtml!CDispNode::Draw+0x10d 
018acf50 43667a64 mshtml!CDispRoot::DrawBand+0xc7 
[...]

The stacks look quite similar for the one we had for a couple of old bugs already fixed for Internet Explorer when dynamically adding cells via DHTML (back in 2002-2003); there was also another bug in .NET 2.0 which has been fixed in KB# 928365.

For both customers the problem reproduced only with IE7, IE was running in Strict mode (but not in Quirks mode) and the page layout was made with nested Tables and DIVs whose dimensions (width and/or height) where expressed in percentage.

Since we needed the page layout to adapt gracefully to the size of browser’s window, we could not avoid using percentages for Tables and DIVs, so we decided to not use Strict mode instead. This is controlled with the !DOCTYPE page declaration, in particular:

To make things easy we simply removed the DOCTYPE declaration from the problematic pages, and the CPU usage went back to normal.

In my tests, the problem does not reproduce in IE8.

Carlo

Ajax is a flexible and powerful technology, but sometimes “With great power comes great responsibility” . And also some kind of fragility and sensitivity to external factors.

In this case browsing the application worked somehow fine, but triggering a partial postback we were getting the following error on the browser:

The message received from the server count not be parser. Common causes for this error are when the response is modified by calls to Response.Write(), response filters, HttpModules, or server trace is enabled.

If you get weird Ajax script errors, my experience tell me to always first check if Http compression is enabled on the web server (this is not the first time I tackle this topic), but this was not the case. An important thing to note is that the application was working perfectly fine when browser from the LAN, while it was failing when browsed from the Internet (no matter the browser we were using).

An important thing to note is that browsing from the Internet, our request was going through IAG:

Intelligent Application Gateway (IAG) is a remote access gateway that boosts productivity by giving mobile and remote workers, partners, and customers easy, flexible, and secure access to virtually any application from a broad range of devices and locations. Using a combination of SSL VPN (secure socket layer virtual private network), a Web application firewall, and endpoint security management, IAG provides employees, partners, vendors, and customers with secure and easy access from a broad range of devices and locations including kiosks, PCs, and mobile devices.

Basically IAG allows access to internal web applications over the internet. It does this by translating every HTML/script link it finds relating to the published Intranet server in the HTTP Response (both Header and Body).

To make a not so long story even shorter, there was a bug which has been fixed in .NET 3.5 SP1, which cause this error when “something” was modifying the headers collection of a request. But we were getting the error anyway (the customer was already running .NET 3.5 SP1) because IAG was modifying the body of a web request and this still supposed to cause the exception.

And just to clarify, this latter behavior is by design. The reason is proxy rewriting URLs on the fly (so we’re not just talking about IAG but every kind of proxy/firewall or even an HttpModule with this capability); the format that the UpdatePanel control uses to send the client updates is very sensitive to any modification made along the way to the client, and it is impossible to support every kind of possible modification that can be made by potentially countless applications and filters.

So there are three possible solutions in my opinion, which one to choose is up to you and your needs:

1. Do not use the UpdatePanel: this means you cannot use Ajax and you must always do a full page postback
2. Do not use the proxy, or make sure it is not tampering the request’s body (if possible, of course)
3. Write your URLs so that they do not need to be rewritten by the proxy: this is the most complex, and maybe not really applicable solution (simply because of the names translation needed to access internal resources from the Internet)

Carlo

Getting feedback always nice, as it is getting suggestions about new posts as happened this morning with my colleague Michael Clemens after he read my latest entry from yesterday (so thanks Mike for sharing this!). The point is, you may get a similar experience (exactly vice versa) after having installed the “IIS media pack 1.0 - Web playlists and bit Rate Throttling package” as part of the Microsoft Web Platform installer" on a x64 OS version.

The media pack installs two 32-bit modules ("BitrateModule" and "PlaylistHandler") that prevent a 64-bit application pool from starting up, resulting in a fail-fast disabled application pool. A look at the Application event log first tells you the application pool couldn't load "%ProgramFiles%\IIS\Media\playlisthandler.dll”. Searching applicationHost.config for this module occurrence, you can simply adjust the affected <add> element with the preCondition attribute set to bitness32.

After this, the affected app pool still cannot start…

Back to the Application event log, you’ll see another module load failure for "%ProgramFiles%\IIS\Media\bitratemodule.dll". Changing this in the same manner as for the PlaylistHandler module will give you the following entry in applicationhost.config added below the <globalmodules> section:

<add name="BitrateModule" image="%ProgramFiles%\IIS\Media\bitratemodule.dll" preCondition="bitness32" />

Do not forget to search the whole “%windir%\System32\inetsrv\config\applicationHost.config” for any additional module entries (in <add> elements) on these two modules to ensure they all specify the preCondition attribute with bitness32.

And last but not least, if you did end up with a fail-fast disabled application pool, do not forget to start it again…

Carlo

As sometime happens, while setting up a repro for a customer (I’m working with him on a completely different problem) I wanted to test my sample code on a 32 bit w3wp.exe instance (I am running Windows 2008 x64); nothing easier on IIS7, just create a new application pool and change its “Enable 32.Bit Applications” property to true in IIS Manager and you’re done:

But when I tried to run my code, I got this a “HTTP Error 503. The service is unavailable” message and the application pool was stopped. The Application event log contains a few entries like the following:

Log Name:      Application
Source:        Microsoft-Windows-IIS-W3SVC-WP
Date:          02/02/2009 14.19.05
Event ID:      2280
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      <computername>
Description: The Module DLL C:\Windows\system32\RpcProxy\RpcProxy.dll failed to load.  The data is the error.

I also got some of this warning:

Log Name:      System
Source:        Microsoft-Windows-WAS
Date:          03/02/2009 20.42.55
Event ID:      5139
Task Category: None
Level:         Warning
Keywords:      Classic
User:          N/A
Computer:      <computername>
Description: A listener channel for protocol 'http' in worker process '4580' serving application pool '32bitPool' reported a listener channel failure.  The data field contains the error number

If I changed the application pool back to a 64 bit process, everything worked fine again.

I save you the tedious details, but the point is: RpcProxy.dll is 64 bit, obviously it cannot by loaded into a 32 bit process…

As I usually do as part of my “learning experience”, I installed all the available roles for IIS7 and one of them is “RPC over HTTP Proxy”:

This installs RpcProxy.dll (and other files) and changes applicationHost.config adding a new global module:

<add name="PasswordExpiryModule" image="C:\Windows\system32\RpcProxy\RpcProxy.dll" />

How can I prevent IIS from loading it? Easy, just add the preCondition=”bitness64” attribute as follows:

<add name="PasswordExpiryModule" image="C:\Windows\system32\RpcProxy\RpcProxy.dll" preCondition="bitness64" />

Bingo, I finally have my 32 bit worker process up and running!

 Carlo

Sometimes they come back, as my favorite writer says… This is the case of this error message I already wrote about a couple of years ago; anyway this time the customer before calling CSS for support had already tried the suggestions on my previous post, unfortunately without luck. The customer has tried:

• aspnet_regiis -ga “Network Service”
• cscript metaacl.vbs IIS://Localhost/W3SVC/AppPools IIS_WPG RE
• Assured the account running Application Pool (NETWORK SERVICE) is part of the IIS_WPG group

The difference this time is that the application’s files are hosted on a centralized network share; for this particular scenario, also the account used in the “Connect As…” dialog in IIS Manager must be part of the IIS_WPG group:

Carlo

One of the (very few) downsides I see working in Customer Support is that most of the times when talking to colleagues and friends or writing a new post for my blog, I find myself talking about problems, bugs, exceptions… what is not working fine, like a doctor most of the times has to deal with malaises and diseases. Anyway the good part is that most of the times we are able to find the solution to those problems, or at least we can alleviate them.

This is the case of a problem I had with the Ajax TabContainer control which is not displayed correctly in Design View, where the Tab caption is not completely visible, as in the screenshot here below:

But if we open the page in a real browser, it displays correctly:

This is part of a problem reported on the Connect site some time ago: http://connect.microsoft.com/VisualStudio/feedback/ViewFeedback.aspx?FeedbackID=322477.

This has to do with the !DOCTYPE (Document Type Definition, or DTD), which among other things influences how CSS styles, formatting and positioning are applied to the page and its UI elements. With DTD we can control IE’s strict standard compliance; for example in this case if we remove the DTD from the source code in Visual Studio, then the TabContainer control and its Tabs are displayed correctly:

But this just moves the problem to the real browser, where without strict compliance mode IE fails to render the tabs correctly:

Visual Studio uses it own rendering engine to show pages and controls in Design View, and this is the component which does not handles compatibility mode correctly; this is a known issue and as of now I know this problem is scheduled to be fixed in Visual Studio 2010, there is no plan for a fix for the current Visual Studio version.

Anyway this real problem here is the difficulty to click on the Tab caption to switch between tabs at design time; other than that I’ve not heard or other issues but feel free to correct me if I’m wrong. So, if that is the real issue, a simple workaround a suggested to the customer is to select the TabContainer control and then in the “Properties” grid you can change the ActiveTabIndex value and press ENTER: this will give focus to the Tab you selected. Remember that this is a zero based array, so as in the sample here below if you want to switch to TabPanel5 you have to set ActiveTabIndex to 4:

Hope this helps…

Carlo