Logging Method Entry and Exit Points Dynamically
4.25/5 (3 votes)
Logging method entry and exit points
Introduction
I am writing and supporting software that is used worldwide. Often the machines run disconnected from the internet. So when something goes wrong, the only way to analyze the problem is by analyzing the log files. We use the log4net library for logging.
Problems are often a consequence of what happened before. Knowing the execution history helps to find out what was the root cause of the problem. So in order to pinpoint what went wrong, we often log the entry and exit points of methods. We log the method name and, if needed, the parameters values and the return value. Before .NET 4.5, logging the method name was hardcoded (unless you were ‘crawling’ the call stack). If you hardcode method name in the logging call, you have a problem when the method name changes: you will have to change log entry and log exit call as well. Since .NET 4.5, we can log the method name dynamically without investigating the stack explicitly. The intention is not to go as far as the Aspect Oriented approach.
In this article, we present some extension methods for the ILog interface of the log4net library to log entry and exit points in a dynamic way. We designed it in such a way that you can customize the way logging takes place. Tests are included and can be used as documentation on how to use the small library.
The rest of the article explains the interface and its implementation.
Implementation
We implemented the extension points in the (static) class LoggerExtension in the namespace log4net.Extension. We reference log4net assembly as we rely on its basic services. The sources for the class explained in this article are included. The solution also contains a second project in which unit tests for LoggerExtension are implemented. We use NUnit to implement the tests.
Here is the structure of the rest of the article. We will start with the simple method LogBlock and explain what is happening. The LogBlock method logs entry and exit points of a method in one call. The LogBlock method has several overloads that will be discussed.
If you want log for entry and exit points differently (for example different logger level), you can use DebugEntry and DebugExit or LogEntry and LogExit. DebugEntry and DebugExit methods log at debug level. These methods are explained after the LogBlock method. Next, we explain the LogEntry and LogExit methods that allow you the log at any logger level and the method parameters as well if needed. Finally, I will explain how to customize the library.
LogBlock
Before .NET 4.5, we logged the entry point and exit point of method MyMethod in the following way (the Logger property returns an initialized log4net logger):
void MyMethod()
{
Logger.Debug(">MyMethod");
...
Logger.Debug("<MyMethod");
}
The method entry is prefixed with ‘>’, the exit with ‘<’. Changing the method name meant changing three lines of code. From .NET 4.5 on by using our extension methods, we can log the entry point and exit point of method MyMethod in the following way:
void MyFunction()
{
using(Logger.LogBlock())
{
...
}
}
As you can see, the string parameters are gone. When the name of the method is changed, the log entry will changed automatically. Here is how the LogBlock extension method is defined in order to achieve this:
static public ExitLogger LogBlock(this ILog logger, [CallerMemberName]string name = null)
The method is defined as static methods with the first parameter the this parameter as the methods are extension methods. The type extended is the ILog interface of the log4net library. The next optional parameter is the name with default value null. This parameter is annotated with the CallerMemberName attribute. As a result of this annotation and if no value is passed for this parameter by the caller, this parameter will be assigned the name of the caller method.
As you can see, the method returns an object of type ExitLogger. This object executes the actual logging of the exit point at the moment it goes out of scope. By using the using statement, we guarantee that the exit point is logged even when an exception would be thrown in the block of code executed.
When you call LogBlock with a parameter value, the value of that parameter will be logged (instead of the method name of the caller) prefixed with the prefix defined (see later). When you call LogBlock with null as parameter value, only the prefix will be logged. So, the following code:
void MyFunction()
{
using(Logger.LogBlock("test"))
{
...
}
}
Results in the strings ">test" and "<test" to be logged at debug level.
The above definition logs at the debug level. In the following overload of the method with the extra Level parameter you can log at any level. The Level type is defined in the log4net library:
static public ExitLogger LogBlock(this ILog logger, Level level, [CallerMemberName]string name = null)
As explained before, we like to log method parameters. This can be done using the following overloads of LogBlock:
static public ExitLogger LogBlock(this ILog logger, Level level, object[] entryParameters,
object[] exitParameters, [CallerMemberName]string name = null)
static public ExitLogger LogBlock(this ILog logger, Level level, object[] entryParameters,
[CallerMemberName]string name = null)
These incarnations of the LogBlock method have extra parameters compared to the definitions above: entryParameters and exitParameters, both an array of objects. The array of objects can hold extra info to be logged. entryParameters holds info to be logged at method entry (typical the call parameters) while exitParameters holds info to be logged at method exit (typical the returned object). The array of objects is (by default) serialized to a string and separated by a space. This code logs at method entry ">MyFunction test" at info level and "<MyFunction" at method exit time:
void MyFunction()
{
object[] parameters = { "test" };
using(Logger.LogBlock(Level.Info, parameters))
{
...
}
}
The entryParameters and exitParameters parameter are ignored when null value is passed to the LogBlock call.
If you want to have tighter control on what is logged at method entry or method exit, it is possible. This is what will be discussed in the rest of this article starting with the DebugEntry and DebugExit methods.
DebugEntry & DebugExit
Debug logging the method name at method entry can be done using DebugEntry. Logging the method name at method exit with DebugExit. Here is how the DebugEntry and DebugExit extension methods are defined in order to achieve this:
static public void DebugEntry(this ILog logger, [CallerMemberName]string name = null)
static public ExitLogger DebugExit(this ILog logger, [CallerMemberName]string name = null)
The parameters are used in the same way as in the LogBlock discussed above. The code below has the same effect as using the LogBlock call without parameters:
void MyFunction()
{
Logger.DebugEntry();
using(Logger.DebugExit())
{
...
}
}
LogEntry & LogExit
In order to log method entry at any other logger level than debug and to support logging of method parameters, we defined the LogEntry extension method:
static public void LogEntry(this ILog logger,
Level level,
[CallerMemberName]string methodName = null)
static public void LogEntry(this ILog logger,
Level level,
object[] parameters,
[CallerMemberName]string methodName = null)
The first incarnation of the LogEntry method has an extra parameter compared to the DebugEntry method: the logger level. The Level type is defined in the log4net library. This code logs ‘>MyFunction’ at info level (if the property EntryPrefix has not been changed, see later):
void MyMethod()
{
Logger.LogEntry(Level.Info);
…
}
The second incarnation of the LogEntry method has two extra parameters compared to the DebugEntry method: the logger level and an array of objects. The array of objects can hold extra info to be logged, typically the call parameters. The array of objects is (by default) serialized to a string and separated by a space. This code logs ‘>MyMethod test’ at info level:
void MyMethod ()
{
object[] parameters = { "test"};
Logger.LogEntry(Level.Info, parameters);
...
}
The parameters parameter is ignored when null value is passed to the LogEntry call. The methodName parameter can be passed as in the DebugEntry method and has the same effect (see above).
For logging the exit of a method, we defined the LogExit methods that is used in the same way as the LogBlock methods explained before:
static public ExitLogger LogExit(this ILog logger,
Level level,
[CallerMemberName]string methodName = null)
static public ExitLogger LogExit (this ILog logger,
Level level,
object[] parameters,
[CallerMemberName]string methodName = null)
The only difference between LogExit and LogEntry methods is the prefix: for LogExit the prefix is "<", for LogEntry is ">" and LogExit returns an ExitLogger for the reason explained above.
Customizing the Library
The library has three customization points:
- The prefix for entry and exit functions (resp.
LogBlock, DebugEntry, LogEntryandLogBlock, DebugExit, LogExit) can be set. - The way parameters are serialized can be customized.
- The way the method name inclusive the prefix is serialized can be customized.
In this section, the three customization points are explained one by one.
EntryPrefix & ExitPrefix
As explained before, the default prefix for the entry-calls (LogBlock, DebugEntry, LogEntry) is ">", for exit-calls (LogBlock, DebugExit, LogExit) it is "<". You can replace this defaults by any other string by setting the EntryPrefix and ExitPrefix properties of the LoggerExtension class. These properties are defined as follows:
public static string EntryPrefix { get; set; }
public static string ExitPrefix { get; set; }
So the following example will add log entry "in MyFunction" at method entry and "out MyFunction" at method exit (both debug logger level):
void MyFunction()
{
LoggerExtension.EntryPrefix = "in ";
LoggerExtension.ExitPrefix = "out ";
using(Logger.LogBlock())
{
...
}
}
Be careful: the properties are static properties. So once set, they are applicable for all calls to the extension points until set to an other value. This is by design: you probably want a consistent way to indicate method entry/exit.
Customizing Parameter Logging
The way parameters are logged can be customized. The parameters are serialized by executing the action defined in the MsgParametersAction property of the LoggerExtension class. You can supply your own implementation by setting the MsgParametersAction property in this class and referring to your own code to be executed. The MsgParametersAction property is defined as follows:
public static Action<StringBuilder, Severity, object[]> MsgParametersAction { get; set; }
The default implementation of this MsgParametersAction is to serialize the parameters is iterating over the object array (2nd parameter) and one by one appending a space, followed by appending the string representation of the object to the StringBuilder instance passed (1st parameter).
You can customize this functionality by supplying your own Action object. Again this property is defined statically so the action replacement will be in effect for all calls to the library. Here is an example, it will always log "test" instead of any values passed as parameter:
const string firstParam = "test";
object[] parameters = { "xx" };
LoggerExtension.MsgParametersAction =
delegate(StringBuilder builder, Level level, object[] prms)
{
builder.Append(" ");
builder.Append(firstParam);
};
Logger.LogEntry(Level.Info, parameters);
Customizing Method Name Logging
The way the method name (inclusive prefix) is logged can be customized. The method name is serialized by executing the action defined in the MsgPrefixAction property of the LoggerExtension class. Your can supply your own implementation by setting the MsgPrefixAction property in this class and referring to your own code to be executed. The MsgPrefixAction property is defined as follows:
public static Action<StringBuilder, Severity, string, string> MsgPrefixAction { get; set; }
The default implementation of this MsgPrefixAction is to append the prefix (3rd parameter) followed by a appending the method name (4th parameter) to the StringBuilder instance passed (1st parameter).
You can customize this Action by supplying your own action. Again this property is defined statically so the action replacement will be in effect for all calls to the library. Here is an example, it will log the hardcoded "test" string instead of the prefix followed by the method name:
LoggerExtension.MsgPrefixAction =
delegate(StringBuilder bldr, Level lvl , string prefix, string name)
{
builder.Append("test");
};
Logger.LogEntry(Level.Info, parameters);
Conclusion
This article discussed an implementation of extension point log log4net to log method entry and method exit point in a dynamic way using the .NET 4.5 CallerMemberName attribute. It was explained how to customize the library to your own needs. The projects include the latest released version of the log4net. It includes unit tests that can serve as working example. You can define your own interface and extension points and make use of the basics in this library. Applying the same functionality to other logging frameworks should be easy. After enjoying so much open source code, I hope other people find this small library useful.
Using the Code
This code will compile for .NET 4.5 (or higher) only. The code can be used by either referencing the log4net.Extension assembly produced by the project included. You will need to use the same log4net version as included in this package. You can you use your own version of log4net as well. In this case, you will need to recompile the assembly. The second option is to including the LoggerExtension and ExitLogger class in your project. A reference to the log4net library will be needed as well.
History
- 2nd January, 2015: Initial version
- 3rd January, 2015: Corrected typos
- 11th January, 2015: Added
LogBlock, simplified the tests