How to set log4net context property specific to an ASP.NET request?

Question

I've been using log4net to log our ASP.NET web site's log messages, and lately I wanted to add information about the page/handler where the error happened. I decided therefore to add the following line to Global.asax:

void Application_BeginRequest(object sender, EventArgs e)
{
    log4net.ThreadContext.Properties["page"] = HttpContext.Current.Request.AppRelativeCurrentExecutionFilePath;
}

and like wise I added %property{page} to my conversion pattern:

<conversionPattern value="%newline%date %-5level %property{page} - %message%newline%newline%newline" />

This worked fine for single requests. But then I noticed in my logs that the page property may change during an ASP.NET request. I have logging in one ASHX handler, and in the midst of its processing, the page property would change to a different value that points to an ASPX page. I concluded that there is another request coming to ASP.NET and its BeginRequest gets executed and the static page property in log4net.ThreadContext gets changed to another value.

Now, I would like to maintain the page property per request, so that I can have the path of the executing page logged to the log consistently. I tried to find an answer, but I came out with nothing. What is the recommended way to solve this problem? I'm sure this is very basic functionality of web server event logging.

Answer 1

Store property value in ASP.NET context HttpContext.Current.Items.Add("yourProperty", value) It will be available from log4net layout:

<layout type="log4net.Layout.PatternLayout">
   <conversionPattern value="%aspnet-context{yourProperty}" />
</layout>

Find more detail here.

Answer 2

Since ASP.NET does not guarantee that the entire page request will be processed on the same thread, I prefer getting the answer from HttpContext.Current as log4net processes the logging event.

The following GetCurrentPage class implements what the log4net manual calls an "Active Property Value" by overriding its ToString method:

public class GetCurrentPage
{
  public override string ToString()
  {
      if (null != HttpContext.Current)
      {
          return HttpContext.Current.Request.AppRelativeCurrentExecutionFilePath;
      }
      return string.Empty; // or "[No Page]" if you prefer
  }
}

Register this class in Global.asax's Application_Start in log4net's GlobalContext.

protected void Application_Start(object sender, EventArgs e)
{
    XmlConfigurator.Configure();
    GlobalContext.Properties["page"] = new GetCurrentPage();
}

When log4net writes the %property{page} part of the line it will call the ToString method of our GetCurrentPage class which will lookup the value in the current request.

Answer 3

Have you tried using Application_PostAcquireRequestState instead of Application_BeginRequest as outlined in this article? How can I include SessionID in log files using log4net in ASP.NET?

We have never felt the need to add the page to the logging since we create our logger in each class with the method name:

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

and have a conversion pattern like this:

<conversionPattern value="%date %P{user} %P{addr} [%property{SessionID}] %level %logger - %message%newline" />

So we end up seeing the class name in the log output. This also lets you differentiate whether the logging happened in the page class file itself, vs. a base class it inherits from. Your solution would have the advantage of showing the page name even when the code is executing in the base class. I think we will look at adding {page} to our setup.