The serviceSecurityAudit Service Behavior

The serviceSecurityAudit service behavior helped me figure out an exception I was receiving from my WCF service. As shown below, the exception was not very helpful:

System.ServiceModel.Security.MessageSecurityException occurred
  HResult=-2146233087
  Message=An unsecured or incorrectly secured fault was received from the other party. See the inner FaultException for the fault code and detail.
  Source=mscorlib
  StackTrace:
    Server stack trace:
       at System.ServiceModel.Channels.SecurityChannelFactory`1.SecurityRequestChannel.ProcessReply(Message reply, SecurityProtocolCorrelationState correlationState, TimeSpan timeout)
       at System.ServiceModel.Channels.SecurityChannelFactory`1.SecurityRequestChannel.Request(Message message, TimeSpan timeout)
       at System.ServiceModel.Security.SecuritySessionSecurityTokenProvider.DoOperation(SecuritySessionOperation operation, EndpointAddress target, Uri via, SecurityToken currentToken, TimeSpan timeout)
       at System.ServiceModel.Security.SecuritySessionSecurityTokenProvider.GetTokenCore(TimeSpan timeout)
       at System.IdentityModel.Selectors.SecurityTokenProvider.GetToken(TimeSpan timeout)
       at System.ServiceModel.Security.SecuritySessionClientSettings`1.ClientSecuritySessionChannel.OnOpen(TimeSpan timeout)
       at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
       at System.ServiceModel.Channels.ServiceChannel.OnOpen(TimeSpan timeout)
       at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
    Exception rethrown at [0]:
       at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
       at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
       at System.ServiceModel.ICommunicationObject.Open(TimeSpan timeout)
       at System.ServiceModel.ClientBase`1.System.ServiceModel.ICommunicationObject.Open(TimeSpan timeout)
       at System.ServiceModel.ClientBase`1.Open()
       at ProductsClient2.Program.Main(String[] args) in c:\Users\farooqm\Documents\Visual Studio 2012\Projects\WCF 4 Step By Step\Chapter 5\ProductsClient2\Program.cs:line 32
  InnerException: System.ServiceModel.FaultException
       HResult=-2146233087
       Message=An error occurred when verifying security for the message.
       InnerException:

Enter serviceSecurityAudit to the rescue. You can configure this to write security related service events to the Windows Event Log. Simply add the code in Listing 1.

  
<servicebehaviors>
     <behavior name="MyService_serviceSecurityAuditBehavior">
          <servicesecurityaudit 
               auditloglocation="Application" 
               serviceauthorizationauditlevel="SuccessOrFailure" 
               messageauthenticationauditlevel="SuccessOrFailure" />
     </behavior>
</servicebehaviors> 

Listing 1

Now when the service fails, take a look at the errors in the Windows Application Event Log. Listing 2 shows the messages seen in a PowerShell session.

 

PS C:\windows\system32> get-eventlog -logname application -entrytype error -newest 10 | fl message

Message : Message authentication failed.          
          Service: https://farooqmelite3/InternetProductsService/ProductService.svc
          Action: http://docs.oasis-open.org/ws-sx/ws-trust/200512/RST/SCT
          ClientIdentity: 
          ActivityId: <null>
          SqlException: An attempt to attach an auto-named database for file C:\Users\farooqm\Documents\Visual Studio 
          2012\Projects\WCF 4 Step By Step\Chapter 5\ProductsService\App_Data\aspnetdb.mdf failed. A database with the 
          same name exists, or specified file cannot be opened, or it is located on UNC share.

Listing 2

Turns out the application pool’s identity did not have permissions to create the ASP.NET membership provider database. Changing the identity to a different account resolved the issue as shown by the event log entries in Listing 3.

 

PS C:\windows\system32> get-eventlog -logname application -entrytype information -source "ServiceModel Audit 4.0.0.0" -newest 10 | fl message
Message : Impersonation succeeded.
          MethodName: GetProductNumbers
          ClientIdentity: bubba
          ActivityId: <null>
		  
Message : Service authorization succeeded.
          Service: https://farooqmelite3/InternetProductsService/ProductService.svc
          Action: http://tempuri.org/IProductService/GetProductNumbers
          ClientIdentity: bubba
          AuthorizationContext: uuid-2db2091a-8226-4e3d-a422-1720388491a0-1
          ActivityId: <null>
          ServiceAuthorizationManager: <default>

Message : Message authentication succeeded.
          Service: https://farooqmelite3/InternetProductsService/ProductService.svc
          Action: http://tempuri.org/IProductService/GetProductNumbers
          ClientIdentity: bubba
          ActivityId: <null>

Message : Message authentication succeeded.
          Service: https://farooqmelite3/InternetProductsService/ProductService.svc
          Action: http://docs.oasis-open.org/ws-sx/ws-trust/200512/RST/SCT
          ClientIdentity: bubba
          ActivityId: <null>

Listing 3

Hopefully, you will find the serviceSecurityAudit saves you time troubleshooting security related issues with your WCF service.

Advertisements

HTTP 500 Error When Browsing to Team Foundation Server 2012 Home Page

I had just installed Team Foundation Server Express 2012 and ran into the following error when browsing to the Server’s home page:

HTTP Error 500.0 – Internal Server Error
Calling LoadLibraryEx on ISAPI filter “C:\Windows\Microsoft.NET\Framework\v4.0.30319\\aspnet_filter.dll” failed

I ran aspnet_regiis -r in the both the Framework\v4.0.30319 and Framework64\v4.0.30319 directories, but no luck.

Next I opened IIS Manager and saw multiple occurrences of aspnet_filter.dll.

I removed all but the 64-bit version, performed an iisreset and problem solved!

Automating Query Plan Analysis – Determining Which Statistics Need Updating (Part 2)

Part 2 – Designing the Solution

Part 1 of this series explained the problem my customer was having regarding the handling of slow running queries. In this post, I will explain a possible solution to this problem. Keep in mind that this solution isn’t perfect.

To recap, this is the process I’d like to automate as much as possible:

  1. Identify slow running queries
  2. Examine their execution plans looking for operators with a high estimate rows to actual rows ratio
  3. Update statistics on said indexes or tables

The only way to fulfill item #2 is to capture the execution plans as the queries are executed. This rules out analyzing the cached plans via the sys.dm_exec_cached_plans DMV because it contains no information concerning the actual operator row counts. There isn’t an extended event that will give this information either. So we are relegated to capturing the execution plans via a SQL trace.

Fortunately we can use the Generic SQL Trace collector type that is part of the Management Data Warehouse to easily manage the capturing and loading of trace data into a central table. Unfortunately we now have a dependency on the Management Data Warehouse. If you are not familiar with it, read about it MSDN. It is a good idea to become familiar with its setup and capabilities.

Here is a simple diagram of the workflow:

image

There a three sub workflows in the diagram above.

  1. Trace events are written to a SQL trace file as they occur.
  2. Every five minutes, the Generic SQL Trace collector writes the trace data to a cache file (green arrows). This frequency is configurable. The location of the cache file is specified during initial Management Data Warehouse setup. Of course you already knew that since you read the MSDN documentation Smile.
  3. Every 30 minutes a Custom Data Collector Set uploads the data in cache to the snapshots.trace_data table in the Management Data Warehouse database (gray arrows). The 30 minute frequency is configurable as well.

At this point the trace data is in the database ready to be queried. Either the DBA can run this or a SQL Agent job can run the analysis query on a scheduled basis and write the output to a table, or if Reporting Services is available – a report can be run on a scheduled basis.

Regardless of the method, the DBA can readily see which statistics need updating. The DBA can then run those updates. Even this part can be automated as well. My customer already has a SQL Server Agent job that updates statistics. It wouldn’t be that difficult to hook up that job with the output of the analysis query.

The good aspects of this solution are the following:

  • We used out of the box SQL Server components and no custom code is needed aside from the analysis query.
  • Every five minutes the current trace file is closed and  a new trace is started automatically. This is good because we don’t have to worry about the trace file size getting out of control.
  • The solution can be developed and implemented quickly.

The not so good aspects of this solution are the following:

  • We are running a SQL trace continuously. Although this is a server-side trace, execution plans are being captured. These are not lightweight events. We need to really test the solution to make sure the application doesn’t get bogged down.
  • The analysis query can be painfully slow. For this reason it is best to constrain the query to a narrow time interval. Another idea is to run the analysis on a scheduled basis during off-peak hours and have the DBA review the results every morning. Maybe the query can be sped up by utilizing SQLCLR to shred the XML.
  • The Management Data Warehouse is in effect another application the DBA must maintain.

The negatives can certainly be daunting. However, if this will help solve a major source of application slowdowns then we may be able to live with the negatives.

In Part 3, I will explain the implementation of this solution.

Automating Query Plan Analysis – Determining Which Statistics Need Updating (Part 1)

Part 1 – The Problem

Note: SQL Server 2008 R2 SP1 is used in this three part series.

When reading a runtime execution plan (as opposed to an estimated plan), an operator whose estimated rows differs from its actual rows by a large factor is usually a sign that statistics need updating. This is common knowledge. When analyzing the query plan of a slow running query, this is one of the first things we look at.

image

A customer I routinely work with would repeatedly encounter slow running queries. The vast majority of these were sped up by statistics updates. The customer had a script that would update statistics with full scan on those tables and indexes whose statistics had not been updated in the last 24 hours. They would run this script every weekend. They would also run this script during working hours whenever users complained about slow queries. Incidentally, my team wrote the script for them and it worked well for a time. As their data size became larger and larger, the script took longer and longer to run. It also consumed more and more server resources. If run during peak times (which was usually the case), the server would slow to a crawl for several hours.

Ordinarily in this situation, the DBA would find the slow running queries, run them, and get execution plans. They could then check if any query operators shows evidence of outdated statistics. The DBA would then update only those statistics that directly impacted the query. Typically full scans rather that samples are done because determining the right sample size is tricky. SQL Servers are generally able to service full scans of a few tables concurrently with users’ workloads just fine. In fact this is what I did several times for them when they contacted me for assistance.

Unfortunately this company did not have a dedicated DBA that had the expertise to quickly do query plan analysis. The de facto DBA was a generalist who was responsible for many different technologies. It was unlikely that they would ever get a dedicated DBA due to financial constraints so they had to work with the personnel they had. Hence, when a performance issue arose, the easiest thing to do was to run the script that potentially did a full scan update statistics on every table and index in all user databases. Just to give an idea of the scale, there were three SQL Servers with over 40 databases with dozens of tables in each. The total data size was in the 3-4 terabyte range.

ID-10091331

Image: FreeDigitalPhotos.net

Given a lot of data and limited personnel, this customer wondered if there was a way to automate what an experienced DBA would do when users complain about slow queries. Specifically, could we look at the execution plans within a given time window, pick out the operators with a high estimated rows to actual rows ratio, and update only those indexes?

In Part 2 I will show how I evaluated the possibilities and settled on a solution.