This, and the next few postings, cover the .NET Framework’s Trace capabilities and explain why you don’t need any third party tools to understand what your code is doing. In particular this posting discusses the Trace framework fundamentals, its features and how to get started.

Background

Microsoft introduced a tracing/diagnostics framework into the first version of .NET through System.Diagnostics.Trace. The Trace framework allowed you to write messages or data to a series of Listeners; Listeners were provided in the .NET Framework and could also be constructed to write to the Event Log, databases, email, files, etc.

This initial Trace framework was pretty light and, as many people adopting .NET were coming from a Java background, this framework wasn’t really deemed powerful enough compared to several of the existing Java frameworks. Several new external frameworks started to appear, Java based frameworks such a log4net and nlog, and the .NET based Enterprise Library Logging Application Block. These frameworks were all very powerful and also tended to be quite complicated to use.

For reference, developers become very passionate about logging and their chosen framework, and as people move around jobs and even departments within the same company, hostility can be encountered!

Revamp

Structurally, the initial version of the Trace framework was pretty sound. In code you could Trace some information. The Trace framework received this information and ran it through a series of configurable Listeners with each one being given the information to record. A single event could be recorded in multiple Listeners simultaneously; in the Event Log, a file and an email for example. This is unchanged.

In the .NET 2.0 release .NET’s Trace framework was revamped to effectively provide most of the functionality you would ever need from a Tracing tool, taking into account the competitor functionality. SourceTypes, Trace Switches and Trace Filters were added as was the ability to track events across process and machine boundaries.

However, there was no song and dance from Microsoft and it was an extension to the existing Trace and .NET framework so no new namespaces or assemblies. The changes went pretty much unnoticed and developers continued to use third party tools.

What’s Nice About Trace

There are obviously powerful new features in the new Trace framework, but there are also a few things that just make the new Trace nice to use compared to third party tools:

There are no extra build, deployment or coding steps required to use Trace as the code is included in the .NET framework. In fact, most projects already reference the correct assembly so simply add a reference to System.Diagnostics and you are away.

The Trace framework can work with third party logging frameworks that support listening for Trace events! So, if you still want to use the appenders or formatters supplied by log4net, for example, then you can, but your code doesn’t need to be littered with log4net references; it is almost impossible to remove a logging provider once it has been added to a codebase!

It really is easy to use. There are a few, simple configuration steps but after that, the code is really easy.

If you are using WCF, it integrates really nicely for propagation of calls through WCF process and machine boundaries.

Finally, one of the most powerful features of the Trace framework is that it is built into the .NET codebase and passes context around behind the scenes. This means it really is possible to follow calls through an entire application, across processes and even across machine boundaries.

What and When and to Trace?

To make it simpler, the question should almost be reversed and be What and When Not to Trace! The more information you Trace the easier it is to understand what is going on in your code and diagnose and resolve any issues. That said, there is a performance hit with continually feeding information to the Trace Listeners but that is where Trace Switches and Filters prove invaluable.

From a development point of view, being able to run your application and make sure variables are being set correctly, files are being loaded from the correct locations and each individual step in a workflow has been called are all crucial. Normally, developers do this through debugging but Tracing is equally valid and valuable especially for retrospective analysis. However, having the ability to ignore these Traces, or simply not generate them in a production environment is also essential to prevent performance problems or producing so many records that it is impossible to see any issues.

From a production point of view, being able to quickly identify and diagnose exceptions or errors is also crucial. The Tracing framework should record every error that occurs, and ideally alert somebody to the issues. Similarly, some issues can be prevented by watching for thresholds being breeched or timeouts occurring.

TraceEventType and Trace Switches

To cater for the requirements above, the Trace framework supports different types of events and levels of severity that can be switched on or off through the TraceEventType enumeration. The current list of TraceEventType severity levels includes:

• Critical – records something that was unexpected and means the application is in an undetermined state or cannot continue
• Error – records something that was unexpected or failed but the application can continue to operate, such as a credit card payment failed
• Information – records general information such as a successful logon, a successful overnight process
• Verbose – typically used by developers when debugging and includes information such as a list of parameters that have been gathered, or a file path that is to be used
• Warning – records information that may become a problem such as a memory threshold has been breached or the amount of free disk space is getting low; the application can continue but may need looking at

The following shows an example of how some normal code could be instrumented, using several different levels. In this case:

Line 4 shows a developer message saying that we are about to store some data to the database

Line 9 is a developer message that says we have successfully saved the data to the database

Line 13 is an error message because an exception was thrown when saving the data. In this case, we could retry or compensate but the application can continue

Line 18 is a critical error from which the application cannot continue.

public void StoreData(object data)
{
  TraceSource traceSource = new TraceSource("DemoApp");
  traceSource.TraceEvent(TraceEventType.Verbose, 0, "About to store the passed in data");

  try
  {
    // Store the data in the database
    traceSource.TraceEvent(TraceEventType.Verbose, 0, "Data saved successfully");
  }
  catch (SqlException ex)
  {
    traceSource.TraceEvent(TraceEventType.Error, 1, "An error occurred contacting the database '{0}'", ex);
    throw;
  }
  catch (OutOfMemoryException ex)
  {
    traceSource.TraceEvent(TraceEventType.Critical, 2, "The application has run out of memory '{0}'", ex);
    throw;
  }
}

