Ukadc.Diagnostics Reference Example

This lightweight reference example should help users quickly get to grips with the new Ukadc.Diagnostics library. A number (though not all) of the features are demonstrated and can be downloaded and built in Visual Studio 2008. The source is available at the end of this page.

The Scenario

This quickstart considers a very simple scenario with a website and a WCF service (hosted in IIS/Cassini). The website has just two pages: Login.aspx and Default.aspx. The site is configured to use Forms Authentication and has a custom MemberShipProvider which takes care of the authentication of users (nothing complex, if the password equals the username, you're in!).

loginAspx.png

The default.aspx page shows a list of products which are retrieved from the WCF service. The WCF service is also very simple and actually has the values of the products hard-coded.

defaultAspx.png

Not going to win any awards for design but this example is about logging. The Logout link logs you out and the Throw button throws an exception (not a feature you see everyday but we need a way to create exceptions to test our logging of errors).

Instrumenting the Web Site using System.Diagnostics

The first thing we do is add some logging code to the application. Let's start by logging unhandled errors. A good place to do this is in the Global.asax by adding the Application_Error method:

private static TraceSource _source = new TraceSource("ReferenceWebApplication");

protected void Application_Error(object sender, EventArgs e)
{
   _source.TraceData(TraceEventType.Error, 0, this.Server.GetLastError());
} 


Notice that we statically initialise a TraceSource with the name "ReferenceWebApplication" - we'll reference this name later in configuration. We then call the TraceData method of this class whenever an exception isn't handled and specify the Error TraceEventType and pass in the Exception object to the data parameter.

Note - At this point we aren't making any decisions about what happens to this logging information. All that's important at present is that the logging information is surfaced so that it can be used and stored as appropriate. We choose how this happens later through configuration.

This is a good start but doesn't go far enough. It's very common for developers to instrument their code with adhoc comments that 'profile' operations something like this:

public void DoSomething()
{
	Debug.WriteLine("Starting DoSomething method");
	// do something!
	Debug.WriteLine("Exiting DoSomething");
} 


However, this is rarely implemented in a consistent manner and the resulting data isn't easy to consume in any interesting way; it's only of use to the Developer who wrote the code ni the first place. System.Diagnostics offers a consistent way of profiling operations through the existence of the Start and Stop values of the TraceEventType enumeration. This allows us to do things like this:

public void DoSomething()
{
	myTraceSource.TraceData(TraceEventType.Start, 0, "DoSomething");
	// do something!
	myTraceSource.TraceData(TraceEventType.Stop, 0, "DoSomething");
} 


Much better and we'll see why later.

This is a useful approach for profiling the life of our pages in ASP.NET too and we can add some code to the Global.asax to do just that (note we're reusing the static _source variable from the earlier example). We're only interested in profiling the lifetime of .aspx pages (not requests for .axd etc) so we check first before logging.

protected void Application_BeginRequest(object sender, EventArgs e)
{
    if (Request.Path.EndsWith(".aspx", StringComparison.InvariantCultureIgnoreCase))
    {
        _source.TraceEvent(TraceEventType.Start, 0, Request.RawUrl);
    }
}

protected void Application_EndRequest(object sender, EventArgs e)
{
    if (Request.Path.EndsWith(".aspx", StringComparison.InvariantCultureIgnoreCase))
    {
        _source.TraceEvent(TraceEventType.Stop, 0, Request.RawUrl);
    }
} 


Next, let's add some instrumentation to our custom MembershipProvider which currently looks like this (we've only implemented ValidateUser for this example). As you can see, to login to our example system you can enter any username and password and gain access provided they are the same.

public class MyCustomMemberShipProvider : MembershipProvider
{
    public override bool ValidateUser(string username, string password)
    {
		if (username != password)
		{
			return false;
		}
		return true;
    }
} 


In reality, this method might be hitting an external system (ADAM, SQL etc) and therefore we might like to 'profile' the operation with logging code. We could do so using the Start and Stop TraceEventTypes as above which would look something like this:

public class MyCustomMemberShipProvider : MembershipProvider
{
	private static TraceSource _source = new TraceSource("ReferenceWebApplication");

    public override bool ValidateUser(string username, string password)
    {
		_source.TraceEvent(TraceEventType.Start, 0, "ValidateUser");
	
		bool result = username == password;
		
		_source.TraceEvent(TraceEventType.Stop, 0, "ValidateUser");
		
		return result;
    }
} 


At this point, we have only ever taken a reference on System.Diagnostics which ships with all versions of .NET since Version 2. However, because writing code like the example shown above can be error prone and fiddly (e.g. entering the name of the method twice and having to restructure the code to put the return after the Stop event) we have provided an ExtendedSource which derives from TraceSource. The ExtendedSource provides an additional method called ProfileOperation which return IDisposable for use in a using block. This automatically causes a Start event when the ProfileOperation is called and a Stop event when the using block exits (i.e. Dispose() is called).

private static ExtendedSource _source = new ExtendedSource("ReferenceWebApplication");

public override bool ValidateUser(string username, string password)
{
	// Start will be logged here
    using (_source.ProfileOperation("ValidateUser"))
    {
        if (username != password)
		{
			return false;
		}
		return true;
	// Stop will be logged here
    }
} 


Furthermore, this ensures that the Stop event will log in the event of an exception being thrown inside the body of the method. Note, to use the ExtendedSource you will need a reference to the Ukadc.Diagnostics library so this approach is optional. It is not required to use the rest of the features of the Ukadc.Diagnostics library.

Also, let's add a log event for a failed login.

if (username != password)
{
	_source.TraceEvent(TraceEventType.Information, 0, "Login failed for user '{0}'.", username);
	return false;
} 


In this instance we've used the TraceEvent method (part of the standard TraceSource class) that takes a format string and an array of arguments. This is useful because the underlying string.format won't occur unless the actual event is going to be logged somewhere. A useful performance optimisation.

At the moment because we haven't configured any logging sources, none of this data will make it's way anywhere.

Turning on some logging output

Lets take a look at the output of our logging code with the minimum amount of configuration. To achieve this all we have to do is add a source in configuration with the name "ReferenceWebApplication" and set its switchValue to something that would allow our events through. We're going to choose the 'All' value but check out this post for more information on how the various levels work.

<system.diagnostics>
	<sources>
		<source name="ReferenceWebApplication" switchValue="All" />
	</sources>
</system.diagnostics> 


Normally, you'd expect to configure some listeners but in this case we're just going to let the DefaultTraceListener (which is automatically added by System.Diagnostics) do the work. The DefaultTraceListener calls OutputDebugString and we can view this output using SysInternal's DebugView. And here's what our logging looks like so far:

debugViewDefaultTraceListener.png

The red rectangle contains the log events from the first load of the Login.aspx page (the one into which the user enters his details). The second blue rectangle shows the second request - the postback - when the user submits his details. In this case we can also see the nested call to ValidateUser (orange highlight) and even the fact I failed to login (green highlight).

This is nice but one of the disadvantages of the built in DefaultTraceListener (and many others) is that there output isn't very configurable. In the Ukadc.Diagnostics library we have provided an alternative OutputDebugStringTraceListener that uses the library's system of Tokens to allow for configuration. Here's an example:

<system.diagnostics>
	<sources>
		<source name="ReferenceWebApplication" switchValue="All">
			<listeners>
				<clear /> <!-- this removes the DefaultTraceListener -->
				<add name="ods" type="Ukadc.Diagnostics.Listeners.OutputDebugStringTraceListener, Ukadc.Diagnostics" 
					initializeData="{EventType}: {Message} - {DateTime}, Process={ProcessId}, Thread={ThreadId}" />
			</listeners>
		</source>
	</sources>
</system.diagnostics> 


Which gives the following output:

debugViewOdsTraceListener.png

Not going to change the world, but it is easier to read and totally configurable (you can even add your own token to extend the output - see Tokens for more information).

Adding correlation

One of the biggest problems with this kind of logging is correlation. That is, on a busy web server, how do I correlate one Start event for /Login.aspx with the appropriate End event? There will likely be hundreds of such entries and they're much less valuable if I can't tie them together. Thankfully, System.Diagnostics has an answer to this problem with the Trace.CorrelationManager.ActivityId property. This is a Guid that is stored in Thread Local Storage (TLS - also known in .NET as CallContext) and can be accessed whenever a log event occurs. All we need to do, is create a Guid at the start of an operation so let's add some code to our Global.asax to do just that.

We'll add this code to the Application_BeginRequest method we looked at earlier:

protected void Application_BeginRequest(object sender, EventArgs e)
{
	// create a new ActivityId for this request
	Trace.CorrelationManager.ActivityId = Guid.NewGuid();
    if (Request.Path.EndsWith(".aspx", StringComparison.InvariantCultureIgnoreCase))
    {
        _source.TraceEvent(TraceEventType.Start, 0, Request.RawUrl);
    }
} 


Now lets change our output string to include the ActivityId token:

<add name="ods" type="Ukadc.Diagnostics.Listeners.OutputDebugStringTraceListener, Ukadc.Diagnostics" 
	initializeData="{ActivityId}|{EventType}: {Message} - {DateTime}, Process={ProcessId}, Thread={ThreadId}" /> 


debugViewActivityId.png

Note how the two request have different ActivityId's, but all events within the request are now correlated by the same activity id.

Instrumenting the WCF Service

So far we've only instrumented our web site, but what about the WCF service? The WCF service has a GetProducts method that we can instrument much the same way we did with the ValidateUser method above:

private static ExtendedSource _source = new ExtendedSource("ReferenceServiceApplication");

public List<Product> GetProducts()
{
	using (_source.ProfileOperation("GetProducts"))
	{
		// simulate a slowish DB call
		Thread.Sleep(150);
		return _products;
	}
} 


Because the service is in a different application we need to configure the same settings in a seperate configuration file (and note our sevice specifies a different TraceSource name: "ReferenceServiceApplication").

<system.diagnostics>
	<sources>
		<source name="ReferenceServiceApplication" switchValue="All">
			<listeners>
				<clear /> <!-- this removes the DefaultTraceListener -->
				<add name="ods" type="Ukadc.Diagnostics.Listeners.OutputDebugStringTraceListener, Ukadc.Diagnostics" 
					initializeData="{ActivityId}|{EventType}: {Message} - {DateTime}, Process={ProcessId}, Thread={ThreadId}" />
			</listeners>
		</source>
	</sources>
</system.diagnostics>


debugViewServiceNotCorrelated.png

Once we've successfully logged into our website we are redirected to the default.aspx page. This page loads the products from the WCF service by calling the GetProducts method. As you can see, now we have Trace information from two different applications. In the context of a single request, it's easy to interpret what's going on but, on a busy web server, we could easily run into the problem of being unable to correlate one event with another.

Fortunately, the chaps at Microsoft who worked on WCF were well aware of this problem and created a facility whereby WCF will automatically propagate an ActivityId from one process to another. All you have to do is add the following source to both the client and server to the sources in configuration:

<source name="System.ServiceModel" switchValue="Off" propagateActivity="true" /> 


As if by magic:

debugViewServiceCorrelated.png

Notice how the ActivityId's are all the same but we have two difference Process IDs which prove our logging is crossing a process boundary.

Other TraceListeners

So far we've only looked at TraceListeners that call the OutputDebugString method that can be viewed using DebugView. Great for demos but not so great for analysis or post-mortem. The Ukadc.Diagnostics ships with a number of other TraceListeners including the SqlTraceListener which allows you to write log data to a SQL Server Database in a structured way.

To do this we need to create a table called LogStore to hold our log data - here's a T-SQL Script to create a simple table that you might use to hold your logging data:

CREATE TABLE [dbo].[LogStore](
	[LogId] [int] IDENTITY(1,1) NOT NULL,
	[Source] [varchar](50) COLLATE Latin1_General_CI_AS NULL,
	[ActivityId] [uniqueidentifier] NOT NULL,
	[ProcessId] [int] NOT NULL,
	[ThreadId] [varchar](50) COLLATE Latin1_General_CI_AS NOT NULL,
	[EventType] [varchar](50) COLLATE Latin1_General_CI_AS NOT NULL,
	[Message] [varchar](8000) COLLATE Latin1_General_CI_AS NULL,
	[Timestamp] [datetime] NOT NULL,
	CONSTRAINT [PK_Log] PRIMARY KEY CLUSTERED 
	(
		[LogId] ASC
	)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY] 


Now, all we need to do to make use of this is add some configuration to our WCF Service and our Web Site.

<add name="sqlTraceListener" initializeData="sqlListener1Settings" type="Ukadc.Diagnostics.Listeners.SqlTraceListener, Ukadc.Diagnostics" /> 


Because the settings for a SqlTraceListener are far too complicated to fit into the initializeData string so we have to store this in a custom section. The initializeData value specfies which set of settings to use.

First, we need to inform the configuration file to expect a new configuration section:

<configuration>
  <configSections>
    <section name="ukadc.diagnostics" type="Ukadc.Diagnostics.Configuration.UkadcDiagnosticsSection, Ukadc.Diagnostics"/> 


Now we can add our ukadc.diagnostics section (it's usually best to put this directly after the System.Diagnostics section)

<ukadc.diagnostics>
  <sqlTraceListeners>
    <sqlTraceListener name="sqlListener1Settings" connectionStringName="log" 
      commandText="INSERT INTO LogStore VALUES(@Source, @ActivityId, @ProcessId, @ThreadId, @EventType, @Message, @Timestamp)"
      commandType="Text">
      <parameters>
        <parameter name="@Source" propertyToken="{Source}" />
        <parameter name="@ActivityId" propertyToken="{ActivityId}" />
        <parameter name="@ProcessId" propertyToken="{ProcessId}" />
        <parameter name="@ThreadId" propertyToken="{ThreadId}" />
        <parameter name="@EventType" propertyToken="{EventType}" callToString="true"/>
        <parameter name="@Message" propertyToken="{Message}" />
        <parameter name="@Timestamp" propertyToken="{DateTime}" />
      </parameters>
    </sqlTraceListener>
  </sqlTraceListeners>
</ukadc.diagnostics> 


For full details on how this all works check out the SqlTraceListener page. From now on, we should start to see some information build up in the LogStore table:

sqlTraceListenerOutput.png

In this form, this data can prove very useful for statistical analysis and post-mortem. For example, to analyse errors we can search the table for all EventTypes of Error or Critical.

SELECT ActivityId, [Message] FROM LogStore WHERE EventType = 'Error' OR EventType = 'Critical'


Which might return:

sqlTraceListenerError.png

We could now use this ActivityId to understand all logged activity that occured before and after this exception occured:

SELECT * FROM LogStore WHERE ActivityId = '3E040B1D-0227-4980-8A0D-B5DFAA6DC877'


Which shows:

sqlTraceListenerActivityId.png

As you can imagine, this whole approach can prove exceptionally useful during post-mortem of an issue. In fact it can often be useful to receive notifications of Errors and Criticals in a more direct way, such as via e-mail.

Implementing the SmtpTraceListener

Ukadc.Diagnostics ships with an SmtpTraceListener that can be used to send logging information via e-mail. This is configured in a similar manner to the SqlTraceListener:

<add name="smtpTraceListener" initializeData="smtpListener1Settings" type="Ukadc.Diagnostics.Listeners.SmtpTraceListener, Ukadc.Diagnostics" />


<ukadc.diagnostics>
	<smtpTraceListeners>
		<smtpTraceListener name="smtpListener1Settings" host="smtpHostServerName" port="25" from="from@address.com" to="to@address.com"
			 subject="Logging Event: {EventType}, {MachineName}"
			 body="{Message}
=======
Process={ProcessId},
Thread={ThreadId},
ActivityId={ActivityId}" />
    </smtpTraceListeners>
</ukadc.diagnostics>


For more information on these settings please see the SmtpTraceListener settings.

However, we wouldn't want ALL messages going to the SmtpTraceListener, we'd probably only want Error or Critical errors being e-mailed. Therefore it's important to add a filter to our listener:

<add name="smtp" type="Ukadc.Diagnostics.Listeners.SmtpTraceListener, Ukadc.Diagnostics"
     initializeData="smtpListener1Settings" >
  <filter type="System.Diagnostics.EventTypeFilter" initializeData="Error"/>
</add>


emailError.png

Sharing configuration

Because the Web project and the WCF Service project will share so much configuration, these settings were placed in a seperate file at the solution level.

separateConfigFiles.png

The files are referenced from the central Web.config file using the new configSource attribute that was introduced with .NET 2.0.

<ukadc.diagnostics configSource="Ukadc.config" />


A build event is then used to copy the files into the output directory of each project.

Running the example

Before we get to the code running there's a couple of things you'll need to do.
  • Setup the database - you'll need to create a database to store the logging information somewhere. The script to create the appropriate table for the demo is listed above (it's also contained in the download and called LogStore.sql)
  • Change the connection string - inside the Conn.config file you'll need to amend the 'log' connection string to point to your new database.
  • Change the SMTP Server - inside the Ukadc.config file you'll need to amend the name of the SMTP server to point to a valid address (or, if you can't access an SMTP server, make sure the SmtpTraceListener is disabled).
  • Set both projects to start - right click on the solution and choose properties. Ensure that both the ReferenceWebApplication and ReferenceServiceApplication are configured to start.

Get the sample

Off you go: Quick Reference Example - Drop 2

We look forward to your feedback.

Last edited Apr 25, 2008 at 5:24 PM by joshtwist, version 41

Comments

No comments yet.