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.


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

14 comments:

Anonymous said...

That was really helpful. Thank you.

Anonymous said...

Great post. Thanks

Anonymous said...

Exactly the info I needed. Thanks!

Btw, do you know if they ever addressed this?

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

@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

urig said...

The accepted answer to this StackOverflow.com question presents an alternative approach where the "adaptive" context is actual the log4net %properties collection: http://stackoverflow.com/questions/9702066/how-to-set-log4net-context-property-specific-to-an-asp-net-request#9789629

Frédéric Delaporte said...

Great solution, but a little issue remains : this does not work with buffering appenders as AdoNetAppender, when buffer size is greater than one.
In their case, your proposed provider gets evaluated only at buffer flush time, causing it to use the http context of the request having caused the flush, defeating the whole purpose of the provider.

Fortunately, it appears little is required to fix this point: the provider just have to implement IFixingRequired from log4net.Core.

As an example, here is my own provider:

public class HttpContextValueProvider : IFixingRequired
{
private string _contextKey;
public HttpContextValueProvider(string contextKey)
{
_contextKey = contextKey;
}

public override string ToString()
{
var currContext = HttpContext.Current;
if (currContext == null)
return null;
var value = currContext.Items[_contextKey];
if (value == null)
return null;
return value.ToString();
}

object IFixingRequired.GetFixedObject()
{
return ToString();
}
}

piers7 said...

@Frédéric - yes, you will need IFixingRequired. I posted a follow up about this here http://piers7.blogspot.com.au/2007/07/log4net-in-aspnet-redux-implement.html

Frédéric Delaporte said...

Yes, I had not seen your follow up, thanks for pointing it.
Now I am back about a recent change in log4net (released November 2015, v1.2.14) for supporting async/await case with LogicalThreadContext. (Yes I have, quickly, searched if you have already posted another follow up, and not found some.)

Maybe it also fixes the context loss issue with asp.net thread agility.
Here is the link to the issue: https://issues.apache.org/jira/browse/LOG4NET-455
(Log4net release notes : http://logging.apache.org/log4net/release/release-notes.html)

I have unfortunately not the knowledge to infer this from the information I found there. Informations on technical detail on how asp.net thread agility works and what may work to preserve some king of context looks sparse.

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

Hi Frédéric,

That's a great question, and thanks for the link - I wasn't aware that feature had been implemented in log4net.

Short answer: not sure. I think it depends more on what ASP.Net propagates onto it's worker thread than how Log4Net is setup, *unless* in the meantime LogicalThreadContext adaptively uses HttpContext if available (which I don't think it does).

Been a long time since I looked at any of this so take all this with some scepticism.

Cheers,

Popular Posts