Improve Logging using C# 5.0 Caller Info Attributes

Posted by: Sumit Maitra , on 1/23/2014, in Category C#
Views: 35208
Abstract: The C# Caller Info attributes have primarily been added to aid Logging, Runtime debugging and error handling. 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

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 a couple of years ago using C# 2.0.

With VS 2012 and C# 5.0, we 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

main

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 presses the Escape key. The code for this is in the LoopInfintely() method shown below.

loop-infinitely-method

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

log-error-method

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

log4net-config-declaration

The configuration section is as follows

log4net-config

log4net-config

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

initialize-log4net-viewer

The GetLogger factory method initializes 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!

logging-code

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

log-messages

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 C# 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.

Download the entire source code of this article (Github)

Give a +1 to this article if you think it was well written. Thanks!
Recommended Articles
Sumit is a .NET consultant and has been working on Microsoft Technologies since his college days. He edits, he codes and he manages content when at work. C# is his first love, but he is often seen flirting with Java and Objective C. You can follow him on twitter at @sumitkm or email him at sumitkm [at] gmail


Page copy protected against web site content infringement by Copyscape


User Feedback
Comment posted by Mayuresh Sawardekar on Friday, January 24, 2014 8:17 AM
Wasnt able to download the source code.
Comment posted by Sumit on Thursday, January 30, 2014 10:39 PM
Hi Mayuresh,

Github has a link on bottom right hand side (search for the text - Download Zip), click on it to download the code in one go.

Comment posted by Harshil Lodhiya on Thursday, February 20, 2014 3:19 AM
Sumit,

Thanks for the article. I was wondering that will this work for 2nd or n level wrapper? Its just providing immediate one level above calling method name.

Thoughts?
Comment posted by mostafa on Friday, February 28, 2014 11:54 AM
merci,
Comment posted by Jeetendra Gund on Friday, March 14, 2014 6:33 AM
Good One....Thanks

Post your comment
Name:  
E-mail: (Will not be displayed)
Comment:
Insert Cancel