log4net Contextual Properties and ASP.NET

December 12, 2011

Probably most of you know and use the log4net library, which is a logging framework for the .NET platform. log4net is a great and practical tool, easy to use and at the same time flexible enough, so that you can tailor it to your more advanced logging scenarios. Most users of this library will sooner or later get acquainted with the possibility to store contextual data, which is then used when your messages are logged. Such data might be for example: the name of currently logged in user or the URL of the request.

As it turns out more often than not in our profession, not everything is as simple as it seems. Collection of contextual properties, which are bound to currently executing thread, that is ThreadContext.Properties because that's what we're talking about, is practically of no use in a web environment, if we want to utilize it in a standard way. By the standard way I mean the ordinary act of adding new items to the collection:

log4net.ThreadContext.Properties["UserName"] = Thread.CurrentPrincipal.Identity.Name;

If we make such assignment inside, for example, the Application_BeginRequest event, we expect, quite reasonably, that later in the process, every use of a logger will store our information and, what's more, this information will be bound to this specific request. Unfortunately, semantics of this collection will not guarantee this in a web environment due to so called thread agility employed by the ASP.NET runtime. What does it mean exactly? I guess it might be a surprise for you, as it was for me when I first found out about this, that a single HTTP request to a ASP.NET application may be handled by multiple threads during its life cycle (!).

In the context of log4net library, switching threads while processing a single request means, that we can't rely on the values stored in the ThreadContext.Properties collection. The way this collection is implemented along with the ASP.NET runtime's thread agility won't guarantee us that proper values will get passed to the new thread. As a result, if we happen to have a bug in our production system and we would want to analyze the path that a particular user took, we can assume with high probability, that this information will be distorted.

There is, however, a workaround for this problem. Namely, in ASP.NET there is one collection, for which we have guarantees, that its contents (bound to a particular request) will stay intact even after switching to a new thread. It's the HttpContext.Items collection. I'd like to show you the implementation of the solution based on this collection, that you should be able to effortlessly use in your own applications.

The main idea of this solution is to create a wrapper for values that we want to store in the ThreadContext.Properties. That way, at the moment log4net retrieves those values to log a message, our object can decide, whether this value should be taken from HttpContext.Items collection (if we're in a web environment) or whether the original value should be returned.

I called the class AdaptivePropertyProvider<T>. Its code is presented below:

public class AdaptivePropertyProvider<T>
{
  private readonly string _propertyName;
  private readonly T _propertyValue;

  #region Constructor(s)

  protected internal AdaptivePropertyProvider(string propertyName, T propertyValue)
  {
    if (string.IsNullOrEmpty(propertyName))
    {
      throw new ArgumentNullException("propertyName");
    }

    _propertyName = propertyName;
    _propertyValue = propertyValue;

    if (HttpContext.Current != null)
    {
      HttpContext.Current.Items[GetPropertyName()] = propertyValue;
    }
  }

  #endregion

  #region Overrides of object

  public override string ToString()
  {
    if (HttpContext.Current != null)
    {
      var item = HttpContext.Current.Items[GetPropertyName()];

      return item != null ? item.ToString() : null;
    }

    if (!ReferenceEquals(_propertyValue, null))
    {
      return _propertyValue.ToString();
    }

    return null;
  }

  #endregion

  #region Private helper methods

  private string GetPropertyName()
  {
    return string.Format("{0}{1}", AdaptivePropertyProvider.PropertyNamePrefix, _propertyName);
  }

  #endregion
}

It's worth noting that the logic of retrieveing a value is placed in the ToString() method. Here we exploit the fact, that log4net itself uses this method for formatting objects stored in the Properties collection.

For convenience let's define a second class, which will expose a factory method for constructing objects of class AdaptivePropertyProvider<T>.

public class AdaptivePropertyProvider
{
  public const string PropertyNamePrefix = "log4net_app_";

  #region Factory methods

  public static AdaptivePropertyProvider<T> Create<T>(string propertyName, T propertyValue)
  {
    return new AdaptivePropertyProvider<T>(propertyName, propertyValue);
  }

  #endregion
}

Usage of such factory method allows the compiler to infer the appropriate type of the property value (that's not the case with ordinary constructors — we can't omit generic type parameters).

log4net.ThreadContext.Properties["UserName"] =
  AdaptivePropertyProvider.Create("UserName", Thread.CurrentPrincipal.Identity.Name);

By remembering the lesson that we should keep contextual properties in a way described above, we should be able to avoid unpleasant surprises during analysis of production logs in a time of crisis :]


Downloads:

References:

1 comment: