Sunday, December 04, 2005

log4net Context problems with ASP.Net thread agility

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.


[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.

9 comments:

Anonymous said...

That was really helpful. Thank you.

Brian said...

Great post. Thanks

Josh Coady said...

Exactly the info I needed. Thanks!

Btw, do you know if they ever addressed this?

Bojan Bjelic said...

Would you care to provide an through example? Because this ain't working for me...

Anonymous said...

Could you elaborate a little, I don't understand how this works?

What object instance will be used for the ToString() call when a logging method is executed from a different thread?

Won't any object instance you assign to the context slot from the original thread be lost in the same way that any assigned value types are lost when the thread is switched?

Thanks

piers7 said...

@Anonymous: when you use a context provider object as above, you only put it in log4net context once (eg in Application_OnStart), but you put it in the *global* context, so it is then shared by all logging calls from all other threads.

You replace thread-local value storage with global storage of something that can *lookup* the value when ToString() is called

Demanding Dev said...

this is working great for all of my logs throughout my asp.net application life cycle. HOWEVER I have a log enter submitted within an httpModule's httpEndRequest method, and while the log call has the HttpContext.Item values, when my custom object's ToString() method is called AFTER the next thread is being processed, and the ThreadContext.Items is empty.

Any ideas how the resolve this?

piers7 said...
This comment has been removed by the author.
piers7 said...

@DemandingDev yes, implement IFixingRequired on your custom object. I blogged about this here http://piers7.blogspot.com.au/2007/07/log4net-in-aspnet-redux-implement.html

Popular Posts