This article is part of a series about aspect-oriented logging with SmartInspect, our logging tool for .NET, Java and Delphi. Please see the first article of this series for a complete overview over the available posts.

There are various AOP frameworks available for each of the three platforms SmartInspect supports, so why did we decide to start with PostSharp for the first part of this blog series about apsect-oriented logging? PostSharp has become the de-facto standard AOP framework for .NET and there are many things to like about PostSharp:

• PostSharp is really easy to use. It integrates nicely with MSBuild (and therefore Visual Studio) and you just need to complete the PostSharp setup and are good to go.
• It provides different APIs depending on what you are trying to accomplish. You can use a low-level API for injecting snippets of MSIL code for complexer tasks (PostSharp.Core) or a very simple high-level API (PostSharp.Laos) to develop aspects with custom .NET attributes.
• It’s very well documented. The APIs are fully documented and there are getting started tutorials, videos, a plugin repository and lots more. Can’t get a lot better than that.
• It’s a compile-time AOP framework. Unlike other tools which inject the AOP code at runtime, it post-processes the assemblies directly after compliation which is more efficient and allows for more flexibility.
• Last but not least, some SmartInspect customers were already successfully using PostSharp in their applications and told us that they liked the combination of both tools (that’s how we became aware of PostSharp in the first place).

We will be using the simpler Laos API for our SmartInspect PostSharp aspects, as we found it sufficient for all our needs. The resulting library is able to automatically trace method execution, log exceptions and watch changes of field variables. The library comes with three aspects for the different tasks, each implemented as a custom .NET attribute.

Using the SmartInspect aspects

The general procedure of using a PostSharp aspect is to install the PostSharp framework and to add the PostSharp.Public and PostSharp.Laos assembly references to your application. PostSharp injects itself into the MSBuild build process and automatically processes all assemblies that reference PostSharp.

For our logging aspects, you further need to add references to the Gurock.SmartInspect and Gurock.SmartInspect.PostSharp assemblies (the logging library and PostSharp aspects, respectively). The logging library is included in the SmartInspect trial download and the SmartInspect AOP plugin can be downloaded from the SmartInspect resources page.

Tracing method execution

The first aspect I am going to demonstrate is for tracing method execution. This aspect makes it really easy to generate a complete call trace of your application, showing you the entire application flow and letting you inspect stack traces at each execution point. It automatically generates two log messages for each method call: one for entering a method and one when a method exits. You can also log the passed method arguments (when entering a method) and the method result (when exiting a method), respectively.

To use this aspect, simple add the SiTrace custom attribute to your application as follows (note how you can continue to use SmartInspect for complementary log messages, of course):

using System;
using Gurock.SmartInspect;
using Gurock.SmartInspect.PostSharp;

[assembly:SiTrace(SessionName="Main")]

namespace Gurock.SmartInspect.PostSharp.Samples
{
	class Program
	{
		static void Main(string[] args)
		{
			SiAuto.Si.Enabled = true; // Enable logging
			Hello("World");
			Goodbye("World");
		}

		static void Hello(string name)
		{
			SiAuto.Main.LogMessage("Hello, {0}.", name);
		}

		static string Goodbye(string name)
		{
			string msg = String.Format("Goodbye, {0}.", name);
			SiAuto.Main.LogMessage(msg);
			return msg;
		}
	}
}

The attribute can be specified on a per-class/per-method basis or, like in our example, for the entire assembly. You can further specify filters for including/excluding certain modules/classes (called attribute targets in the PostSharp terminology), set aspect priorities (useful with nested aspects) and much more.

Our aspects have a few additional SmartInspect-related options. First, as you can see in the example above, you can set the session name used for sending log messages. If you do not want a hard-coded session name, you can tell the aspect to make use of the logging context and automatically adjust the name based on the current namespace or class. You can do so by setting a so called session policy. For example, to automatically use a session name that equals the name of the current class context, you can use a session policy of SessionPolicy.TypeName and omit the session name:

...
[assembly:SiTrace(SessionPolicy=SessionPolicy.TypeName)]
...

There are additional options for including the method arguments (IncludeArguments) and method return value (IncludeReturnValue). With both options enabled, the resulting log looks as follows in the SmartInspect Console (SmartInspect’s viewer application). Note how the automatic enter/exit messages are mixed with the manual log messages:

The SiTrace sample log shown in the SmartInspect Console

Logging exceptions

Another typical use-case for logging is recording all occurring exceptions and this is usually done by adding log calls to your exception handlers. Adding log statements to all your exception handlers can get tedious and error-prone though (e.g., you could forget to rethrow the exception after logging it), so we’ve added an aspect to automate this task for you. To use it, just add the SiException attribute to your code:

using System;
using Gurock.SmartInspect;
using Gurock.SmartInspect.PostSharp;

...

[assembly: SiException(SessionName="Main")]

...

		static void Hello(string name)
		{
			SiAuto.Main.LogMessage("Hello, {0}.", name);
			throw new Exception("This is a test exception");
		}

...

Note how the exception is now automatically included in the resulting log (within the expected method context):

The SiException sample log shown in the SmartInspect Console

Watching field values

Arguably the most advanced aspect in this library is the SiField attribute. This attribute lets you automatically record any changes to values of object or class fields. The aspect gets notified whenever the value of a field changes and then logs the name of the field along with its old and new value. You can configure whether the aspect should send the name and values as normal log messages or as SmartInspect watches (for showing the latest values of a variable in the watches toolbox or for displaying its history as a chart in the watches graph). By default, both watches and normal messages are logged.

Let’s have a look at the following example which demonstrates SiField in practice. Note how we use SiField as an attribute for the entire assembly again. We could also limit it to individual classes or fields, either by writing the attribute above the classes/fields we want to inspect or by specifying filters/attribute targets for the global attribute.

using System;
using Gurock.SmartInspect;
using Gurock.SmartInspect.PostSharp;

[assembly: SiField(SessionName = "Main")]

namespace Gurock.SmartInspect.PostSharp.Samples
{
	class Program
	{
		public static int FIELD;

		static void Main(string[] args)
		{
			SiAuto.Si.Enabled = true; // Enable logging
			Counting();
		}

		static void Counting()
		{
			Random r = new Random();

			for (int i = 0; i < 10; i++)
			{
				FIELD = r.Next(100);
				Thread.Sleep(1000);
			}
		}
	}
}

And here’s the generated log in the SmartInspect Console:

The SiField sample log shown in the SmartInspect Console

As you can see, every field change is automatically logged and shown in the Console. The watches toolbox in the lower left of the Console displays the latest value of FIELD in addition to the normal log messages in the main view. Also note the watches graph on the right that displays the field’s history as a chart (with its values over time). I believe an upcoming version of PostSharp will also be able to watch properties and we will update our library accordingly when this feature is available.

The nice thing about these aspects is that they can be freely combined as you like. You can mix and match the aspects as needed. If you plan to use our aspects and library, I also recommend taking a look at the PostSharp documentation for more details about aspects, AOP and PostSharp in general as well as how to configure PostSharp for more complex scenarios.

Feel free to send me an email or leave a comment on this blog in case you have any questions about this plugin.