How many times have you worked on a project and found yourself implementing your own custom application logging solution? How many more times have you been part of a large project where it seems that every programmer implements his or her own logging solution, and log files are strewn across the system? Instead of logging to a central log file or to the Event Log, messages are dumped to their own custom files, with arbitrary file formats and information. How many times have you told your customers that they would have to �Search for all files named *.log, and send them to us.� It�s certainly not confidence inspiring, and makes �debugging via end user� especially difficult.
Application logging is often an afterthought in application architectures, and log files are frequently found haphazardly distributed across the system. With the advent of .NET, Microsoft has declared application logging a first class citizen, embedding a solution right into the framework. Microsoft�s Trace classes offer simple logging, but also allow for extensive customization. In this article, we will explore the use of reflection to enhance trace logging in your current applications.
There have been several good articles already written on Tracing, and I'll try to avoid reproducing them here. For a solid overview of tracing, you might visit CodeProject's own Writing custom .NET trace listeners by Vagif Abilov, or MSDN's February 2001 Bugslayer article.
The Trace class is found in the System.Diagnostics namespace of the Framework. It�s simple and easy to use. You simply define TRACE in your application (VS.NET does this by default in all C# projects), and begin making calls to one of the static Write() methods found in the System.Diagnostics.Trace class.
using System.Diagnostics;
public void MyMethod() {
Trace.WriteLine("Entering Method MyMethod()");
// Rest of your application code.
}
Making the Trace.WriteLine() call is simple, but who is listening to the call? Where does this information go? Microsoft designed tracing to be as customizable and flexible as possible, so that we can either ignore the information, or several different logging methods may subscribe as Listeners. The base class that allows for this is the TraceListener class. All logging solutions must derive from this class. One of the simplest listeners included in the framework is a pre-build logging solution called the TextWriterTraceListener. The TextWriterTraceListener allows us to log, trace output directly to a file, with minimal additional coding. All we have to do is notify the framework that the TextWriterTraceListener wishes to subscribe to the application's Trace messages. Notification may occur through adding the listener in the application code, or through the application�s config file. We�ll use the application config file, as it is the most flexible solution. Simply add the following code to the config file:
<configuration>
<system.diagnostics>
<trace autoflush="true" indentsize="4">
<listeners>
<add name="CustomTraceListener"
type="Dennany.Diagnostics.CustomTraceListener,
CustomTraceListener" initializeData="c:\myListener.log" />
<remove type="System.Diagnostics.DefaultTraceListener"/>
</listeners>
</trace>
</system.diagnostics>
</configuration>
Make certain that the application config file is in the application�s directory, and is properly named. (See the downloadable code example TraceTester for a real-world example, or review the MSDN documentation for an in-depth discussion). A word of caution: config file errors are extremely difficult to track down, and simple errors like case sensitivity may cause failures that are difficult to find. You've been warned, so check your config file carefully! Other than that word of caution, that�s all there is to configuring a TextWriterTraceListener. All trace calls coming from the test application will now be directed to the file myListener.log. With tracing, it is easy to log to a file, the Event Log, or any other custom listener we wish to set up. However, after spending time with the trace class, I found myself writing a lot of boilerplate code. When I entered a method, I would write things like this:
public void MyMethod() {
Trace.WriteLine("Entering Method MyMethod()");
// Rest of your application code...
}
This isn�t really the ideal solution. I know it�s trivial, but what if I re-factor my program and change the name MyMethod to FooMethod? I�ve got to go in and change the Trace messages as well. Although this is a minor detail, it�s the kind of thing that has bitten me in the past, and bug hunting is difficult enough without having to be concerned about whether or not your trace messages are truly accurate.
So, reaching into my handy .NET toolbox, I pull out another invaluable tool to every .NET developer, Reflection. Using the Reflection classes, I am able to self examine the code at run-time, to determine who I am (what type am I?) and where I am (what method am I?). So, instead I found myself writing the following code:
using System.Reflection;
using System.Diagnostics;
public static void MyMethod() {
Trace.WriteLine("Entering" + MethodInfo.GetCurrentMethod().
ReflectedType.ToString() + "." +
MethodInfo.GetCurrentMethod().ToString() );
// Rest of your application code.
}
With the above tracing call, the expected output sent to our TraceListener would be something like:
Entering MyNameSpace.ClientStartup.Void MyMethod()
Well, I�ve got my logging solution, and I�ve started to use it throughout my application, but there are several problems with the way I�ve done things. First, there is quite a bit of code here, and I�ve created quite a bit of IDE inheritance or cut and paste coding. It isn�t exactly the OO solution that we are looking for. If I were a C programmer, perhaps I would look to a pre-processor solution and create a macro that would simply copy this code in wherever I placed the macro. That way, if I ever wanted to update the code, I could do so in one place. ATL and MFC made heavy use of macros, and didn�t it work for them?
Aside: I�ve also made another noteworthy mistake here. I�ve assumed that the object�s .ToString() method returns the object�s type information. This is true for the majority of the FCL, but not all classes display this behavior. For example, the System.Int32.ToString() instance method is overloaded to return the String representation of the Int32, and not its type information. We'll address this later in the article.
Well, macro support was not included in C#, and there were very good reasons for this. The main reason was likely to keep people like me from doing dumb things like creating macros when we really shouldn�t! What else could I do? I could try re-factoring this code into a central logging class, but then whenever I call GetCurrentMethod(), I�ll get the name of the logging class, and not the name of MyMethod(). I looked at in-lining the code, but the C# compiler does not allow you to force the inlining of a method into another method.
The next immediate thought would be to extend the Trace class with my own custom Trace class that does all of the logging for me! That should work, shouldn�t it? Well, it doesn�t, because Microsoft has headed us off at the pass on this one by declaring the Trace class sealed. This means that inheritance is impossible, and any solution that I implement must be done completely from scratch. Since re-inventing the wheel is normally something that I would like to avoid, I�ll continue my search elsewhere. Besides this, there are a couple of other problems with the above solution that we haven�t addressed yet.
First, there is the issue of performance. Each time you execute the above Trace.WriteLine()call, several things happen:
The static method GetCurrentMethod() is called inside the WriteLine() call (twice!), the get_ReflectedType accessor method is called internally to return the type, and there are also the ToString() calls on each of the returned objects. Quite a bit of overhead for a bit of simple logging. All this is happening whether or not we are listening! This could be quite a performance hit on any application.
We could of course compile without the TRACE switch defined. In VS.NET, see Project -> Properties -> Configuration Properties -> Build -> Conditional Compilation Constants. The default is to define TRACE. If you remove this, then Trace calls will not be compiled into the final executable. The problem here is that you�ve made a compile time decision, and not a runtime one. It would be far better to be able to define this at the customer�s site, and not while you are sitting at your desk compiling the solution.
You could also use TraceSwitch to check to see if you should log, and then add additional code elsewhere in the application or in the config file to set this:
using System.Reflection;
// Create a TraceSwitch.
static TraceSwitch mySwitch = new TraceSwitch("mySwitch",
"This is the description for mySwitch");
public static void MyMethod() {
Trace.WriteLineIf(mySwitch.TraceVerbose, "Entering" +
MethodInfo.GetCurrentMethod().ReflectedType.ToString()
+ "." + MethodInfo.GetCurrentMethod().ToString() );
// Rest of your application code.
}
In fact, if you take a look at TraceSwitch in the MSDN docs, this is very similar to what they've done. However, now we�ve created a real monster � these logging calls seem to grow and grow. This will enable us to turn off logging at runtime, but we�ve added to our code-bloat. There are now several lines of code to update every time I need to make a change to the way I do logging.
Well, I�ve looked around the Trace class and am unable to find an elegant solution for my logging problem. I�ve found a way to auto generate and log, class information at runtime, but it is slow, a little bloated, and I don�t consider it to be maintainable.
The answer to my problem is certainly not on the Trace side of .NET�s logging solution. What about on the TraceListener side?
I�ve already taken a look at the TextWriterTraceListener class, and found that it is a simple and easy way to consume Trace messages sent from our test application. Would it be possible to extend our listener to take care of the above problem?
At first glance, we appear to be stuck with the same problem that we had when we looked at factoring the Trace calls into their own logging method. Any self-introspective reflection calls will return the name of the TraceListener subclass, and not the name of the class calling the Trace.WriteLine() method.
However, reaching back into our .NET class library toolbox, we find the StackFrame class tucked away in the System.Diagnostics namespace. Perhaps if we could walk through the callstack, we could find our way backwards to the class and method that called us?
It's pretty simple to extend the FCL's TextWriterTraceListener class, so we'll start with an example that adds the date / time stamp to each message logged by the listener:
public class CustomTraceListener : TextWriterTraceListener {
// for our constructors, explicitly call the base
//class constructor.
public CustomTraceListener( System.IO.Stream stream,
string name ) : base(stream, name) { }
public CustomTraceListener( System.IO.Stream stream) :
base(stream) { }
public CustomTraceListener( string fileName, string name ) :
base(fileName, name) { }
public CustomTraceListener( string fileName ) :
base(fileName) { }
public CustomTraceListener( System.IO.TextWriter writer,
string name ) : base(writer, name) { }
public CustomTraceListener( System.IO.TextWriter writer ) :
base(writer) { }
public override void Write( string message ) {
base.Write( getPreambleMessage() + message );
}
public override void WriteLine( string message ) {
base.WriteLine( getPreambleMessage() + message );
}
private string getPreambleMessage() {
StringBuilder preamble = new StringBuilder();
preamble.Append(DateTime.Now.ToString());
preamble.Append(": ");
return preamble.ToString();
}
}
In the above code sample, we've inherited from the TextWriterTraceListener class, and each of our constructors merely call the base class constructor. Each call to Write() or WriteLine() then calls the private method getPreambleMessage(). This method will be responsible for building the message that we want to pre-pend to our messages in our custom logging solution. Note that here we used StringBuilder for efficiency, as we will be building on this method later. For now, we are simply return a string containing the current date and time, and our Write() and WriteLine() methods will write the preamble followed by the message passed from the original Trace call.
That's really all there is to writing a simple custom listener - most of the work has already been done for us by the .NET Framework Class Library. Let's build upon this now.
Now that we've built a Listener, we've also got a bit of code that we can step through in a debugger and see exactly what is going on when we are listening. If we build a simple client console application that makes a simple Trace.WriteLine("test 1 , 2 3...") call, and set a breakpoint in our getPreambleMessage(), we might see a call stack similar to the one found in Figure 1. You might wish to download the sample code included and step through the debugger yourself.
A detailed look at the call stack (See Figure 1) shows us that when our application makes a Trace call, the framework calls an internal TraceInternal class, which then checks for any registered listeners. TraceInternal then notifies each listener of the Trace() call. This is easy enough to see in our Visual Studio .NET debugger, but how do we find this information dynamically at run time? I have to find a way to walk back through the call stack, skipping any of the internal Tracing calls, to the method that originally called my custom TraceListener. After retrieving this information, I would like to log the type information and method signature.
Figure 1: CustomTraceListener CallStack
When looking at the Call Stack in the Visual Studio debugger, you might notice that the only methods that are between the calling class and our CustomTraceListener are from the System.Diagnostics.Trace and TraceInternal classes. It is useful to note that these are both in the System namespace.
By getting the current StackTrace, I can find my location on the call stack using the StackTrace instance method GetFrame(). This tells me where I am now. More useful in my logging solution is where I was before. I may find this out by �walking the stack� backwards. How do I know where to stop on the stack? If you noticed in Figure 1 that Trace and TraceInternal are the only classes between us and the original calling method, you might be tempted to hard code the number of steps to backtrack on the stack. The major problem with this approach is that the release version of your code is free to perform inlining and various other optimization tricks that will �break� your code and be very difficult to debug. You are also tying yourself to a specific implementation and version of the CLR. A much slower, yet safer, solution is to use reflection to examine the name of each class and decide if we have moved far enough backwards on the call stack. I know that the name of my current class is CustomTraceListener, and I also know that everything between my calling method and me lies within the System namespace. Therefore, I will simply keep walking backwards on the call stack until I�m no longer in the CustomTraceListener class, and no longer in the System namespace. The following code snippet illustrates this principle:
StackTrace stackTrace = new StackTrace();
StackFrame stackFrame;
MethodBase stackFrameMethod;
int frameCount = 0;
string typeName;
do {
frameCount++;
stackFrame = stackTrace.GetFrame(frameCount);
stackFrameMethod = stackFrame.GetMethod();
typeName = stackFrameMethod.ReflectedType.FullName;
} while ( typeName.StartsWith("System") ||
typeName.EndsWith("CustomTraceListener") );
We now know how to find where we were, using the call stack information available to us at runtime, and we have already examined how to use reflection to retrieve class and method information. By combining the two, we may achieve our previous goal of finding "Who am I?" and "Where am I?" We'll accomplish this by replacing our getPreambleMessage() in our CustomTraceListenerClass with the following code:
private string getPreambleMessage(){
StringBuilder preamble = new StringBuilder();
StackTrace stackTrace = new StackTrace();
StackFrame stackFrame;
MethodBase stackFrameMethod;
int frameCount = 0;
string typeName;
do {
frameCount++;
stackFrame = stackTrace.GetFrame(frameCount);
stackFrameMethod = stackFrame.GetMethod();
typeName = stackFrameMethod.ReflectedType.FullName;
} while ( typeName.StartsWith("System") ||
typeName.EndsWith("CustomTraceListener") );
//log DateTime, Namespace, Class and Method Name
preamble.Append(DateTime.Now.ToString());
preamble.Append(": ");
preamble.Append(typeName);
preamble.Append(".");
preamble.Append(stackFrameMethod.Name);
preamble.Append("( ");
// log parameter types and names
ParameterInfo[] parameters =
stackFrameMethod.GetParameters();
int parameterIndex = 0;
while( parameterIndex < parameters.Length ) {
preamble.Append(parameters
[parameterIndex].ParameterType.Name);
preamble.Append(" ");
preamble.Append(parameters[parameterIndex].Name);
parameterIndex++;
if (parameterIndex != parameters.Length )
preamble.Append(", ");
}
preamble.Append(" ): ");
return preamble.ToString();
}
The above code example merely combines each topic we've discussed so far. For a full code example, you may download the CustomTraceListener code example linked to this article.
When I first started learning .NET, I viewed reflection as a cool feature, but struggled with the idea that it could have any useful application for the day to day coder. After spending some time with it, however, I realized that reflection really opens the doors to more aspect-oriented programming, and will help greatly reduce coding efforts required to perform plumbing-type coding jobs. The more I look at reflection, the more I like what I see!
| You must Sign In to use this message board. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
. 
