Trace Context Aspects with PostSharp

In my previous post I wrote about a method context information gathering framework I wrote in an attempt to increase the amount of useful information in trace output and exceptions. In this final post about the framework I will discuss the use of a static aspect weaver PostSharp.

Static Aspect Weaving

I assume that you know what aspects are at least at a conceptual level. The nice thing about static aspects is that their code is injected at compile time, not at runtime. True: static aspects are not configurable, but they are completely transparent (dynamic aspects usually require the client code to create a proxy instead of the actual object).

I use PostSharp, a static aspect weaver, to implement a code attribute that triggers aspect code injection into the assembly. PostSharp works at IL level so it should be usable with any .NET language. While PostSharp provides a generic assembly manipulation framework, it is actually Laos that provides the aspect framework.

When an aspect (a code attribute) is applied to a method, PostSharp (actually Laos) rewrites the IL for that method. It basically relocates the original method IL in a new method with the same name, prefixed by a ‘~’. Then it inserts custom IL that performs the call sequence on your aspect object. Your aspect can be responsible for calling the actual method -using a delegate- (as it is in this example), although there are also flavors of aspects that do not require this.

So a typical (simplified) call stack would look something like this:

void MyClass.MyMethod(string param1)
void MyAspect.OnInvocation(MethodInvocationEventArgs eventArgs)
void delegate.DynamicInvoke(object[] parameters)

void MyClass.~MyMethod(string param1)

