Non-intrusive Logging with PostSharp and EntLib V5

This is really a classic of the Aspect Oriented Programming (AOP) domain with the twist that it has been used together with the Enterprise Library V5. Okay, you can find a number of implementations of this AOP pattern all over the web, however, this is my very own version of my grandmother’s recipe.

Firstly, let us have a look at the ingredients that will be needed to prepare this wonderful dish. Of course, as the title mentions, Enterprise Library V5 will be needed. The only other requirement is an AOP framework. This will be provided by PostSharp V2.0 (I did do the very same code a number of years back with EntLib 4 and PostSharp 1.5 with great success).

There are many good introductions to the Enterprise Library in general and specifically for the Logging Application Block so I will not be covering this software in any great detail. The emphasis here is how to show the use of PostSharp in making logging non-intrusive.

The AOP feature that will be used here is Aspect Weaving, or how to inject the logging code into the program flow between caller and callee. This is achieved by defining an attribute based on the PostSharp OnMethodBoundaryAspect class. This class along with the PostSharp post-compiler that is installed into the Visual Studio compile chain which builds and injects the AOP code directly into the normal code flow.

The attribute will be used in the code as follows:

[Logging(Priority = 3, 
Severity = TraceEventType.Error, 
Message = “Some message for the Log”
EventId = 1003)]

There is also the possibility to provide “filtering” in the assembly.cs such that the attribute is automatically applied to namespaces or to specific method names. Here is an example where all the methods in the Samples namespace beginning with “My” are logged:

[assembly: Logging( AttributeTargetTypes = “Samples3.My*” Category = “A”)]

And I almost forgot here is the code for the attribute:

    /// <summary>
    /// Enterprise Library Logging Application Block Attribute.
    /// </summary>
    [Serializable]

    public sealed class LoggingAttribute : OnMethodBoundaryAspect
    {
        /// <summary>
        /// The message written to log when entering a method.
        /// This field is initialized at runtime. It does not need to be serialized.
        /// </summary>
        [NonSerialized]

        private string enteringMessage;
        /// <summary>
        /// The message written to log when exiting a method.
        /// This field is initialized at runtime. It does not need to be serialized.
        /// </summary>
        [NonSerialized]

        private string exitingMessage;

        /// <summary>
        /// The message written to log when an exception is thrown in a method.
        /// This field is initialized at runtime. It does not need to be serialized.
        /// </summary>
        [NonSerialized]

        private string exceptionMessage;
The test program is very simple:

        /// <summary>
        /// The message written to log when a method is successful.
        /// This field is initialized at runtime. It does not need to be serialized.
        /// </summary>
        [NonSerialized]

        private string successMessage;

        /// <summary>
        /// Initializes a new instance of the <see cref=”LoggingAttribute”/> class.
        /// </summary>
        public LoggingAttribute()

        {

            this.Priority = 5;
            this.EventId = 1000;
            this.Message = “Test Default Logging Message”;
            this.Severity = TraceEventType.Information;
        }

        /// <summary>
        /// Gets or sets the priority.
        /// This field is initialized and serialized at build time, then deserialized at runtime.
        /// </summary>
        /// <value>The priority.</value>
        public int Priority { getset; }



        /// <summary>
        /// Gets or sets the severity.
        /// This field is initialized and serialized at build time, then deserialized at runtime.
        /// </summary>
        /// <value>The severity.</value>
        public TraceEventType Severity { getset; }



        /// <summary>
        /// Gets or sets the message.
        /// This field is initialized and serialized at build time, then deserialized at runtime.
        /// </summary>
        /// <value>The message.</value>
        public string Message { getset; }



        /// <summary>
        /// Gets or sets the event id.
        /// This field is initialized and serialized at build time, then deserialized at runtime.
        /// </summary>
        /// <value>The event id.</value>
        public int EventId { get;
 set; }

        /// <summary>
        /// Initializes the current aspect.
        /// Invoked only once at runtime from the static constructor of type declaring the target method.
        /// </summary>
        /// <param name=”method”>Method to which the current aspect is applied.
        /// </param>
        public override void RuntimeInitialize(MethodBase method)

        {

            this.enteringMessage = Resources.OnEntry;
            this.exitingMessage = Resources.OnExit;
            this.exceptionMessage = Resources.At;
            this.successMessage = Resources.Success;
        }

        /// <summary>
        /// Method executed <b>before</b> the body of methods to which this aspect is applied.
        /// </summary>
        /// <param name=”args”>Event arguments specifying which method
        /// is being executed, which are its arguments, and how should the execution continue
        /// after the execution of <see cref=”M:PostSharp.Laos.IOnMethodBoundaryAspect.OnEntry(PostSharp.Laos.MethodExecutionEventArgs)”/>.</param>
        /// <remarks>
        /// If the aspect is applied to a constructor, the current method is invoked
        /// after the <b>this</b> pointer has been initialized, that is, after
        /// the base constructor has been called.
        /// </remarks>
        public override void OnEntry(MethodExecutionArgs args)

        {

            this.PerpareMessage(this.enteringMessage, args);

        }



        /// <summary>
        /// Method executed when an exception occurs in the methods to which the current
        /// custom attribute has been applied.
        /// </summary>
        /// <param name=”args”>Event arguments specifying which method
        /// is being called and with which parameters.</param>
        public override void OnException(MethodExecutionArgs args)

        {

            this.PerpareMessage(this.exceptionMessage, args);

        }

        /// <summary>
        /// Method executed <b>after</b> the body of methods to which this aspect is applied,
        /// even when the method exists with an exception (this method is invoked from
        /// the <b>finally</b> block).
        /// </summary>
        /// <param name=”eventArgs”>Event arguments specifying which method
        /// is being executed and which are its arguments.</param>
        public override void OnExit(MethodExecutionArgs eventArgs)

        {

            this.PerpareMessage(this.exitingMessage, eventArgs);

        }



        /// <summary>
        /// Method executed <b>after</b> the body of methods to which this aspect is applied,
        /// but only when the method succesfully returns (i.e. when no exception flies out
        /// the method.).
        /// </summary>
        /// <param name=”eventArgs”>Event arguments specifying which method
        /// is being executed and which are its arguments.</param>
        public override void OnSuccess(MethodExecutionArgs eventArgs)

        {

            this.PerpareMessage(this.successM
essage, eventArgs);

        }

        /// <summary>
        /// Perpares the message.
        /// </summary>
        /// <param name=”resourceString”>The resource string.</param>
        /// <param name=”eventArgs”>The <see cref=”PostSharp.Laos.MethodExecutionEventArgs”/> instance containing the event data.</param>
        private void PerpareMessage(string resourceString, MethodExecutionArgs eventArgs)

        {

            if (eventArgs.Method == null)

            {

                return;
            }

            var log = new LogEntry
                          {
                              EventId = this.EventId,
                              Priority = this.Priority,
                              Severity = this.Severity,
                              Message = string.Format(
                                  resourceString,
                                  eventArgs.Method.DeclaringType.Name,
                                  eventArgs.Method.Name)
                          };
            Logger.Write(log);
        }
    }