The Trace framework can be configured through Trace Switches so that the levels at which events are raised can have different outcomes. For example, it is possible to do nothing with Verbose events and just ignore them, write Warnings and Errors to the Event Log and send emails to support staff for Critical events. When the code is written, the developer should understand the different levels above and choose the most appropriate one as above. Then, configuration can be used to adjust the outcomes without changing the code.

The following shows a simple configuration where all trace information is dumped to the Console through a single Trace Switch.

Line 4 then shows a TraceSource being configured. We will talk about TraceSources in a moment but effectively this section says the any messages whose level is Verbose or above (effectively all levels) should be written to the following listeners – the console listener is then added.

Line 11 shows where the listeners are configured. In this case, there is only one listener which is the console.

The <trace autoflush=”true”/> ensures trace information is written immediately as opposed to when the application is closed.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener" />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Running the application with this configuration produces the following output for normal flow, i.e. no exceptions:

DemoApp Verbose: 0 : About to store the passed in data
DemoApp Verbose: 0 : Data saved successfully

If we wanted to prevent the developer information from being recorded, we could simply change the switchValue to Information. This would mean only Information messages or above are sent to the Trace Listeners and recorded. In the example code above, no output would now be generated unless an exception was thrown.

We can also add different listeners for different levels. The following example configuration shows that Information messages or above are displayed in the Console and Errors or above are added to the EventLog.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Information">
        <listeners>
          <add name="console"/>
        </listeners>
      </source>
      <source name="DemoApp" switchValue="Error">
        <listeners>
          <add name="console"/>
          <add name="eventlog"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener" />
      <add name="eventlog"
        type="System.Diagnostics.EventLogTraceListener"
        initializeData="DemoAppEventLog" />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

If we ran the code above and there was an error contacting the database, the following would be seen in the console:

DemoApp Error: 1 : An error occurred contacting the database 'An Exception ...'

The following would also be seen in the EventLog:

Trace Filters

Trace Filters have the same effect as Trace Switches in determining which Listeners record information. However, Trace Switches determine which listeners receive the event to be traced whereas Trace Filters are applied to the listener themselves and enable the listener to determine if it should Trace. This may seem very similar but it does make for simpler configuration.

If we take the above configuration and change it around slightly to use filters we can end up with exactly the same results. In this configuration, all messages (the Verbose Trace Switch is being used) are sent to the console and eventlog listeners but the console listener only records Information events or above and the eventlog only records Error events or above.

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
          <add name="eventlog"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add
        type="System.Diagnostics.ConsoleTraceListener"
        name="console">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Information"/>
      </add>
      <add name="eventlog"
        type="System.Diagnostics.EventLogTraceListener"
        initializeData="DemoAppEventLog">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Error"/>
      </add>
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Trace Filters prove invaluable in some scenarios such as when numerous Trace Sources are configured. It becomes trivial to have one Trace Listener handle all errors produced by all Trace Sources.

Trace Sources

The initial version of the Trace framework used simple Write calls to log information. The new version uses a Trace Source instead. To ensure you are using the latest version of the Trace framework:

Do not use Write, use the TraceSource class!

A Trace Source is really a way of being able to group code and to manage the Trace levels associated with it; the Trace Switches and Filters. In the examples above, we have been using a Trace Source called “DemoApp”. The code traces events against the “DemoApp” Trace Source and the configuration specifies a switchValue and one or more listeners. This means that all code that traces against the “DemoApp” TraceSource class instance will be subject to the same switchValue, filters and listeners.

Normally the TraceSource name is the same as the assembly. For example, a database access assembly may be required to trace all errors to the Event Log whereas the UI assembly may only trace critical events to a file. We can configure the two assemblies differently if they use different Trace Source names. Microsoft follows this rule. If you wanted to trace low level information from the Microsoft networking layer, you could add the following to your configuration file and see all levels of message recorded in the XmlWriterTraceListener:

<system.diagnostics>
  <sources>
    <source name="System.Net" maxdatasize="1024">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
    <source name="System.Net.Sockets">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
    <source name="System.Net.Cache">
      <listeners>
        <add name="xml" />
      </listeners>
    </source>
  </sources>
  <switches>
    <add name="System.Net" value="Verbose"/>
    <add name="System.Net.Sockets" value="Verbose"/>
    <add name="System.Net.Cache" value="Verbose"/>
  </switches>
  <sharedListeners>
    <add initializeData="C:\logs\web.svclog"
      type="System.Diagnostics.XmlWriterTraceListener"
      name="xml" />
  </sharedListeners>
  <trace autoflush="true">
  </trace>
</system.diagnostics>

In Conclusion

Hopefully, this posting has given you a good background in why the System.Diagnostics.Trace framework should be the only trace framework you need, given you some idea of how to get started, configure the output levels, switches and filters and use the Trace code.

The following postings will look at:

More detailed configuration and usage of the framework

How to propagate and gather information across process and machine boundaries

How to pass ActivityIds to ASP.NET/MVC applications for end-to-end tracing in REST

A couple of helper classes that will prove useful when using the Trace framework

P.N.