The stubbed MyClass.MyMethod routes execution to the aspect (OnInvocation) applied to the method and the aspect code invokes the delegate that point to the original method (or it doesn’t 😉 and the original method (prefixed with ~) executes.

TraceContextAspect

In order to eliminate the custom code you’d have to write to use the TraceContext in our method context information gathering framework, I’ve created a PostSharp/Laos aspect class that intercepts the method call as described above. So instead of making all the calls to the TraceContext yourself in the method code, you simply apply the aspect to the method:

[TraceContextAspect]
public string PrintName(int numberOfTimes)
{
    // method impl.
}

The TraceContextAspect implements the OnInvocation method like so:

using (AspectTraceContext ctx = new AspectTraceContext(_methodBase))
{
    ctx.Initialize(eventArgs.Delegate.Target);
    AddParameters(ctx, eventArgs.GetArguments());
    ctx.TraceMethodEntry();

    try
    {
        eventArgs.ReturnValue = eventArgs.Delegate.DynamicInvoke(eventArgs.GetArguments());

        ctx.SetReturnValue(eventArgs.ReturnValue);
    }
    catch (Exception e)
    {
        ctx.AddContextTo(e);
        throw;
    }
} // maintains stack and writes method exit and flushes writer.

Note that I’ve derived a new class from TraceContext for this specific situation (AspectTraceContext) that takes a MethodBase instance as a parameter in its constructor. The MethodBase instance is handed to you by the PostSharp/Laos framework and represent the method the aspect was placed on. The bold text is the actual call to the original method. As you can see, all the custom code needed to setup the TraceContext has now moved to the OnInvocation method implementation.

Conclusion

The use of a static aspect weaver has dramatically simplified the usage of the method context information gathering framework. Tracing useful and rich information from your method has now become a breeze (as it should be ;-).

I hope these last 3 post has shown you how you can leverage existing technology (System.Diagnostics and PostSharp) to make the most out your own tracing framework (in this case). I also hope you will be inspired to find new applications to use static aspects in your own code. I find that static aspects can really make your life easier while at the same time not making your code (execution paths) more complicated than needed.

You can download the source code here.

A Method Context Information Gathering Framework

Do you also have that feeling when you type in your tracing code that it is too cumbersome and too much hassle to get it right? I mean really trace the information that is useful for finding faults, for instance. And when you log an exception, even when you write out all the information the exception offers, it is barely enough to really understand what went wrong?


That is why I wrote this framework. This framework tries to solve one major problem (and some small one on the side): Getting the runtime information of an executing method into a trace text or an exception.

Note that this post assumes you know about the main classes in System.Diagnostics.


MethodContext


The MethodContext is a class that maintains all running values during the execution of a method. It is created at the beginning of the method and it is Disposed at the end of the method. It collects information about the runtime values of the method parameters, the class reference (this) if it isn’t a static method and its return value. This runtime method context information can be formatted into trace texts or added to an exception the code is about to throw.


The MethodContext also maintains its own call stack and provides access to its calling method context.


For tracing purposes a MethodContext derived class, the TraceContext, adds to this a reference to a MethodTracer and method entry and exit trace methods.


Here’s a typical usage scenario:


public string Repeat(string value, int numberOfTimes)
{
    using(TraceContext ctx = new TraceContext())
    {
        ctx.Initialize(this);
        ctx.AddParameter(value, “value”);
        ctx.AddParameter(numberOfTimes, “numberOfTimes”);
        ctx.TraceMethodEntry();

        string result = null;

        // method impl.

        ctx.ReturnValue = result;

        return result;
    }  // Dispose is called on ctx, calling TraceMethodExit()

}


Note that the TraceContext (MethodContext) maintains weak references to all instances.


MethodTracer


The MethodTracer instance is created for each TraceContext. The MethodTracer takes a TraceSource and an optional method-level TraceSwitch in its constructor and uses these to filter and output trace text. It implements 2 versions of the FormatTrace method; one instance and one static. The static FormatTrace method can be used by your code to trace custom texts. The TraceContext is located behind the scenes.


The FormatTrace method takes an object parameter as the object to generate a trace text for (along with some other parameters). The method delegates this task to the TraceManager (discussed next) where a collection of ITraceFormatter instances is checked to see if that specific Type is supported.


If the TraceSwitch allows it the formatted text is output to the TraceSource.


TraceManager


The TraceManager is a global (singleton) class that manages several cached classes. One already discussed are the TraceFormatters. These classes are able to generate trace text for a specific Type of object. TraceFormatters can use other TraceFormatters and thus composing the trace text.


By convention the TraceManager will keep track of a TraceSource for each class Type that creates a TraceContext. It will also keep track of optional method TraceSwitch instances that can be configured to fine tune trace levels at method level.


Exceptions


Exceptions caught in the method that created a TraceContext can keep track of it using the LastError property on the context. When throwing exceptions you can add the context information of the TraceContext to the exception using the AddContextTo method. This method populates the Data dictionary of an exception instance with the context information. Note that only types that are serializable are added, this is because the Data dictionary doesn’t allow otherwise (exceptions need to be marshaled across boundaries sometimes and that involves serialization).


The following code sample shows a nice way to add runtime information to an exception before propagating it to a higher level.


public string ReadTextFile(string path)
{
    using(TraceContext ctx = new TraceContext())
    {
        ctx.Initialize(this);
        ctx.AddParameter(path, “path”);
        ctx.TraceMethodEntry();

        string result = null;

        try
        {
            // method impl.
        }
        catch(IOException ioe)
        {
            ctx.AddContextTo(ioe);
            throw;
        }

        ctx.ReturnValue = result;

        return result;
    }  // Dispose is called on ctx, calling TraceMethodExit()

}


The calling code will receive an exception which Data dictionary is filled with runtime method context information. A nice extension would be to be able to dump all properties of the instances present in the Data dictionary. That way you should be able to generate comprehensive error log messages.


Configuration


The following configuration shows how to set up a Console TraceListener and an EventLog TraceListener for errors, a trace source for several classes, trace switches at class level (trace source) and at method level.


<configuration>
  <system.diagnostics>
    <sharedListeners>
      <!– Choose your trace output channels –>
      <add name=”Console” type=”System.Diagnostics.ConsoleTraceListener”
           initializeData=”false” />
      <!– Only Error traces will go to the Event Log –>
      <add name=”ErrorEventLog” type=”System.Diagnostics.EventLogTraceListener”
           initializeData=”Jacobi.Diagnostics.TestApp”>
        <filter type=”System.Diagnostics.EventTypeFilter” initializeData=”Error” />
      </add>
    </sharedListeners>
    <sources>
      <!– Configure a TraceSource for each class–>
      <!– Non-configured classes all create a default TraceSource –>
      <source name=”Jacobi.Diagnostics.TestApp”>
        <listeners>
          <add name=”Console” />
          <add name=”ErrorEventLog” />
        </listeners>
      </source>
      <source name=”Jacobi.Diagnostics.TestApp.TraceAspectTest”>
        <listeners>
          <add name=”Console” />
          <add name=”ErrorEventLog” />
          <remove name=”Default” />
        </listeners>
      </source>
    </sources>
    <switches>
      <!– SourceSwitch settings for classes –>
      <!– You can specify SourceSwitch settings
          without configuring the TraceSource (<sources>) –>
      <add name=”Jacobi.Diagnostics.TestApp” value=”Error” />
      <add name=”Jacobi.Diagnostics.TestApp.TraceAspectTest” value=”All” />
      <!– TraceSwitch settings for Methods –>
      <add name=”Jacobi.Diagnostics.TestApp.TraceAspectTest.WithContext” value=”Info” traceFlow=”Entry,Exit” />
      <add name=”Jacobi.Diagnostics.TestApp.TraceAspectTest.ConcatName” value=”Verbose” />
    </switches>
  </system.diagnostics>
</configuration>

Basically this configuration is very similar to the one discussed in my previous post about System.Diagnostics.  <sharedListeners> declares all listeners, <sources> lists a TraceSource per class and <switches> configures both class-level switches and method-level switches. Notice that the method level switches extent the dot-syntax with the method name for the name of the switch and carry an extra traceFlow attribute. The traceFlow attribute allows you to filter the output of method entry and exit traces that are done by the TraceMethodEntry and TraceMethodExit methods on TraceContext.


The next post will investigate a way to get rid of all the custom code you have to write to use the TraceContext. Using a static aspect weaver it is possible to have all that code removed from your method and indicate with a code attribute what methods you want to trace in a completely transparent way.


Download the source code here. Note that this source code also contains the projects for the static aspect weaver that will be discussed in the next post.

Basic System.Diagnostics

The .NET framework has shipped with the System.Diagnostics namespace since version 1.0. My efforts to build a method context information gathering framework on the services of System.Diagnostics has brought me a deeper understanding of its classes and configuration settings. I will talk about my method context information gathering framework in a later post, but first I thought I would get us all on the same page on System.Diagnostics.


System.Diagnostics implements several classes that play a key role in outputting trace text from your application. Better understanding these classes will bring you insights in to how to extend the existing diagnostic framework in .NET or how to set up the configuration file to make full use of the out-of-the-box functionality.


TraceListener


The TraceListener class receives trace texts from the application and outputs it to a specific channel it was written for. There is a DefaultTraceListener class that outputs its text to the Win32 API OutputDebugString. But there is also an EventLogTraceListener that outputs its text to the windows event log. There is even an XmlWriterTraceListener that will output Xml to a stream. There are more listeners you can choose from and you can even write your own. Just derive your listener class from the abstract TraceListener base class and implement the abstract methods.


A TraceListener also maintains an optional Filter. This allows you to fine tune the type of information that a TraceListener actually outputs. For instance, you could put an EventTypeFilter on the EventLogTraceListener to only output Error-type traces to the windows event log.


TraceListener instances are held in a collection that all receive the same trace text to output. This means that the same trace text can be output on different channels (each channel is represented by a TraceListener) at the same time. This collection can live at the global/static Trace or Debug classes or at a TraceSource.


TraceSource


A TraceSource represents a configurable trace object that maintains its own set of TraceListeners. An associated TraceSwitch (discussed next) controls the trace level for this ‘scope’. Typically a TraceSource is configured in the .config. When the code instantiates a TraceSource with the same name it reads its settings from the .config file. This way you can control what portions of your application code will output trace text.


TraceSwitch


A TraceSwitch maintains a TraceLevel property that controls the importance of the trace texts passed to the TraceListeners. The usual Error, Warning, Info and Verbose are supported. Typical use is to configure the TraceSwitch in the .config file and when the code instantiates an instance using the same name it reads its settings from the .config file. Although you can use TraceSwitches standalone they are usually associated with a TraceSource (in config). It is also possible to write your own TraceSwitch.


Configuration Settings


A lot of System.Diagnostics functionality is driven by the .config file. Lets dive right in and look at the following configuration:


<configuration>
  <system.diagnostics>
    <sharedListeners>
      <!– Choose your trace output channels –>
      <add name=”Console” type=”System.Diagnostics.ConsoleTraceListener”
           initializeData=”false” />
      <!– Only Error traces will go to the Event Log –>
      <add name=”ErrorEventLog” type=”System.Diagnostics.EventLogTraceListener”
           initializeData=”Jacobi.Diagnostics.TestApp”>
        <filter type=”System.Diagnostics.EventTypeFilter” initializeData=”Error” />
      </add>
    </sharedListeners>
    <sources>
      <!– Configure a TraceSource for each class–>
      <source name=”Jacobi.Diagnostics.TestApp”>
        <listeners>
          <add name=”Console” />
          <add name=”ErrorEventLog” />
        </listeners>
      </source>
      <source name=”Jacobi.Diagnostics.TestApp.Class1″ >
        <listeners>
          <add name=”Console” />
          <add name=”ErrorEventLog” />
          <remove name=”Default” />
        </listeners>
      </source>
    </sources>
    <switches>
      <!– SourceSwitch settings for classes –>
      <add name=”Jacobi.Diagnostics.TestApp” value=”Error” />
      <add name=”Jacobi.Diagnostics.TestApp.Class1″ value=”All” />
    </switches>
  </system.diagnostics>
</configuration>

The configuration settings live inside the <system.diagnostics> element. Then we see a <sharedListeners> section. Although it is possible to configure all TraceListener settings separately for each TraceSource, I prefer to maintain a global list of (configured) TraceListeners and refer to them from the TraceSource configuration. <sharedListeners> is that global place. Notice that the EventLogTraceListener has a <filter> defined that only allows Error-type traces to pass to the event log.


The <sources> section allows you to list the configuration settings for all the TraceSources your application uses. If the configuration for an instantiated TraceSource is not found in the .config file, it is shut off by default. So if you expect to see trace output from a specific TraceSource but there isn’t any, 9 out of 10 times you did not configure it right (check the spelling).


Each <source> declares its own collection of TraceListeners, in this case referring to one declared in <sharedListeners>. As a convention I’ve used the full class names as TraceSource names and TraceSwitch names. But you can also choose a courser granularity, say at component level or at sub-system level.


You can associate a TraceSwitch with a TraceSource by using the switchName and switchType attributes on the <source> element. I’ve not done so in my example and that means that you have to instantiate the TraceSwitches manually in code (with the correct name). You can associate a TraceSwitch with a TraceSource by either using the switchName and switchType attributes on the <source> element -or- by just declaring a switch (<switches><add>) with the same name as the TraceSource.


Wrapping up


This quick tour around System.Diagnostics discussed the main classes that enable you to build pretty powerful tracing support into your application. With this information you could already instantiate a TraceSource for each class and configure a matching TraceSwitch. Code inside the class would simply call the TraceSource and it would work. You could configure it to allow specific (type of) information to come through while the rest is blocked, for instance. And although I would encourage anybody to at least take some time to fiddle with a simple console test application to try out these features, it is my experience that you’ll want more in a real application. That is why I build my method context information gathering framework. Although this framework does not add much to the tracing capabilities of System.Diagnostics, it does add a lot to the quality of information that is in the trace texts.


I plan to write about my framework in a future post.


For more information on System.Diagnostics go to MSDN.

Writing a WCF POX Syndication Service

WCF has received some enhancements in the .NET 3.5 framework. It is now possible to use the WCF service framwork to write POX  services; a service that does not use SOAP, but Plain Old Xml.


Also the Syndication support for WCF is new to .NET 3.5. It has builtin support to produce Rss 2.0 and Atom 1.0 feeds.


The example I like to show you is an Event Log Feed Service. This service produces a Rss 2.0 feed for the Application event log Error entries. It is hosted in IIS and can be called by addressing it over the url:


http://[base url]/Service.svc/GetLogEntries


Notice the GetLogEntries after the Service.svc. The GetLogEntries maps to the GetLogEntries method of the service and takes two optional parameters: an entryType (Error, Warning, Information) and a feedType (Rss1, Atom1).


http://[base url]/Service.svc/GetLogEntries?feedType=atom1
http://[base url]/Service.svc/GetLogEntries?entryType=Warning&feedType=atom1


To look at this for yourself download the source code here and install the service in IIS. Make sure the service dll is in the web’s bin folder.


The Service interface is declared using WFC’s ServiceContract attribute.


[ServiceKnownType(typeof(Atom10FeedFormatter))]
[ServiceKnownType(typeof(Rss20FeedFormatter))]
[ServiceContract]
public interface IEventFeedService
{
    [WebGet(UriTemplate=”/GetLogEntries?eventType={eventType}&feedType={feedType}”)]
    [OperationContract]
    SyndicationFeedFormatter<SyndicationFeed> GetLogEntries(string eventType, string feedType);
}


The return types are declare with using the ServiceKnownType attribute. The WebGet attribute makes it possible to call this service using the url (GET). The UriTemplate declares what possible variation are supported on the url: the method name and its optional parameters. Note that the parameter names of the method match the parameter names in the UriTemplate.


The Service implementation class implements the method of the Service interface (refer to the dowload for complete source code). Creating the Syndication Feed is a matter of creating SyndicationFeedItem instances and adding them to a SyndicationFeed instance. Finally the method returns either a Rss20FeedFormatter or a Atom10FeedFormatter instance depending on the requested feed format.


The Service.svc file is used by IIS to determine how to host the service.


<%@ServiceHost Factory=”System.ServiceModel.Web.WebServiceHostFactory” Service=”EventLogFeedService.EventFeedService” %>


Besides specifying which service class should be hosted, the file also specifies a Factory to create a WCF service Host instance. Note that this is a new class that supports the url addressing of our WebGet enabled service.


Disclaimer: Exposing event log information to external sources can expose a security hole!