Logging ClassName and MethodName using log4net for a .NET project

Question

I have been looking for a way to log class names and method names as part of my logging infrastructure. Obviously I'd like to make it simple to use and fast at runtime. I've done a lot of reading about logging class names and method names, but I've run across 2 themes.

1. That log4net uses an internally throws exception to generate a stack frame and that gets expensive if you use that generally for all logging.
2. Confusion. There is a lot of literature out there. I've tried a bunch of it and not gotten to something useful.

If you humor me for a second, I'd like to reset.

I created a class like this in my project

public static class Log {
    private static Dictionary<Type, ILog> _loggers = new Dictionary<Type, ILog>();
    private static bool _logInitialized = false;
    private static object _lock = new object();

    public static string SerializeException(Exception e) {
        return SerializeException(e, string.Empty);
    }

    private static string SerializeException(Exception e, string exceptionMessage) {
        if (e == null) return string.Empty;

        exceptionMessage = string.Format(
            "{0}{1}{2}\n{3}",
            exceptionMessage,
            (exceptionMessage == string.Empty) ? string.Empty : "\n\n",
            e.Message,
            e.StackTrace);

        if (e.InnerException != null)
            exceptionMessage = SerializeException(e.InnerException, exceptionMessage);

        return exceptionMessage;
    }

    private static ILog getLogger(Type source) {
        lock (_lock) {
            if (_loggers.ContainsKey(source)) {
                return _loggers[source];
            }

            ILog logger = log4net.LogManager.GetLogger(source);
            _loggers.Add(source, logger);
            return logger;
        }
    }

    public static void Debug(object source, object message) {
        Debug(source.GetType(), message);
    }

    public static void Debug(Type source, object message) {
        getLogger(source).Debug(message);
    }

    public static void Info(object source, object message) {
        Info(source.GetType(), message);
    }

    public static void Info(Type source, object message) {
        getLogger(source).Info(message);
    }

...

    private static void initialize() {
        XmlConfigurator.Configure(); 
    }

    public static void EnsureInitialized() {
        if (!_logInitialized) {
            initialize();
            _logInitialized = true;
        }
    }
}

