Using Caller Info Attributes in C# 5.0 to Improve Logging

Tweet

The problem of passing current method details haunted my team and me when we were asked to add logging to every available business layer method in a two year old project, that had no logging and empty try { } catch { } blocks. We eventually worked around it by using a mix of reflection and string literals to get the current method name. But in my guts I hated the fact that I had to use reflection to do logging. This was 5 years ago using C# 2.0.

Come VS 2012 and C# 5, we will have access to three attributes that do specifically the task that we had hacked around then. These attributes are

• CallerFilePathAttribute
• CallerLineNumberAttribute
• CallerMemberNameAttribute

These can be used in any logging method to retrieve the calling method and log it. In this post, we will see how we can use Log4Net’s rolling file Appender* and the Caller Info Attributes to log errors in an application

Note: Appenders for log4Net are like Providers and serve as an extension point for Log4Net. The RollingFileAppender logs errors to a file and rolls over to a new file if the current file passes certain criteria like a date based roll over or size of file based roll over. You also have SQL Appenders and Xml Appenders and host of log outputs possible using Log4Net.

Starting off with a Console Application

Create a new Console Application in Visual Studio 2012 (aka VS 11)

We will simply log key-strokes as input at the Console window and depending on type of keys pressed throw exceptions with different methods. We end the execution when users press the Escape key. The code for this is in the LoopInfintely() method shown below.

To show that the Caller Info Attributes work at the method level we are logging Errors from a method called LogError as shown below

Logger class above is a Singleton wrapper around Log4Net. Before we look at the code for it, let us see the steps to install and configure Log4Net.

Setting up Log4Net

If there was ever anything to complain about Log4Net it was setting up a basic workable Appender in one go. Thanks to Nuget and the Community that has been rectified. Install Log4Net using the following command in the Package Manager Console

PM> install-package log4net

Next install a Rolling File Appender configuration using the following package

PM> log4net.samples.rollingfileappender

The above inserts the following configuration section in the App.config

The configuration section is as follows

With this as a default, Rolling File Appender has been setup that rolls over daily. We have updated the file location and the converstionPattern as highlighted above. The conversion Pattern ensures the fields are Pipe ( | ) separated, making them easy to import into excel and monitor.

With Log4Net in place let’s implement our Wrapper class Logger

Implementing the Log wrapper – Logger

The Log wrapper is a singleton class that creates one instance of the Log4Net logger and exposes methods for logging different levels of messages. For example it has methods Error, Warning and Debug to log corresponding levels in Log4Net.

It is initialized as follows

The GetLogger factory method initialized the LogManager.

The log4net.Config.XmlConfigurator.Configure() uses the configuration defined in the App.config

The Initialize method is called the first time _log is used. We have a guard clause to check if _log has been initialized. If not, the Initialize() method is called.

Using the Caller Info Attributes and Logging

So far we have a sample application that waits for key-strokes at the console and throws exception with different messages depending on what type of key is hit. Numeric keys result in Debug level logs, Function keys result in Warning level errors and all others result in Error level logs.

Now we look at the wrapper functions in our Logger class and see how we are obtaining trace information. As seen below we have three attribute decorated optional parameters called memberName, sourceFilePath and sourceLineNumber. These are decorated with the Caller* attributes. We can now very easily use these input params in our logs as shown below. The beauty of the implementation is ONLY your logger wants this information so it is specified only in the logger not in every method call to the logger. This by my standards is Magic!

Digging Deeper Into Caller Info Attributes

Actually there is not much of magic here, if you notice the three pieces of information they are static once the code is compiled. So the compiler simply replaces the optional parameters with the static values of MethodName, FilePath and SourceLineNumber in the method call at runtime. Basically the compiler is writing a bit of code/text for us at compile time.

Looking at the Logs

I had initially specified the log format to be pipe ( | ) separated. So we can open the file in Excel and specify custom separator as ( | ). Part of the log looks as follows

As we can see in Column D we have the details of the Method (where the error occurred), the File in which it occurred and the line number at which the error occurred. The Debug and Warn logs were from the LoopInfinitely whereas Error logs are from the LogError method. In column E we have the exception message and as we can see we have thrown messages based on type of keys typed.

Conclusion

The caller info attributes have primarily been added to aid runtime debugging and error handling. This is a very robust low-level language support.

As seen above it greatly helps writing better trace routines for runtime issue debugging. Also they are simply optional parameters, so you can at any point override the default values and pass in custom values in the parameters.

The Caller Info values are emitted as actual strings into IL at compile time and are not affected by obfuscation.

Another use for the CallerMemberName attribute is implementation of the INotifyPropertyChange interface. Without the CallerMemberName we would need to pass in the property name as a mandatory parameter.

Fork this on Github or Download the entire source code

Reference

http://msdn.microsoft.com/en-us/library/hh534540%28v=vs.110%29.aspx

Tweet