Logging Method Entry and Exit Points Dynamically

• Download source - 661.5 KB
• Download demo project - 114.8 KB

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 "&lt", 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.

EntryPrefix & ExitPrefix

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 (2^nd parameter) and one by one appending a space, followed by appending the string representation of the object to the StringBuilder instance passed (1^st 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 (3^rd parameter) followed by a appending the method name (4th parameter) to the StringBuilder instance passed (1^st 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

• 2^nd January, 2015: Initial version
• 3^rd January, 2015: Corrected typos