Simplifying Logging With PostSharp

Tags: ASCOM, software-engineering, aspect-oriented-programming, development, logging, clean-code

In my ASCOM drivers and other software, I’ve taken to using a product called PostSharp (https://www.postsharp.net/) which can be used to automate certain design patterns and generally reduce ‘boilerplate’ clutter, leading to cleaner, more readable code. The essence of PostSharp is that it lets you factor out the ‘cross cutting concerns’ such a logging, code contracts (pre- and post-conditions), design patterns such as INotifyPropertyChanged, thread safety, synchronization and marshalling, and almost anything repetitive. The repetitive code is factored out and then re-applied declaratively, using attributes.

The simplest way to explain this is to show a real example. So here is a method from an ASCOM Telescope driver from about 2 years back, before I started using PostSharp:

1 /// <summary> 2 /// Abort any slew in progress. 3 /// </summary> 4 public void AbortSlew() 5 { 6 Diagnostics.Enter(); 7 if (!Connected) 8 throw NotConnected; 9 if (SystemIsParked) 10 throw Parked; 11 try 12 { 13 awr.WriteCommand(Protocol.AbortGoTo); // No reply expected. 14 awr.WriteCommand(Protocol.AbortGoTo); // Write the abort sequence a few times just to make certain. 15 } 16 finally 17 { 18 Diagnostics.Exit(); 19 } 20 }

There are basically only two functional lines in this method, lines 13 and 14. Everything else is either logging or testing preconditions. Let’s look at that same method today, after PostSharp has been used:

1 /// <summary> 2 /// Abort any slew in progress. 3 /// </summary> 4 [NotParked] 5 public void AbortSlew() 6 { 7 awr.AbortGotoSlew(); 8 }

All the cruft has gone, yet this smaller version of the method produces more detailed logging output and carries out the same pre-requisite checks, only more efficiently (for example, if this method happens to be called from within another that has already checked the ‘NotParked’ precondition, the check would not be performed again).

So how is this achieved? The trick is in something called ‘aspects’ – PostSharp is an (AOP) framework. Aspects are bits of code that you can write yourself, or in many cases (as is the case with logging) are supplied ready-made with PostSharp. Aspects are actually custom attributes, and you’ll observe the [NotParked] attribute applied to the second example. PostSharp adds an additional compilation step, which post-processes the compiler output and re-writes the code to include the functionality of the aspect. Aspects can be applied broadly, at the assembly level in AssemblyInfo.cs:

1 // Add PostSharp aspect to trace program execution using NLog. The attribute is given 2 // a low priority as we don't want to trace other aspects. The verbosity level defaults to Trace. 3 [assembly: NLogTraceWithArguments(AspectPriority = 999, AttributePriority = 999)] // PostSharp logging pattern

…or they can be applied directly to methods, properties, fields, etc. as shown in the AbortSlew() method.

It is worth looking at the code for the [NotParked] aspect as this is a custom aspect that I had to write myself…

1 [Serializable] 2 public sealed class NotParkedAttribute : OnMethodBoundaryAspect 3 { 4 static int nesting = 0; 5 /// <summary> 6 /// Verifies that the telescope device is not parked. 7 /// Throws <see cref="ParkedException" /> if it is. 8 /// </summary> 9 /// <param name="args"> 10 /// Event arguments specifying which method 11 /// is being executed, which are its arguments, and how should the execution continue 12 /// after the execution of 13 /// <see cref="M:PostSharp.Aspects.IOnMethodBoundaryAspect.OnEntry(PostSharp.Aspects.MethodExecutionArgs)" />. 14 /// </param> 15 /// <exception cref="InvalidOperationException">Thrown if the apsect is applied to any type that does not implement ITelescopeV3</exception> 16 /// <exception cref="NotConnectedException">Thrown if the device is disconnected.</exception> 17 /// <exception cref="ParkedException">Thrown if the device is parked.</exception> 18 public override void OnEntry(MethodExecutionArgs args) 19 { 20 base.OnEntry(args); 21 if (!(args.Instance is ITelescopeV3)) 22 throw new InvalidOperationException("Aspect can only be used in a class that implements ITelescopeV3"); 23 var instance = args.Instance as ITelescopeV3; 24 if (nesting > 0) return; // Optimization - no need to check in nested calls. 25 if (!instance.Connected) 26 { 27 var name = args.Method.Name; 28 var message = string.Format("{0} requires that Connected is true but it was false", name); 29 throw new NotConnectedException(message); 30 } 31 if (instance.AtPark) 32 { 33 var name = args.Method.Name; 34 var message = string.Format("{0} is invalid when the device is parked", name); 35 throw new ParkedException(message); 36 } 37 ++nesting; // No need to check on nested callse until we exit from this one. 38 } 39 40 /// <summary> 41 /// Method executed <b>after</b> the body of methods to which this aspect is applied, 42 /// even when the method exists with an exception (this method is invoked from 43 /// the <c>finally</c> block). 44 /// </summary> 45 /// <param name="args">Event arguments specifying which method 46 /// is being executed and which are its arguments.</param> 47 public override void OnExit(MethodExecutionArgs args) 48 { 49 base.OnExit(args); 50 --nesting; 51 } 52 }

That may seem like a lot of code, but if you ignore the comments its only about 20 lines. This is a Method Boundary Aspect and let us intercept a method call both on entry and exit. Note that the exit boundary is guaranteed to execute even if the method throws an exception. I use this aspect at least 15 times in just one driver, and it incorporates the ‘Not Connected’ check, and many of the calls are nested and would otherwise result in multiple redundant checks, which clutters up the log output and reduces efficiency, so this actually makes a big difference. Is my code any shorter? Yes, a little bit (it eliminates about 90 lines of code and replaces it with about 20 lines in the aspect). Is it cleaner and more loosely coupled? Yes, absolutely; clean code and loose coupling are things I care about a lot, so I think overall this is a very worthwhile trade-off. Again, it will come down to your personal development style as to whether you think it is worthwhile – but what convinced me is the fact that I could get really detailed diagnostics with pretty much no effort.

Not everyone likes AOP. Anders Hejlsberg, father of .NET and C#, . No doubt the complexity of the build process is increased slightly and you still have to write the aspects, but you write them once and then that logic evaporates from the rest of the code. Whether you think it makes the code clearer or more obscure, easier or harder to write, is largely a matter of personal taste and style. For me and my approach to software engineering, it is a ‘no-brainer’ and I love the simplifying effect on my code and the way it reduces coupling – for example, I can swap my logging framework just by changing the logging aspect, and it changes everywhere.

PostSharp has a free “community” edition which has some limitations; for example there is a limit on the numer of methods that some of the standard patterns can be applied to, but the quota is probably sufficient for most ASCOM drivers. It’ll work in Visual Studio 2013 Community Edition because that allows add-ons, so you can get started completely for free. The simplest way to get started is to , but be sure to understand the licensing limitations before relying on the pattern libraries – you don’t want to start using them thinking they are free only to discover later that isn’t the case. Although, if you are a freelance developer or work on an open source project, you may well be able to get a free full license, as I did.

Definitely worth a try, just to see what’s possible. I ended up using it in my production code.

No Comments

Add a Comment

Let Us Help You

Find us on Facebook