/// <summary>
/// The test program.
/// </summary>
internal static class Program
{

    /// <summary>
    /// Mains this instance.
    /// </summary>
    private static void Main()

    {
        try
        {
            SayHello();
            SayGoodBye();
            Console.WriteLine(Strings.Program_Main_Success);
            Console.ReadLine();
        }
        catch (Exception ex)
        {
            var str = ex.Message;
            Console.WriteLine(str);
            Console.ReadLine();
        }
    }
    /// <summary>
    /// Says the hello.
    /// </summary>
    [Logging(Priority = 2, Severity = TraceEventType.Information, Message =
 “Some message for SayHello”, EventId = 3)]
    private static void SayHello()
    {
        Console.WriteLine(Resources.World);
    }

    /// <summary>
    /// Says the good bye. for SayGoodbye
    /// </summary>
    [Logging(Priority = 2, Severity = TraceEventType.Information, Message = “Some message for SayGoodbye”, EventId = 3)]

    private static void SayGoodBye()
    {
        Console.WriteLine(Resources.ByeWorld);
    }
}
When the Enterprise Logging has been configured for file based logging an output similar to this will appear:

----------------------------------------

Timestamp: 23.01.2011 15:24:39

Message: Entering Program.SayHello.

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

----------------------------------------

Timestamp: 23.01.2011 15:24:39

Message: On Success

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

----------------------------------------

Timestamp: 23.01.2011 15:24:39

Message: Leaving Program.SayHello.

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

----------------------------------------

Timestamp: 23.01.2011 15:24:39

Message: Entering Program.SayGoodBye.

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

----------------------------------------

Timestamp: 23.01.2011 15:24:40

Message: On Success

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

----------------------------------------

Timestamp: 23.01.2011 15:24:40

Message: Leaving Program.SayGoodBye.

Category: General

Priority: 2

EventId: 3

Severity: Information

Title:

Machine: PC2

App Domain: PostSharpTest.vshost.exe

ProcessId: 7896

Process Name: M:\Projects\PostSharpTest\PostSharpTest\bin\Debug\PostSharpTest.vshost.exe

Thread Name:

Win32 ThreadId:7076

Extended Properties:

----------------------------------------

 

Some small points to remember here:

  1. The initialisation of the debug strings is only made once when the aspect comes into life.
  2. The complete setup of the Enterprise Library Logging Application Block depends on developer preferences.

By the way PostSharp can be found here, and V5 of the Enterprise Library here.

That’s all folks…

Advertisements

~ by Intelligence4 on January 25, 2011.

One Response to “Non-intrusive Logging with PostSharp and EntLib V5”

  1. […] is just a quick post that augments my previous one on non-intrusive logging. Many of you out there have chosen the other logging framework due to prior experience with Log4J […]

Comments are closed.

 
%d bloggers like this: