Ever have one of those third party libraries that you love but it’s missing that one feature or one piece of syntactical candy that would make it so much more useful? This, I truly think, is one of the best uses of extension methods.
I began discussing extension methods in my last post (which you find here) where I expounded upon what I thought were some rules of thumb for using extension methods correctly. As long as you keep in line with those (or similar) rules, they can often be useful for adding that little extra functionality or syntactical simplification for a library that you have little or no control over.
Oh sure, you could take an open source project, download the source and add the methods you want, but then every time the library is updated you have to re-add your changes, which can be cumbersome and error prone. And yes, you could possibly extend a class in a third party library and override features, but that’s only if the class is not sealed, static, or constructed via factories.
This is the perfect place to use an extension method! And the best part is, you and your development team don’t need to change anything! Simply add the using for the namespace the extensions are in!
So let’s consider this example. I love log4net! Of all the logging libraries I’ve played with, it, to me, is one of the most flexible and configurable logging libraries and it performs great. But this isn’t about log4net, well, not directly. So why would I want to add functionality? Well, it’s missing one thing I really want in the ILog interface: ability to specify logging level at runtime.
For example, let’s say I declare my ILog instance like so:
using log4net;
public class LoggingTest
{
private static readonly ILog _log = LogManager.GetLogger(typeof(LoggingTest));
...
}If you don’t know log4net, the details aren’t important, just to show that the field _log is the logger I have gotten from log4net.
So now that I have that, I can log to it like so:
log.Debug("This is the lowest level of logging and just for debugging output.");
_log.Info("This is an informational message. Usual normal operation events.");
_log.Warn("This is a warning, something suspect but not necessarily wrong.");
_log.Error("This is an error, some sort of processing problem has happened.");
_log.Fatal("Fatals usually indicate the program is dying hideously.");And there’s many flavors of each of these to log using string formatting, to log exceptions, etc. But one thing there isn’t: the ability to easily choose the logging level at runtime. Notice, the logging levels above are chosen at compile time. Of course, you could do some fun stuff with lambdas and wrap it, but that would obscure the simplicity of the interface. And yes there is a Logger property you can dive down into where you can specify a Level, but the Level properties don’t really match the ILog interface exactly and then you have to manually build a LogEvent and… well, it gets messy. I want something simple and sexy so I can say:
_log.Log(someLevel, "This will be logged at whatever level I choose at runtime!");
Now, some purists out there might say you should always know what level you want to log at, and for the most part I agree with them. For the most party the ILog interface satisfies 99% of my needs. In fact, for most application logging yes you do always know the level you will be logging at, but when writing a utility class, you may not always know what level your user wants.
I’ll tell you, one of my favorite things is to write reusable components. If I had my druthers I’d write framework libraries and shared components all day! And being able to easily log at a runtime-chosen level is a big need for me. After all, if I want my code to really be re-usable, I shouldn’t force a user to deal with the logging level I choose.
One of my favorite uses for this is in Interceptors — I’ll describe Interceptors in my next post and some of my favorites — for now just know that an Interceptor wraps a class and allows you to add functionality to an existing method without changing it’s signature. At the risk of over-simplifying, it’s a very generic implementation of the Decorator design pattern.
So, say for example that you were writing an Interceptor that would time method calls and emit a log message if the method call execution time took beyond a certain threshold of time. For instance, maybe if your database calls take more than 5,000 ms, you want to log a warning. Or if a web method call takes over 1,000 ms, you want to log an informational message. This would be an excellent use of logging at a generic level.
So here was my personal wish-list of requirements for my task:
- Be able to determine if a runtime-specified logging level is enabled.
- Be able to log generically at a runtime-specified logging level.
- Have the same look-and-feel of the existing Debug, Info, Warn, Error, and Fatal calls.
Having the ability to also determine if logging for a level is on at runtime is also important so you don’t spend time building a potentially expensive logging message if that level is off. Consider an Interceptor that may log parameters on entrance to the method. If you choose to log those parameter at DEBUG level and if DEBUG is not on, you don’t want to spend the time serializing those parameters.
Now, mine may not be the most elegant solution, but it performs really well since the enum I provide all uses contiguous values — while it’s never guaranteed, contiguous switch values usually get compiled into a jump table in IL which is VERY performant – O(1) – but even if it doesn’t, it’s still so fast you’d never need to worry about it.
So first, I need a way to let users pass in logging levels. Sure, log4net has a Level class, but it’s a class with static members and plus it provides way too many options compared to ILog interface itself — and wouldn’t perform as well in my level-check — so I define an enum like below.
namespace Shared.Logging.Extensions
{
// enum to specify available logging levels.
public enum LoggingLevel
{
Debug,
Informational,
Warning,
Error,
Fatal
}
}Now, once I have this, writing the extension methods I need is trivial. Once again, I would typically /// comment fully, but I’m eliminating for blogging brevity:
namespace Shared.Logging.Extensions
{
// the extension methods to add functionality to the ILog interface
public static class LogExtensions
{
// Determines if logging is enabled at a given level.
public static bool IsLogEnabled(this ILog logger, LoggingLevel level)
{
switch (level)
{
case LoggingLevel.Debug:
return logger.IsDebugEnabled;
case LoggingLevel.Informational:
return logger.IsInfoEnabled;
case LoggingLevel.Warning:
return logger.IsWarnEnabled;
case LoggingLevel.Error:
return logger.IsErrorEnabled;
case LoggingLevel.Fatal:
return logger.IsFatalEnabled;
}
return false;
}
// Logs a simple message - uses same signature except adds LoggingLevel
public static void Log(this ILog logger, LoggingLevel level, object message)
{
switch (level)
{
case LoggingLevel.Debug:
logger.Debug(message);
break;
case LoggingLevel.Informational:
logger.Info(message);
break;
case LoggingLevel.Warning:
logger.Warn(message);
break;
case LoggingLevel.Error:
logger.Error(message);
break;
case LoggingLevel.Fatal:
logger.Fatal(message);
break;
}
}
// Logs a message and exception to the log at specified level.
public static void Log(this ILog logger, LoggingLevel level, object message, Exception exception)
{
switch (level)
{
case LoggingLevel.Debug:
logger.Debug(message, exception);
break;
case LoggingLevel.Informational:
logger.Info(message, exception);
break;
case LoggingLevel.Warning:
logger.Warn(message, exception);
break;
case LoggingLevel.Error:
logger.Error(message, exception);
break;
case LoggingLevel.Fatal:
logger.Fatal(message, exception);
break;
}
}
// Logs a formatted message to the log at the specified level.
public static void LogFormat(this ILog logger, LoggingLevel level, string format,
params object[] args)
{
switch (level)
{
case LoggingLevel.Debug:
logger.DebugFormat(format, args);
break;
case LoggingLevel.Informational:
logger.InfoFormat(format, args);
break;
case LoggingLevel.Warning:
logger.WarnFormat(format, args);
break;
case LoggingLevel.Error:
logger.ErrorFormat(format, args);
break;
case LoggingLevel.Fatal:
logger.FatalFormat(format, args);
break;
}
}
}
}So there it is! I didn’t have to modify the log4net source code, so if a new version comes out, i can just add the new assembly with no changes. I didn’t have to subclass and worry about developers not calling my sub-class instead of the original. I simply provide the extension methods and it’s as if the long lost extension methods were always a part of the ILog interface!
Consider a very contrived example using the original interface:
// using the original ILog interface
public class DatabaseUtility
{
private static readonly ILog _log = LogManager.Create(typeof(DatabaseUtility));
// some theoretical method to time
IDataReader Execute(string statement)
{
var timer = new System.Diagnostics.Stopwatch();
// do DB magic
// this is hard-coded to warn, if want to change at runtime tough luck!
if (timer.ElapsedMilliseconds > 5000 && _log.IsWarnEnabled)
{
_log.WarnFormat("Statement {0} took too long to execute.", statement);
}
...
}
}Now consider this alternate call where the logging level could be perhaps a property of the class
// using the original ILog interface
public class DatabaseUtility
{
private static readonly ILog _log = LogManager.Create(typeof(DatabaseUtility));
// allow logging level to be specified by user of class instead
public LoggingLevel ThresholdLogLevel { get; set; }
// some theoretical method to time
IDataReader Execute(string statement)
{
var timer = new System.Diagnostics.Stopwatch();
// do DB magic
// this is hard-coded to warn, if want to change at runtime tough luck!
if (timer.ElapsedMilliseconds > 5000 && _log.IsLogEnabled(ThresholdLogLevel))
{
_log.LogFormat(ThresholdLogLevel, "Statement {0} took too long to execute.",
statement);
}
...
}
}Next time, I’ll show one of my favorite uses for these extension methods in an Interceptor.
