Tue
Apr 17
2007

Log4Net + ASP.Net

In web applications, Log4Net’s ThreadContext properties (typically items like the current user) should be set immediately before each logging call.

Normally these properties are set in Global.Session_Start(). However, log4net internally stores these properties in thread local storage. Using Reflector to disassemble log4net.dll (v1.2.10), start with log4net.ThreadContext which leads to ThreadContextProperties.get_Item() and then to ThreadContextProperties.GetProperties(). The disassembly for this method:

internal PropertiesDictionary GetProperties(bool create)
{
    PropertiesDictionary data;
    data = (PropertiesDictionary) Thread.GetData(s_threadLocalSlot);
    if ((data == null) && create)
    {
        data = new PropertiesDictionary();
        Thread.SetData(s_threadLocalSlot, data);
    }
    return data;
}

The call to Thread.GetData() is the problem. ASP.Net, when under load, may switch threads when processing a single request (see ThreadStatic, CallContext and HttpContext in ASP.Net). You may initialize log4net with the current user on one thread, then attempt to log on a different thread. Log4net.LogicalThreadContext() suffers a similar problem as it uses CallContext to store its data rather than HttpContext.

For reliable logging information, set these ThreadContext properties each time you log an entry. The additional processing time will be negligable in most cases. Further, as a general rule of thumb, use HttpContext to store request-specific information in ASP.Net applications.

10 minutes after finishing this post I come across this post, also from piers7:
log4net Context problems with ASP.Net thread agility. It suggests another workaround.

Leave a reply

© 2009 Brian Low. All rights reserved.