Non-Invasive Tracing & Logging
Logging is so ubiquitous, and is addressed so elegantly by aspect-oriented programming, that it has become the Hello, World of AOP.
Logging is so frequently cited in introduction to aspect-oriented programming literature that many mistakenly think AOP is only good for tracing. Yet, logging is only one of many simple aspects.
Getting Started
Basically, logging is nothing more than writing some text whenever a method enters or exits. In PostSharp, this can be achieved by the following piece of code:
/// <summary> /// Aspect that, when applied on a method, emits a trace message before and /// after the method execution. /// </summary> [Serializable] public class TraceAttribute : OnMethodBoundaryAspect { /// <summary> /// Method invoked before the execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Information about the method being executed.</param> public override void OnEntry( MethodExecutionArgs args ) { Trace.TraceInformation( "{0}.{1}: Enter", args.Method.DeclaringType.FullName, args.Method.Name ); Trace.Indent(); } /// <summary> /// Method invoked after successfull execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Information about the method being executed.</param> public override void OnSuccess( MethodExecutionArgs args ) { Trace.Unindent(); Trace.TraceInformation( "{0}.{1}: Success", args.Method.DeclaringType.FullName, args.Method.Name ); } /// <summary> /// Method invoked after failure of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Information about the method being executed.</param> public override void OnException( MethodExecutionArgs args ) { Trace.Unindent(); Trace.TraceInformation( "{0}.{1}: Exception {2}", args.Method.DeclaringType.FullName, args.Method.Name, args.Exception.Message ); } }
The class TraceAttribute is a custom attribute that can be used to
annotate every method requiring tracing. However, in many situations, we do not
want to touch the source code of target methods.
Aspects allow you to target multiple methods using a single piece of code. For instance,
the following snippet applies TraceAttribute to all public methods
of public types in the namespace MyNamespace:
#if DEBUG [assembly: Trace( AttributeTargetTypes = "MyNamespace.*", AttributeTargetTypeAttributes = MulticastAttributes.Public, AttributeTargetMemberAttributes = MulticastAttributes.Public )] #endif
Improving Runtime Performance
The preceding code was a good pedagogical example, but don't use it in production:
it is inefficient. Indeed, it makes use of System.Reflection at runtime
to build the method name. The following version of the aspect computes the method
name at build time and stores it in a field. At runtime, the field just has to be
read, and reflection is not necessary any more.
/// <summary> /// Aspect that, when applied on a method, emits a trace message before and /// after the method execution. /// </summary> [Serializable] public class TraceAttribute : OnMethodBoundaryAspect { private string methodName; /// <summary> /// Method executed at build time. Initializes the aspect instance. After the execution /// of <see cref="CompileTimeInitialize"/>, the aspect is serialized as a managed /// resource inside the transformed assembly, and deserialized at runtime. /// </summary> /// <param name="method">Method to which the current aspect instance /// has been applied.</param> /// <param name="aspectInfo">Unused.</param> public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo) { this.methodName = method.DeclaringType.FullName + "." + method.Name; } /// <summary> /// Method invoked before the execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnEntry(MethodExecutionArgs args) { Trace.TraceInformation("{0}: Enter", this.methodName); Trace.Indent(); } /// <summary> /// Method invoked after successfull execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnSuccess(MethodExecutionArgs args) { Trace.Unindent(); Trace.TraceInformation("{0}: Success", this.methodName); } /// <summary> /// Method invoked after failure of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnException(MethodExecutionArgs args) { Trace.Unindent(); Trace.TraceInformation("{0}: Exception {1}", this.methodName); } }
Printing Parameter Values
You know the situation: a bug occurs in production, you can't reproduce it in a development environment, and logs are useless because they don't contain the value of parameters of methods in the exception call stack. One solution may be to log the parameter values whenever an exception happens. Although this is daunting using conventional programming techniques, aspects make it much easier.
[Serializable] public class VerboseTraceAttribute : OnMethodBoundaryAspect { private string methodName; /// <summary> /// Method executed at build time. Initializes the aspect instance. After the execution /// of <see cref="CompileTimeInitialize"/>, the aspect is serialized as a managed /// resource inside the transformed assembly, and deserialized at runtime. /// </summary> /// <param name="method">Method to which the current aspect instance /// has been applied.</param> /// <param name="aspectInfo">Unused.</param> public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo) { this.methodName = method.DeclaringType.FullName + "." + method.Name; } /// <summary> /// Method invoked before the execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnEntry(MethodExecutionArgs args) { Trace.TraceInformation("{0}: Enter", this.methodName); Trace.Indent(); } /// <summary> /// Method invoked after successfull execution of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnSuccess(MethodExecutionArgs args) { Trace.Unindent(); Trace.TraceInformation("{0}: Success", this.methodName); } /// <summary> /// Method invoked after failure of the method to which the current /// aspect is applied. /// </summary> /// <param name="args">Unused.</param> public override void OnException(MethodExecutionArgs args) { Trace.Unindent(); StringBuilder stringBuilder = new StringBuilder(1024); // Write the exit message. stringBuilder.Append(this.methodName); stringBuilder.Append('('); // Write the current instance object, unless the method // is static. object instance = args.Instance; if (instance != null) { stringBuilder.Append("this="); stringBuilder.Append(instance); if (args.Arguments.Count > 0) stringBuilder.Append("; "); } // Write the list of all arguments. for (int i = 0; i < args.Arguments.Count; i++) { if (i > 0) stringBuilder.Append(", "); stringBuilder.Append(args.Arguments.GetArgument(i) ?? "null"); } // Write the exception message. stringBuilder.AppendFormat("): Exception "); stringBuilder.Append(args.Exception.GetType().Name); stringBuilder.Append(": "); stringBuilder.Append(args.Exception.Message); // Finally emit the error. Trace.TraceError(stringBuilder.ToString()); } }
See Also
Check also the following third-party PostSharp add-ins: