Windows DevCenter    
 Published on Windows DevCenter (http://www.windowsdevcenter.com/)
 See this if you're having trouble printing code examples


Logging with Custom Web Events

by Jesse Liberty
03/13/2007

Every serious ASP.NET application requires logging, though not every application gets the logging it requires. Keeping an automated log allows you to track exceptions, errors, and unexpected events. A log can be used to create an audit trail, to track changes to your database, and to monitor the health and usage of your system.

There is any number of ways to create a logging system, and there is any number of places to log to. Among the most popular methods are logging to a file, logging to a database and, at times, sending an email to IT support (or, worse, to the developer!) when something goes drastically wrong.

ASP.NET provides extensive support for logging with the Health Monitoring classes provided in the System.Management namespace, but few know of it, and fewer use it. My personal theory is that this underutilization is due to a perfect storm of three factors: the system is typically presented in all its off-putting complexity; it is declarative, which is not a "natural" way for C# or VB programmers to think about coding; and Microsoft led us astray by naming the system Health Monitoring.

In this article, I will not attempt to explain the Health Monitoring system. Instead, I will extract the nuggets you can use to create a minimal yet very effective logging system that will send email in a crisis and routinely log to a database, and that is robust and extensible so that you can add the functionality you need with little effort.

Examining the Log

Before going into the details of how to add logging to your program, let's examine the output we'd like to see. In the application we're going to build, we'll take advantage of just a couple of the possible features, and log all errors and some events to a SQL Express table. We'll send an email message whenever an exception is thrown that might lead to a mismatch between what the app saves to a database and what the user hoped for.

It turns out that when the tables are created for Forms security and personalization (see my previous article), an extra table is added to the ADPNETDB.MDB database file: aspnet_WebEvents_Events, which is incredibly handy for capturing (surprise!) Web Events--the backbone of our logging. The structure of this table is shown in Figure 1.

Web Events table
Figure 1. aspnet_WebEvents_Events table structure

Web Events are provided by the Framework, in a hierarchy of classes, all deriving from the base class WebBaseEvent. This base class holds the date and time of the event, a unique ID, and an event code and a detail code, as well as a text message.

The event code is an enumeration of errors that might arise during the life cycle of an application (e.g., "RuntimeErrorValidationFailure"), a list of which can be obtained in the documentation, but that does not concern us here since we'll be creating our own event codes. (EventDetailCodes are used to subdivide event codes.)

This information can also be packaged into an email message, as shown in the following snippet:

MyProject Warning!
** Summary **
---------------
This message contains events 1 to 1 from the total of 1 events scheduled for this notification.  There were 0 events left in the buffer at the beginning of this notification.


** Application Information **
---------------
Application domain: cfde81e7-1-128169905359687500 Trust level: Full Application Virtual Path: /My Application Path: D:\Test\MyApplication \ Machine name: BERNSTEIN


** Events **
---------------
Event code: 3005
Event message: An unhandled exception has occurred.
Event time: 3/26/2007 2:09:44 PM
Event time (UTC): 3/26/2007 7:09:44 PM
Event ID: a9224a59cb8b495b98dcd88740c79ecf Event sequence: 28 Event occurrence: 1 Event detail code: 0

Process information:
    Process ID: 4500
    Process name: WebDev.WebServer.EXE
    Account name: BERNSTEIN\Jesse

Exception information:
    Exception type: System.Data.OleDb.OleDbException
    Exception message: Data type mismatch in criteria expression.

Request information:
    Request URL: http://localhost:2573/MyApplication/MyPage.aspx
    Request path: /MyApplication/MyPage.aspx
    User host address: 127.0.0.1
    User: jesse
    Is authenticated: True
    Authentication Type: Forms
    Thread account name: BERNSTEIN\Jesse

Thread information:
    Thread ID: 8
    Thread account name: BERNSTEIN\Jesse
    Is impersonating: False
    Stack trace:    at  [stack trace here]


---------------
[footer message here]

Specifying the Logging Requirements

While it is easy to be overwhelmed by the Health Monitoring classes and their myriad interactions, we're going to pick our way through the apparent complexity by focusing on creating a useful, robust, and extensible logging facility. To do so, let's delineate our requirements.

To begin, an event is defined as an error, exception, unexpected outcome, or notable occurrence that we want to keep track of. (Later, not shown in this article, we might differentiate two or more types of events--e.g., audit events and errors.)

Our logging module must:

Creating the Test Bed

To demonstrate how you can implement logging that stores the required information both in a database and, optionally, send email for critical errors, you'll need a program that can generate exceptions, errors, and so forth. We'd like our sample application to be simple (so that we can focus on the logging) but at least marginally realistic.

Create a new ASP.NET application and call it Logging. Click on Website-->ASP.NET Configuration to open the Web Site Administration Tool, and click on Security to set up Forms-based security (from the Internet). Create a single user.

Close the tool and ensure that your web.config file has the following lines (if not, add them by hand):

<authentication mode="Forms" />
<membership>
   <providers>
      <remove name="AspNetSqlMembershipProvider"/>
      <add name="AspNetSqlMembershipProvider" 
         type="System.Web.Security.SqlMembershipProvider, 
         System.Web, Version=2.0.0.0,             
         Culture=neutral,
         PublicKeyToken=b03f5f7f11d50a3a" 
         connectionStringName="LocalSqlServer" 
         applicationName="/" 
         requiresUniqueEmail="false" 
         passwordFormat="Hashed" 
         maxInvalidPasswordAttempts="10" 
         minRequiredPasswordLength="1"
         minRequiredNonalphanumericCharacters="0" 
         passwordAttemptWindow="10" 
         passwordStrengthRegularExpression=""/>
   </providers>
</membership>

Double-check that the name of the connection string listed is LocalSqlServer and that inside your App_Data folder a file has been created named ASPNETDB.MDF. You should be able to examine the tables for this database using the Server Explorer window, as shown in Figure 2.

Personalization tables
Figure 2. Examining the Personalization Tables

To keep the example simple, maintain the name Default.aspx. You'll create a GridView that is bound to the Person.Contact table in the sample AdventureWorks database that ships with SQL Server 2005 (or you can download it from Microsoft). The only extras are that you'll allow the user to put in the starting letters of the user's last name to narrow the results, and you'll add a button that will force an exception, as shown in Figure 3.

The Grid
Figure 3. The Grid you'll build

To create this grid, follow these relatively easy steps:

  1. Drag a GridView control onto your .aspx page and name it ContactGridView.
  2. Use the smart tag to create a new DataSource. Point the data source to your AdventureWorks database, saving the connection string, and use the following SQL statements for Select, Update, Insert, and Delete:
SELECT [ContactID], [FirstName], [LastName], [EmailAddress], [Phone] FROM [Person].[Contact] where LastName LIKE @LastName + '%' order by LastName 
UPDATE [Person].[Contact] SET [FirstName] = @FirstName, [LastName] = @LastName, [EmailAddress] = @EmailAddress, [Phone] = @Phone WHERE [ContactID] = @ContactID
UPDATE [Person].[Contact] SET [FirstName] = @FirstName, [LastName] = @LastName, [EmailAddress] = @EmailAddress, [Phone] = @Phone WHERE [ContactID] = @ContactID
INSERT INTO [Person].[Contact] ([FirstName], [LastName], [EmailAddress], [Phone]) VALUES (@FirstName, @LastName, @EmailAddress, @Phone)
DELETE FROM [Person].[Contact] WHERE [ContactID] = @ContactID

The square brackets in these SQL statements are not strictly necessary, but they are used to avoid problems with spaces within object names.

The fastest way to get this right is to let the control create the statements for you. This will let you use the tool to create the WHERE clause (using the text box as the source for the parameter) and to generate the Insert, Update, and Delete statements.

You will then need to edit each statement to prepend each table name with the schema names used in this latest version of the AdventureWorks database (e.g., [Person].[Contact]). You'll also need to edit the Select statement to change the WHERE clause to use the LIKE statement (which lets you use the wild card character %).

Below the grid, add the Label, TextBox, and two Buttons, using this markup:

<asp:Label ID="LastNamePrompt" runat="server" Text="Last name starts with: " />
<asp:TextBox ID="LastName" runat="server" Width="96px" />
<asp:Button ID="Search" runat="server" Text="Search" />
<asp:Button ID="ThrowException" runat="server" OnClick="ThrowException_Click" Text="Divide by zero" />

Run the program and make sure that you can retrieve and edit data from the appropriate table. Great.

Error Handling

There are many things that can go wrong with even such a simple program, but let's identify two obvious potential issues: when editing, the row might not be updated or an exception might be thrown.

You would like to log either of these events. Accomplishing this requires three steps:

  1. Catching the error or exception and creating a message to be logged
  2. Setting up the logging infrastructure in web.config
  3. Writing a custom web event to manage your error handling

web.config

The confusion, for most programmers, comes when they set up web.config. This is due in large measure to the fact that (a) the syntax is declarative, and (b) there are many options that don't have to be dealt with initially but they're not intuitive, and (c) everything depends on everything else so it is difficult to create a simple starting point.

We'll solve that by taking things one step at a time.

We begin by making sure that the web.config file already has the necessary elements in it that are not part of health monitoring--specifically, the membership connection string (so that we can log to the membership database) and the mail settings (so we can send email). Note that you don't need either of these. You could log to a file or a different database, in which case you'd just need to make sure you had the right connection string for your chosen database connection. And, nothing says you have to send email.

We've already seen the membership entry required to log to the membership table. The mail settings for smtp specify the mail host and (in my case) my login name and password:

<system.net>
    <mailSettings>
       <smtp from="jliberty@jliberty.com">
          <network host="mail.speakeasy.net" 
            password="????" userName="?????@????.com"/>
       </smtp>
    </mailSettings>
 </system.net>

With that in place, we are ready to set up the health monitoring section, which will handle our logging. Here is what you need to know (though there is much more to know when you move beyond the basics).

First, the entire health monitoring section is placed within the <system.web> element, along with the authentication, membership, compilation, and custom errors elements.

The two attributes that I add are enabled="true" and heartbeatInterval="0".

Zero indicates that the heartbeat check should be turned off, which is what we want (and which is the default).

The healthMonitoring element has four subelements that we care about: <bufferModes>, <providers>, <eventMappings>, and <rules>. These four combine to tell the system what you want to log, where you want to log to, and how you want to buffer the logging (so as not to slow down your system).

Creating a Custom Web Event

In our case, we want to log our own custom log events, so we will create a new class that will derive from one of the existing Web Events--specifically, WebBaseErrorEvent. This is a very convenient event to derive from, because it does a lot of the work of handling errors (and errors that have exceptions) for us. Our first step is to create a new class (which will be housed under App_Code. I'll place that code in the file Logging.cs, and name the class LoggingErrorEvent (though of course, you may choose whatever name you like).

My new class must have a constructor, and because I want to be able to send additional information I'll override the FormatCustomEventDetails method, which lets me send any text I like to the details part of the logged error.

The constructor for my class must pass four parameters to its base class:

My LoggingErrorEvent class will create an enumeration for my own "loggingEventCodes." The Microsoft literature suggests that when you generate a code at the source of the problem you add WebEventCodes.WebExtendedBase to your code so as not to step on existing codes. I can't see making every class know about that, so I've put that into my enumeration as follows:

public enum loggingEventCode
{
   Exception = WebEventCodes.WebExtendedBase + 1,
   ProgramError,
   PotentialDataCorruption,
   Information,
};

The class itself holds on to the page that is passed in as the source and the exception that is passed in (if any) for use in the FormatCustomEventDetails method. Otherwise the constructor does nothing except translate the loggingEventCode back to an integer and pass its parameters to the base class.

public class LoggingErrorEvent : WebBaseErrorEvent
{
   private Exception exception;
   private Page page;

   public LoggingErrorEvent(
      string message,
      object source,
      loggingEventCode code,
      Exception ex
      ):
      base ( message, source, Convert.ToInt32(code), ex)
    {
      page = source as Page;
      exception = ex;
    }

Finally, my override of FormatCustomEventDetails checks to see whether I have an exception object and if I have a page, and sends along details about both if available (nothing fancy here).

public override void FormatCustomEventDetails( WebEventFormatter formatter )
{
   base.FormatCustomEventDetails( formatter );
   if ( exception != null )
   {
      if ( page != null)
      {
         formatter.AppendLine(page.ToString());
      }
      formatter.AppendLine(exception.Message);
      formatter.AppendLine(exception.Source);
      formatter.AppendLine("Exception stack trace...");
      formatter.AppendLine(exception.StackTrace);
   }
}

Event Mappings

web.config does not know about LoggingErrorEvents but it does know about WebBaseErrorEvents so the section can create a name for events of that type:

<healthMonitoring enabled="true" heartbeatInterval="0">
<eventMappings>
    <add name="All LoggingErrors" type="System.Web.Management.WebBaseErrorEvent" />
 </eventMappings>

Of course, you can have multiple mappings so that you could map errors to one name, exceptions to another, progress events to a third, and so forth.

Providers and Rules

With the name of our error event in place, next we need to tell web.config where to map each event type (in our case, we only have one type). This is done with two elements: <rules> and <providers>. A rule says "when you see this event name, use this provider." Each rule consists of three parts:

The name of the rule can be anything you like.

The name of the event will match the name you created in the <eventMappings> section.

The name of the provider will match the name you will create in the <providers> section.

You can create the rules before the providers or the providers before the rules; it is entirely up to you. I suspect most folks create the providers first. That way, the rules just match up events with providers. Let's do that.

Providers

The providers section has an element for each place you might send logging information (e.g., a database table, email, a file, etc.). Different providers need different information; email needs a To and From field, a database table does not. Here is my providers element for both email and for storing to the SQL table provided by the security table we looked at earlier:

<providers>
   <add name="MailEventProvider"
      type="System.Web.Management.SimpleMailWebEventProvider"
      from="jliberty@jliberty.com"
      to="jliberty@jliberty.com"
      bodyHeader="Logging Example Warning!"
      bodyFooter="Please investigate ASAP."
      subjectPrefix="Logging Error Notification: "
      buffer="true"
      bufferMode="Critical Notification" 
      maxEventLength="4096"
      maxMessagesPerNotification="1"/>
   
   <add name="SQLEventLog"
        type="System.Web.Management.SqlWebEventProvider"
        connectionStringName="LocalSqlServer"
        bufferMode="Logging Notification"
      />
</providers>

Notice that each provider has its own name (you may call each anything you like). In my case, I have named them MailEventProvider and SQLEvenLog, respectively. Nothing like consistency, and that was nothing like consistent.

Let's take the second one first. The SqlWebEventProvider has four attributes: its name, its type, the connectionStringName to indicate which database to connect to, and the name of the buffer mode. That last is defined in an element you haven't seen yet. Buffer modes are elements you define to tell the system how much you want to buffer the logging messages, trading off performance for the risk of losing a logging message should the system crash. We'll return to buffering shortly.

The first Provider is for email and contains more information. In addition to its type, it has fields for the From field, the To field (and you can add cc, etc.). It has a body header, footer, subject prefix, and so forth. You can indicate if it is to be buffered and, if so, which mode to use. Finally, you can indicate the maximum length and the maximum number of messages that should be put in a single notification.

I should also mention that I'm using the SimpleMailWebEventProvider. There is a second option--which I won't show here to keep things simple--that uses templates to create HTML email messages.

Rules

With the providers in place, we are ready to create the rules. As mentioned above, a rule has a name, and then it matches up an event with a provider. We want to match the All LoggingErrors with the MailEventProvider, and we want to match up that same event with the SqlEventLog, so we create two rules, each with its own name:

<rules>
   <add name="Email Error Notification" eventName="All LoggingErrors" 
      provider="MailEventProvider" />
   <add name="DB Logging" eventName="All LoggingErrors" provider="SQLEventLog" />
</rules>

Once again, you can imagine having many rules, allowing you to match some events with a subset of your providers, and other events with either a disparate or an overlapping subset of providers. But keeping things simple has its merits as well.

Buffering

The final piece that we've not yet looked at is buffering. It is just fine to have your messages go out or be logged instantly, but if you are creating audit messages that audit just about everything your system does, and if you have a lot of traffic, that can slow the system down noticeably. One mechanism for dealing with this drain on the system is to buffer the messages until either a given number accumulates, or a given period of time elapses.

As you can imagine, you may want to set different buffers for different providers, depending on how critical the events they handle are. Thus, you can create a bufferModes element and within that, any number of named BufferModes.

<bufferModes>
   <add name="Logging Critical Notification" 
      maxBufferSize="100" 
      maxFlushSize="20" 
      urgentFlushThreshold="1" 
      regularFlushInterval="Infinite" 
      urgentFlushInterval="00:01:00" 
      maxBufferThreads="1"/>
  
   <add name="Logging Notification"
      maxBufferSize="500" 
      maxFlushSize="50" 
      urgentFlushThreshold="5" 
      regularFlushInterval="Infinite" 
      urgentFlushInterval="00:02:00" 
      maxBufferThreads="1"/>
        
</bufferModes>

Here, I've created two buffer Mode objects, one named Logging Critical Notification, and one named Logging Notification. The former is for more critical messages, and so flushes after one minute. The urgentFlushThreshold is set to 1, indicating that just one event will flush the buffer and setting the urgentFlushInterval to 1, allowing a flush of the buffer after just one minute (you can find all the fields explained in detail in the documentation under BufferMode).

I've defined a second, less urgent bufferMode, Logging Notification, that will flush after five messages or two minutes and can be used for less critical notifications. Each of these can be assigned to a provider. As we saw earlier, the former is assigned to the MailEventProvider, and the latter to the SqlEventLog provider.

Testing

The easiest way to test the logging is to press the Divide By Zero button, whose event handler looks like this:

protected void ThrowException_Click
   ( object sender, EventArgs e )
{
   int x = 16;
   int y = 12;
   int z = 6;
   y = y - z;
   y -= z;
   try
   {
      int q =  x / y;  // divide by zero!
   }
   catch ( Exception ex )
   {
      LoggingErrorEvent le = new LoggingErrorEvent(
         "Exception raised in Default.aspx.cs", 
              this, loggingEventCode.Exception, ex );
      le.Raise();
   }

}

The key here is to catch the exception, create an instance of our custom event, send in the simple message (Exception raised in Default.aspx.cs), the page, the code enumeration (loggingEventCode.Exception), and the exception. The result is an entry in the database:

e902262e82da402c807196732632fa0f    2/28/2007 4:37:40 PM    2/28/2007 11:37:40 AM    LoggingErrorEvent    4    1    100001    0    
Exception raised in Default.aspx.cs    D:…\Logging\    /Logging    BERNSTEIN    NULL    System.DivideByZeroException    Event code: 100001
Event message: Exception raised in Default.aspx.cs
Event time: 2/28/2007 11:37:40 AM
Event time (UTC): 2/28/2007 4:37:40 PM
Event ID: e902262e82da402c807196732632fa0f
Event sequence: 4
Event occurrence: 1
Event detail code: 0
Application information:
    Application domain: 3df6b61b-14-128171542553125000
    Trust level: Full
    Application Virtual Path: /Logging
    Application Path: D:\...\Logging\
    Machine name: BERNSTEIN

Process information:
    Process ID: 6756
    Process name: WebDev.WebServer.EXE
    Account name: BERNSTEIN\Jesse

Exception information:
    Exception type: System.DivideByZeroException
    Exception message: Attempted to divide by zero.

Custom event details: 
    ASP.default_aspx
    Attempted to divide by zero.
    App_Web_-gksxlwk
    Exception stack trace...
       at _Default.Button1_Click(Object sender, EventArgs e) in d:\...\Logging\Default.aspx.cs:line 79

and an email:

Logging Example Warning!
** Summary **
---------------
This message contains events 1 to 1 from the total of 1 events scheduled for this notification.  There were 0 events left in the buffer at the beginning of this notification.


** Application Information **
---------------
Application domain: 3df6b61b-14-128171542553125000 Trust level: Full Application Virtual Path: /Logging Application Path: D:\...\Logging\ Machine name: BERNSTEIN


** Events **
---------------
Event code: 100001
Event message: Exception raised in Default.aspx.cs Event time: 2/28/2007 11:37:40 AM Event time (UTC): 2/28/2007 4:37:40 PM Event ID: e902262e82da402c807196732632fa0f Event sequence: 4 Event occurrence: 1 Event detail code: 0

Process information:
    Process ID: 6756
    Process name: WebDev.WebServer.EXE
    Account name: BERNSTEIN\Jesse

Exception information:
    Exception type: System.DivideByZeroException
    Exception message: Attempted to divide by zero.

Custom event details: 
    ASP.default_aspx
    Attempted to divide by zero.
    App_Web_-gksxlwk
    Exception stack trace...
       at _Default.Button1_Click(Object sender, EventArgs e) in d:\...\Logging\Default.aspx.cs:line 79

---------------
Please investigate ASAP.

Jesse Liberty is a senior program manager for Microsoft Silverlight where he is responsible for the creation of tutorials, videos and other content to facilitate the learning and use of Silverlight. Jesse is well known in the industry in part because of his many bestselling books, including O'Reilly Media's Programming .NET 3.5, Programming C# 3.0, Learning ASP.NET with AJAX and the soon to be published Programming Silverlight.


Return to the Windows Dev Center.

Copyright © 2009 O'Reilly Media, Inc.