(If this code looks familiar it's because it is borrowed from the examples!)

In any case, throughout my project I use lines like this to log:

        Log.Info(typeof(Program).Name, "System Start");

Well, this kind of works. Most importantly, I get the class name but no method name. Less, importantly, I am polluting my code with this "typeof" junk. If I copy and paste a snippet of code between files, etc. the logging framework will be lying!

I tried playing with the PatternLayout (%C{1}.{M}) but that didn't work (all it did was write "Log.Info" to the log--because everything is routing through the Log.X static methods!). Besides, that's supposed to be slow.

So, what is the best way, given my setup and my desire to be simple and fast?

Appreciate any help in advance.

Solution 1

log4net (and NLog) both expose a logging method that makes it possible to "wrap" their loggers and still get correct the call site information. Essentially, the log4net (or NLog) logger needs to be told the Type that forms the "boundary" between logging code and application code. I think they call this the "logger type" or something similar. When the libraries get the call site information, they navigate up the call stack until the MethodBase.DeclaringType is equal (or maybe AssignableFrom) the "logger type". The next stack frame will be the application calling code.

Here is an example of how to log via NLog from within a wrapper (log4net would be similar - look in log4net docs for ILogger (not ILog) interface:

  LogEventInfo logEvent = new LogEventInfo(level, _logger.Name, null, "{0}", new object[] { message }, exception);

  _logger.Log(declaringType, logEvent);

Where declaringType is a member variable that was set something like this:

  private readonly static Type declaringType = typeof(AbstractLogger);

And "AbstractLogger" is the type of your logger wrapper. In your case, it would probably look like this:

  private readonly static Type declaringType = typeof(Log);

If NLog needs to get the call site info (because of call site operators in the layout), it will navigate up the stack until the MethodBase.DeclaringType for the current frame is equal (or AssignableFrom) declaringType. The next frame in the stack will be the actual call site.

Here is some code that will work for logging with a "wrapped" log4net logger. It uses the log4net ILogger interface and passes the type of the "wrapping" logger to preserve the call site information. You don't have to fill in an event class/structure with this method:

  _logger.Log(declaringType, level, message, exception);

Again, "declaringType" is the type of your wrapper. _logger is the log4net logger, Level is the log4net.LogLevel value, message is the message, exception is the exception (if any, null otherwise).

As far as polluting your call sites with Typeof(whatever), I think you are stuck with that if you want to use a single static "Log" object. Alternatively, inside of the "Log" object's logging methods, you could get the calling method like the accepted answer in this post

How can I find the method that called the current method?

That link shows how to get the immediately preceding caller. If you needed to get the method that called the logging function, but your work is being done a couple of layers deeper, you will need to go up the stack some number of frames rather than just one frame.

Taking all of this together, you would write your Debug method something like this (again, this is in terms of NLog because that is what I have in front of me):

public static void Debug(object message)
{
  MethodBase mb = GetCallingMethod();
  Type t = mb.DeclaringType;
  LogEventInfo logEvent = new LogEventInfo(LogLevel.Debug, t.Name, null, "{0}", new object [] message, null);
  ILogger logger = getLogger(t) As ILogger;
  logger.Log(declaringType, logEvent)
}

Note that you probably won't find many people here on StackOverflow that would recommend writing a logging wrapper function like this (that explicitly gets the calling method for ever log call). I can't say that I would recommend it either, but it does more or less answer the question that you asked. If you want to use a static "Log" object, then you will either have to explicitly pass the Type at each logging call site (to get the correct class logger) or you will have to add code inside of the logging call to navigate the stack and figure out that information for yourself. I don't think that either of those options are particularly attractive.

Now, having said all of that, you might consider using either log4net or NLog directly rather than adding this complicated (and not necessarily reliable) code for getting the call site information. As Matthew points out, NLog provides an easy way to get the logger for the current class. To get the logger for the current class using log4net, you would do this in every class:

private static readonly log4net.ILog log = log4net.LogManager.GetLogger( 
        System.Reflection.MethodBase.GetCurrentMethod().DeclaringType); 

vs this way with NLog:

  private static readonly NLog.logger log = NLog.LogManager.GetCurrentClassLogger();

That is a pretty common usage.

If you don't want to be dependent on a particular logging implementation, you could use one of the logging abstractions available such as Common.Logging (NET) or Simple Logging Facade (SLF).

Even if you don't use one of these abstractions, download the source for Common.Logging and look at the abstraction for log4net. It will show exactly how to wrap a log4net logger such that the call site information is preserved (and available to the layout operators).

Solution 2

I prefer a pattern like the following, which works with Log4Net and similar APIs:

class MyClass
{
    private static readonly ILog logger = LogManager.GetLogger(typeof(MyClass));

    void SomeMethod(...)
    {
        logger.Info("some message");

        ...

        if (logger.IsInfoEnabled)
        {
            logger.Info(... something that is expensive to generate ...);
        }
    }

}

Some remarks:

• With this pattern, you are evaluating typeof(MyClass) only once - compared with your sample where you're calling object.GetType() on every logging call, whether or not the corresponding logging level is enabled. Not a big deal, but in general it's desirable for logging to have minimal overhead.

• You still need to use typeof, and make sure you don't get the wrong class name when using copy/paste. I prefer to live with this, because the alternative (e.g. NLog's LogManager.GetCurrentClassLogger as described in Matthew Ferreira's reply) requires getting a StackFrame which has a performance overhead, and requires that the calling code have UnmanagedCode permission. As an aside, I think it would be nice if C# provided some compile-time syntax to refer to the current class - something like the C++ _class_ macro.

• I would abandon any attempt to get the current method name for three reasons. (1) There is a significant performance overhead overhead, and logging should be fast. (2) Inlining means you may not get the method you think you're getting. (3) It imposes the requirement for UnmanagedCode permission.

Solution 3

I also did some research on this and I believe the only way to do this efficiently is to wrap the logging functions, as much as I hate to do so:

public static void InfoWithCallerInfo(this ILog logger, 
    object message, Exception e = null, [CallerMemberName] string memberName = "",
    [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0)
{
    if (!logger.IsInfoEnabled)
        return;
    if (e == null)
        logger.Info(string.Format("{0}:{1}:{2} {3}", sourceFilePath, 
            memberName, sourceLineNumber, message));
    else
        logger.Info(string.Format("{0}:{1}:{2} {3}", sourceFilePath, 
            memberName, sourceLineNumber, message), e);
}

Notes:

• This is the wrapper function I wrote around ILog::Info, you would need one around the other logging levels as well.
• This requires Caller Information which is only available starting .Net 4.5. The up-side is that these variables are replaced at compile-time with string literals, so it's all very efficient.
• For simplicity I left the sourceFilePath parameter as-is, you would probably prefer to format it (trim most/all of its path)

Comments

[wageoghe]

Note that, according to this link (msdn.microsoft.com/en-us/library/…), StackTrace in .NET does indeed requires UnmanagedCode permission. However, according to this link, () StackTrace in Silverlight does not have the same restriction. My point being, if NLog is Silverlight compatible (as the upcoming version 2.0 will be), GetCurrentClassLogger might work just fine in Silverlight (if implemented correctly). As Joe points out, in "regular" .NET or .NET Client Profile, you could indeed run into the UnmanagedCode restriction.

[wageoghe]

Missed pasting the second link above: StackTrace in .NET (msdn.microsoft.com/en-us/library/…) StackTrace in Silverlight (msdn.microsoft.com/en-us/library/…)

[Jeremy Thompson]

This is really good, I'd consider making a pull request in the official repo.