Even after my recent revalations about
how ASP.Net's agile threading model precudes storing things in threadslots, ThreadStatic's or CallContext almost without exception[1], it still took me until just the other day to realize an important ramification of that:
log4net contexts are broken[2] under ASP.Net
A
log4net context is a bag where you can put data that can be referenced by the log4net appenders when the logging calls are rendered. This supports the model where you just publish logging data that's relevant to your immediate scope, and the log4net renderer (based on the pattern you put in your config) just appends all the extra data that you probably want to log (like the CustomerID who's logged in or somesuch).
There are three log4net contexts:
GlobalContext,
ThreadContext and
LogicalThreadContext, which do pretty much what you'd expect - provide places to hang contextual data for logging calls that's either global, thread-local or 'logical call' local (ie propagates across remoting calls). Unfortunately that's just not good enough in an ASP.Net environment, since we now know that neither CallContext nor Thread Local Storage slots get propagated onto the new thread when ASP.Net does a thread switch. Since that's where the ThreadContext and LogicalThreadContext are actually stored, ASP.Net's thread switch either blows away your context (in the case of LogicalThreadContext), or overwrites it (in the case of ThreadContext).
There's nothing fundamentally wrong with log4net, it's just you
can't use log4net's ThreadContext or LogicalThreadContext within ASP.Net and expect to get a per-request logging context, though you'd be forgiven for imagining otherwise.
Demo: Storing the requested page URL in ThreadContext, so it's liable to be overwritten if a thread switch happens because two requests come in concurrently:
[3164] INFO ASP.global_asax /ASPNetThreadingDemo/SlowPage.aspx - Begin request for /ASPNetThreadingDemo/SlowPage.aspx
[3164] INFO ASP.global_asax /ASPNetThreadingDemo/SlowPage.aspx - End request for /ASPNetThreadingDemo/SlowPage.aspx
[1996] INFO ASP.global_asax /ASPNetThreadingDemo/SlowPage.aspx - Begin request for /ASPNetThreadingDemo/SlowPage.aspx
[3164] INFO ASP.global_asax /ASPNetThreadingDemo/FastPage.aspx - Begin request for /ASPNetThreadingDemo/FastPage.aspx
[1996] INFO ASP.global_asax /ASPNetThreadingDemo/SlowPage.aspx - End request for /ASPNetThreadingDemo/SlowPage.aspx
[1996] INFO ASP.global_asax /ASPNetThreadingDemo/SlowPage.aspx - End request for /ASPNetThreadingDemo/FastPage.aspx
See how the last logging call has 'SlowPage' in context, even though the request that's finishing is actually for 'FastPage' (I was expecting exactly the reverse, but hey).
It's pretty ironic really, since it was log4net I used to confirm how the threading really worked in the first place, but of all the things I looked at, log4net contexts wasn't one of them. Trouble is, if you're using log4net contexts in ASP.Net this is
exactly the kind of thing you'd[3] be doing: setting things up in BeginRequest so they're there for all logging calls throughout the system.
The Workaround:
Fortunately log4net's so flexible that it already contains the solution. For all the contexts, log4net supports the concept of delayed resolution of the context value. To be more specific, log4net gets the context value by calling
ToString() on the contents of the context bags when they're frozen and attached to a logging call. If rather than adding the actual value, you add an object who's
ToString() provides the value, then you've deferred resolution of what the actual value was.
So in this case, rather adding the value of CustomerID directly into the ThreadContext, you'd add a CustomerIdProvider object instead:
Public Class CustomerIdProvider
Public Overrides Function ToString() As String
Return HttpContext.Current.Items("CustomerId")
End Function
End Class
Since this now leverages HttpContext, you can put it in GlobalContext as well - it's automatically thread-safe.
It's a bit of a drag, but you're going to have to do this for
all your non-global log4net context data[4]. It's pretty easy to generalise the class above into an all-purpose HttpContextValueProvider though, so you won't have to spawn a myriad of classes.
The Solution:
log4net's going to have to have an AdaptiveContext. This is a context bag that's stored
either in CallContext or in HttpContext, depending on the environment that the application is running within. I'm already doing this for anything I previously put in CallContext in my business layer, but I haven't got round to grafting one onto log4net yet.
[
Update: I posted a follow-up post about
the need to also implement IFixingRequired - please read. Also, please note the date on this post is
2005, I don't claim this as all current information. YMMV]
[1] Ok, if you don't store anything in TLS / CallContext prior to Page.Init, then you'll be ok (given the current implementation anyway).
[2] ...depending on how you're using them
[3] I.E. 'me, until I realised all this'
[4] Despite all this, log4net's still the best logging framework I know of by far.
Posts
