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.
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 methods: DebugEntry
and DebugExit
and explain what is happening. Those methods log at debug level. 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. We will include small examples on how the library can be used.
DebugEntry & DebugExit
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()
{
Logger.DebugEntry();
...
Logger.DebugExit();
}
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 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 void DebugExit(this ILog logger, [CallerMemberName]string name = null)
The methods are 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.
When you call DebugEntry/DebugExit
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 DebugEntry
/ DebugExit
with null
as parameter value, only the prefix will be logged. So, the following code:
void MyFunction()
{
Logger.DebugEntry("test");
...
}
Results in the string
">test
" to be logged at debug level.
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
:
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 work in the same way as the LogEntry
methods explained before:
static public void LogExit(this ILog logger,
Level level,
[CallerMemberName]string methodName = null)
static public void 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 ">
".
Customizing the Library
The library has three customization points:
- The prefix for entry and exit functions (resp.
DebugEntry, LogEntry
and 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.
As explained before, the default prefix for the entry-calls (DebugEntry, LogEntry
) is ">", for exit-calls (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 ";
Logger.DebugEntry();
...
Logger.DebugExit();
}
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
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