Ramblings

Download Source Here: loggingwithaop (You must install PostSharp, which adds the PostSharp dll’s to the .Net reference list. PostSharp is free and easy to install)

One thing that has always bothered me is seeing logging statements all over in code, making the code less readable, and adding lines of unnecessary and repetitive code.  I’ve always wondered how to get around this, because in order to log what you want, you have to have code there to do it, right? At least that is what I thought until I stumbled across Aspect-Oriented Programming (AOP) with PostSharp.

AOP is a new technology or paradigm for separating crosscutting concerns (such as logging), that are usually difficult to implement in object-oriented programming.  Logging would be considered a “crosscutting concern” because, even though it is not the main concern of the program, it still affects many parts of the system. With Aspect-Oriented Programming, you implement your project using your OO language (c# for me) just like you would do normally, and then you deal separately with your crosscutting concerns in the code by implementing “aspects”. (One aspect could be logging, or security).  Finally, both the code and aspects are combined into a final executable form using an aspect weaver. So your objects go unchanged and uncluttered while adding in the aspect you want. If you are like me this is a little hard to picture without an example. Stay tuned.

PostSharp is a library for the .Net Framework that allows programmers to easily apply AOP techniques via class and method attributes. It transparently inserts itself in the build process and post-processes the compiled assembly. Since PostSharp works at MSIL level, it supports virtually all static languages targeting the .NET Framework.

In my example, each class adds a class attribute (the aspect) that will resolve the log level and encapsulate all of the logging logic that is executed. In the event that the user wants to have specific log statements, this is also possible by using the logging class directly. This logging example is implemented in such a way that log levels are dynamic, meaning you can create any combination of levels, and change any class level without having to recompile the program.

Lets begin with a simple class. Money.

public class Money
{
public Money() : this(0,0){}
public Money(int dollars, int cents)
{
if(dollars < 0 || cents < 0 || cents > 99)
{
throw new ArgumentOutOfRangeException();
}
Dollars = dollars;
Cents = (byte) cents;
}
public int Dollars { get; private set; }
public byte Cents { get; private set; }
public static Money operator +(Money a, Money b)
{
return new Money(a.Dollars+b.Dollars,a.Cents+b.Cents);//if the cents add up to more then 99 this will throw an exception
}
}

If we wanted to add trace or debug statements to this code we would have log statements at the beginning and end of each function/property, and also before the ArgumentOutOfRangeException, which should indicate some sort of error. Our properties would no longer be one line and the entire class would be less readable and convoluted with irrelevant code.  All this can be accomplished with a simple class attribute:

[Log("Money")]

.

The PostSharp.Laos namespace contains the OnMethodBoundaryAspect class that can be derived from. This contains the “OnEntry”, “OnSuccess”, “OnException” and “OnExit” methods that are overridden to implement behavior that fires when execution enters a method, returns from a method (OnSuccess only fires if the method has returned normally, i.e. not by an exception. OnExit executes regardless of an exception or not), or if a method returns because of an unhandled exception.   The following is an example of how to implement a custom logging attribute using the PostSharp library.

[Serializable]
public sealed class LogAttribute : OnMethodBoundaryAspect
{
public LogAttribute(string className)
{
_className = className;
}
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
LogLevel level = Logging.ResolveLogLevel(_className);
if (level <= Logging.SystemLogLevel)
{
string argumentString = BuildArgumentString(eventArgs);
Logging.Write(level,string.Format("Entering {0}.{1}({2})",
eventArgs.Method.DeclaringType.Name,
eventArgs.Method.Name,
argumentString));
}
}

This class is pretty straight forward. It overrides the OnEntry method, among others, so that any class that has the Log attribute will automatically have this method execute on any method, property or constructor that exists in the class. That is all the log code that is required. There is no need for logging statements anywhere in the code, although this is still possible if the user wants. The OnSuccess and OnException implementations are included in source code. The class simply adds the

[Log("ClassName")]

attribute. The name of the associated class is passed into the Log attribute constructor and when the OnEntry method executes, it resolves the log level that is registered with the associated class, which it grabs from an xml file. All classes simply have to pass in the name of class into the Log attribute and the Logging class resolves the level of the logging for the class. One advantage of this is that you can change the log level of any class or the log level of the system without having to recompile. This means if you have a problem in a particular part of the system you can easily turn the logging all the way up in that part of the system without slowing down the entire application.  I have even built a generic tool (which i have included in the source) that provides a GUI interface to change the log levels. This is generic enough to use with any program that follows a few simple rules. So you can use the same tool to control the log levels of any application.

The PostSharp library allows users to add attributes to not only classes, but also individual methods to allow different methods within each class to have different logging levels. My implementation of having each class register is own level does not as easily support this, because all logging is dynamic. The code does not know about the different levels, what they’re called, or the order of magnitude. This means you can’t programmatically call logging statements and specify the log level. However, I think the abstraction that is created has a much greater advantage then being able to label individual methods, which realistically wouldn’t be used. I’ve seen that throughout most classes, the level will be exactly the same for each method. There are exceptions however. You might want to log a specific error (one that is handled by the user because the OnException method will only log any unhandled exception. Or you might want to log a specific calculation or important value. This can be easily done using the Logging.Write(string customLevel, string message) method.  You can pass in a string to represent the level, but since logging is dynamic, technically, the code should not know which levels are valid. For this reason, in my example, every time i want to specifically write to the log file, i pass in a hard coded GUID for the customLevel parameter. This means that you can simply do a quick search for the GUID within the code and find it easily. This rule also makes it so if there are duplicate generic log messages, you can determine which one was logged.

When i run the application, i get output that is similar to the following:

<EXCEPTION>
<TIME>05/14/2009(mm/dd/yy)- 03:16:05 (utc)</TIME>
<MESSAGE>EXCEPTION: Money..ctor(System.Int32 dollars=="4",System.Int32 cents=="100",): Exception: Specified argument was out of the range of valid values.
Stack Trace:   at PostSharpTest.Money..ctor(Int32 dollars, Int32 cents) in C:DevelopmentPostSharpTestPostSharpTestMoney.cs:line 14</MESSAGE>
</EXCEPTION>
<EXCEPTION>
<TIME>05/14/2009(mm/dd/yy)- 03:16:05 (utc)</TIME>
<MESSAGE>EXCEPTION: Money.op_Addition(PostSharpTest.Money a=="PostSharpTest.Money",PostSharpTest.Money b=="PostSharpTest.Money",): Exception: Specified argument was out of the range of valid values.
Stack Trace:   at PostSharpTest.Money..ctor(Int32 dollars, Int32 cents) in C:DevelopmentPostSharpTestPostSharpTestMoney.cs:line 18
at PostSharpTest.Money.op_Addition(Money a, Money b) in C:DevelopmentPostSharpTestPostSharpTestMoney.cs:line 24</MESSAGE>
</EXCEPTION>
<A88D2E1F-8C36-4ac1-B7CC-DDE356847B1D>
<TIME>05/14/2009(mm/dd/yy)- 03:16:05 (utc)</TIME>
<MESSAGE>Invalid Money Value</MESSAGE>
</A88D2E1F-8C36-4ac1-B7CC-DDE356847B1D>

This gives you very accurate and relevant information: Date/Time (of course), the name of the method, the values passed into the method, the values returned from the method, and the stack trace on an exception. If you turn trace all the way up (“TRACE”) in the application (via “PostSharpTestApplication” setting in the “LogLevels.xml”, you will see that this happens for each method, property (get and set), and constructor. All this information is given back and the user doesn’t have to do anything for it.

In summary, application classes simply add the “Log” attribute to the class that the logging will be done in and pass in the name of the class to the attribute constructor. The log level gets resolved in the LogAttribute class. If necessary, the application classes can also use the Logging class to directory write to the log file, although this should be very infrequent.

In my opinion, post sharp offers a very clean way of performing very accurate and complete logging without cluttering up code. My solution offers logging that is abstracted from the user, and is dynamic in the sense that any log level can be added, deleted, or modified, and any class can change levels, without having to recompile.  Please post questions and comments for further discussion on Logging with Aspect-Oriented Programming.

Listen, this my first blog, and its not going to be that deep of a conversation, but its something that i see all the time, and in my personal and semi-professional opinion it’s incredibly annoying, and even more important, pretty stupid.

Do not, under any circumstances, give “Failure” names to boolean values. This is what i mean:

bool unsuccessful = true; //stupid
bool successful = true; //smart

You might be thinking, “this isn’t a big deal Kercheval.. why are you writing about this.” But it is a big deal, and this is why. This is something I’ve seen in industry, and has caused me headaches.  When communicating with hardware, you often send and receive information/data in raw bytes, and each bit is some sort of flag. So say we have a byte that we get back from the hardware, and one of the bits represent an error. Say a communication error. Do you see the problem? It might be obvious to me because the problem punched me right in the face… So lets say its the right most bit that is the “Communication Error” bit. The code to see if there was an error would be:

byte result = getInformationFromHardware(); //so we went out to the hardware and communicated and it returned a byte of information
bool failure = result & 0x01; //we bitwise and the result with 1 to get the right bit and if the bit is set, this represents a communication error

Ok.. this isn’t too bad. Seems reasonable.. But wait.. what are the default values for bytes, and shorts, and ints. 0. So if getInformationFromHardware() is really a c++ function and it doesn’t throw exceptions on failures (because it has the failure bits to tell you if there is an exception), but if there is an error and the return value never gets set then you have a good chance that you get the default value, 0, back. But since you named your variable “communication error”, or “failure”, then the bit has to be set to indicate a failure, but it never got set because there was a failure. So i assume success. Do you see why this is stupid now? You’re setting a value to indicate failure, but if there is a failure where you are not expecting it, the failure might cause the failure bit to not get set. Wow. Now i know this isn’t going to happen often, because usually (i develop in c# by the way) your managed code will call other managed code that will throw exceptions on errors, but if you’re calling unmanaged code, as is the case when you work with hardware, (from what I’ve seen) the code tends not to throw exceptions, because it tends to rely on return codes. (Although you can catch native exceptions use the Win32Exception class, and probably should have unmanaged code always wrapped in some sort of try/catch block. )

So while this probably isn’t the case most of the time, it was a headache for me because someone decided to name their variable a “Failure” name.

Ok. This wasn’t the most exciting or mind blowing post.  But i felt i needed to share why you should never do such a thing.