.NET Trace, The Only Logging Framework You’ll Ever Need – Part 2

In the previous posting we introduced the new .NET (2.0+) Trace framework and talked about the features that make it a comprehensive Tracing tool.

This posting builds on that information to look at more advanced usage and configuration. You should read the previous posting before embarking on this one.

Configuration Revisited

The code used to Trace is very simple: TraceEvent Traces the information you pass to it; TraceData simply calls ToString on the objects that are passed to it and then calls TraceEvent. It really is that simple!

There are, however, more advanced options for enhancing the Trace output through configuration.

TraceOutputOptions

TraceOutputOptions are used to Trace additional information in the Listeners (some Listeners such as the EventLogTraceListener don’t honour all of these options due to the potential size of the event). There are 6 options for the additional information that can be traced (again, available on MSDN):

  • Callstack – Write the call stack, which is represented by the return value of the Environment.StackTrace property.
  • DateTime – Write the date and time.
  • LogicalOperationStack – Write the logical operation stack, which is represented by the return value of the CorrelationManager.LogicalOperationStack property.
  • ProcessId – Write the process identity, which is represented by the return value of the Process.Id property.
  • ThreadId – Write the thread identity, which is represented by the return value of the Thread.ManagedThreadId property for the current thread.
  • Timestamp – Write the timestamp, which is represented by the return value of the GetTimeStamp() method.

These options are added to the Trace output through the traceOutputOptions attribute of the Listener, as shown below. In this case, the Console will display an additional Timestamp and the XmlWriterTraceListener, which is called only when an error occurs, will also Trace the LogicalOperationStack  and Callstack:

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <add name="console"/>
          <add name="xml"/>
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="console"
        type="System.Diagnostics.ConsoleTraceListener"
        traceOutputOptions="Timestamp">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Information"/>
      </add>
      <add name="xml"
        type="System.Diagnostics.XmlWriterTraceListener"
        initializeData="C:\logs\DemoApp.svclog"
        traceOutputOptions="LogicalOperationStack,Callstack">
        <filter
          type="System.Diagnostics.EventTypeFilter"
          initializeData="Error"/>
      </add>
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

If we run an application with this configuration, and execute the following line of code:

TraceSource traceSource = new TraceSource("DemoApp");
traceSource.TraceEvent(TraceEventType.Error, 1, "An error occurred contacting the database 'An Exception ...'");

The following is seen in the Console window, with the additional Timestamp being displayed:

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

We are going to look at the XmlWriterTraceListener in more detail below but the following shows the XML that is generated with the ApplicationData element containing the LogicalOperationStack and Callstack elements

<E2ETraceEvent xmlns="<a href="http://schemas.microsoft.com/2004/06/E2ETraceEvent">http://schemas.microsoft.com/2004/06/E2ETraceEvent</a>">
  <System xmlns="<a href="http://schemas.microsoft.com/2004/06/windows/eventlog/system">http://schemas.microsoft.com/2004/06/windows/eventlog/system</a>">
    <EventID>1</EventID>
    <Type>3</Type>
    <SubType Name="Error">0</SubType>
    <Level>2</Level>
    <TimeCreated SystemTime="2012-09-11T15:22:37.3469888Z" />
    <Source Name="DemoApp" />
    <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
    <Execution ProcessName="DemoApp.vshost" ProcessID="13232" ThreadID="9" />
    <Channel/>
    <Computer>ICEBLUE</Computer>
  </System>
  <ApplicationData>
    An error occurred contacting the database &apos;An Exception ...&apos;<System.Diagnostics xmlns="<a href="http://schemas.microsoft.com/2004/08/System.Diagnostics">http://schemas.microsoft.com/2004/08/System.Diagnostics</a>">
      <LogicalOperationStack></LogicalOperationStack>
      <Timestamp>1135474177573</Timestamp>
      <Callstack>   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at System.Diagnostics.XmlWriterTraceListener.WriteFooter(TraceEventCache eventCache)
at System.Diagnostics.XmlWriterTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String message)
at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message)
at ConsoleApplication3.Program.StoreData(Object data) in C:\_RS\ConsoleApplication3\ConsoleApplication3\Program.cs:line 46
at ConsoleApplication3.Program.Main(String[] args) in C:\_RS\ConsoleApplication3\ConsoleApplication3\Program.cs:line 15
at System.AppDomain._nExecuteAssembly(RuntimeAssembly assembly, String[] args)
at System.AppDomain.ExecuteAssembly(String assemblyFile, Evidence assemblySecurity, String[] args)
at Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly()
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean ignoreSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()</Callstack>
    </System.Diagnostics>
  </ApplicationData>
</E2ETraceEvent>

Trace Listeners

There are also several additional Listeners that can be configured to run in the Trace framework. In the previous posting we looked at two Trace Listeners that record information in the Console and Event Log. We discussed how these Listeners can be run concurrently so that the same Trace can be output to multiple Listeners simultaneously. We looked at how we can control which Listeners record information for different severity levels. Once the code has been instrumented with Trace calls, we have complete control over where the Trace events are recorded through configuring the Listeners.

There are several other trace listeners provided by the .NET Framework out of the box. These additional Listeners include (this is taken directly from MSDN):

  • A TextWriterTraceListener redirects output to an instance of the TextWriter class or to anything that is a Stream class. It can also write to the console or to a file, because these are Stream classes.
  • A FileLogTraceListener provides a simple listener that directs logging output to file.
  • An EventLogTraceListener redirects output to an event log.
  • An EventProviderTraceListener redirects output to the Event Tracing for Windows (ETW) framework. Click for more information on ETW Tracing.
  • A DefaultTraceListener emits Write and WriteLine messages to the OutputDebugString and to the Debugger.Log method. In Visual Studio, this causes the debugging messages to appear in the Output window. Fail and failed Assert messages also emit to the OutputDebugString Windows API and the Debugger.Log method, and also cause a message box to be displayed. This behavior is the default behavior for Debug and Trace messages, because DefaultTraceListener is automatically included in every Listeners collection and is the only listener automatically included.
  • A ConsoleTraceListener directs tracing or debugging output to either the standard output or the standard error stream.
  • A DelimitedListTraceListener directs tracing or debugging output to a text writer, such as a stream writer, or to a stream, such as a file stream. The trace output is in a delimited text format that uses the delimiter specified by the Delimiter property.
  • The IisTraceListener routes all tracing and debugging output to the IIS 7.0 infrastructure.
  • A WebPageTraceListener directs Trace messages to ASP.NET Web page outputs.
  • An XmlWriterTraceListener directs tracing or debugging output as XML-encoded data to a TextWriter or to a Stream, such as a FileStream.

In addition to the Listeners above, there are community projects that provide extensions and additional Listeners. An example of such community work includes:

http://msdn.microsoft.com/en-us/library/ee779630

http://essentialdiagnostics.codeplex.com/

The DefaultTraceListener is automatically added to the Listeners collection when application starts. If you make no configuration changes and simply Trace some events, they will appear in the Visual Studio Output window through this DefaultTraceListener. It is, however, possible to remove the DefaultTraceListener from the collection using the following configuration:

<configuration>
  <system.diagnostics>
    <sources>
      <source name="DemoApp" switchValue="Verbose">
        <listeners>
          <clear/>
        </listeners>
      </source>
    </sources>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

The Listeners for the Trace framework are pluggable so you can also write your own. This is out of the scope of this posting but in essence you need to create a new class that derives from TraceListener and use the configuration to include this new Listener.

XmlWriterTraceListener

The XmlWriterTraceListener is perhaps one of the most powerful out-of-the-box Trace Listeners available in the .NET Framework. It writes Trace events into a configurable file in an XML format but more importantly there is a supporting client application called the Microsoft Service Trace Viewer which was actually introduced with WCF.

If we open the previous XML output from the C:\logs\DemoApp.svclog file generated above, in the Service Trace Viewer, we see the following detailed breakdown. Our Error message is highlighted in red and the details of the event are decomposed into discrete sections in the UI.

In Conclusion

In this posting we have looked at some of the advanced configuration techniques and Trace Listeners provided by the .NET Trace framework and the different TraceListeners provided out-of-the-box. We have also looked at how we can use the XmlWriterTraceListener and the Microsoft Service Trace Viewer to view detailed Trace events.

In the following postings we will look at:

How we can instrument our code to propagate information across process and machine boundaries and use the XmlWriterTraceListener and the Microsoft Service Trace Viewer to view end-to-end activity

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.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s