Log4Net Active Property Values via Lamdas

Some years ago I wrote a couple of posts on some nasty problems that you could encounter if using log4net contexts in an environment where you didn’t control the thread lifecycle, say ASP.Net. Judging by the amount of coverage it got at the time (and still) I wasn’t the only person caught out by this.

Anyway I was doing something similar recently, not in ASP.Net, but in a Windows Service application with lots of threads. It’s the same kind of problem: there’s some thread-specific context that always exists, which we want to make available to log4net, but putting it in ThreadLocalContext doesn’t really work very well because we’d have to set them up in all our thread-entry methods, which would be everywhere where a callback gets entered – very messy in our (highly asynchronous) application.

Instead I wanted to put something in log4net’s GlobalContext that resolved to the thread’s context value. And actually now we’ve got lamdas and all that nice stuff, I was able to come up with a significantly neater implementation for a general-purpose contextual logging property, which basically answers the original ASP.Net problem too:

 

    /// <summary>

    /// Implements a class that can be used as a global log4net property

    /// to resolve an action to a string at event-fixing-time

    /// </summary>

    /// <remarks>With a suitable lamda expression, you can put this

    /// into your log4net.GlobalContext to resolve at logging time to a variety

    /// of stuff you might want to use in your logging statements.

    /// <example>Using threadId (not thread Name) as a property:<code>

    /// log4net.GlobalContext.Properties["threadId"] =

    /// new Log4NetContextProperty(() => Thread.CurrentThread.ManagedThreadId.ToString());

    /// </code></example>

    /// </remarks>

    public class Log4NetContextProperty : IFixingRequired

    {

        private readonly Func<string> _getValue;

 

        public Log4NetContextProperty(Func<string> getValue)

        {

            _getValue = getValue;

        }

 

        public override string ToString()

        {

            return _getValue();

        }

 

        public object GetFixedObject()

        {

            return ToString();

        }

    }

In this case I wanted ‘threadId’ as a logging property (log4net exposes thread name, which is normally fine, but the R# test runner creates woppingly long thread names that basically hide the actual logging message, and I really just wanted the IDs (hence the example above). But you can see how you can basically use this to expose any context data to log4net if you wanted to.

Log4net in Asp.Net redux: Implement IFixingRequired on your Active Property Values

A while back I noted that the built-in contexts in log4net were broken in the face of ASP.Net's thread agility (and pointed this out to the log4net community).

The workaround I suggested, which was also suggested on the log4net developers list, was to leverage log4net's support for deferred evaluation of logging properties. These are known as Active Property Values, but that's just a fancy/short way of saying 'any object you like, who's ToString() method results in the value that you actually want logged'. This was a pretty neat workaround, eg:

      log4net.GlobalContext.Properties["requestUrl"] = new HttpContextRequestUrlProvider();

    private class HttpContextRequestUrlProvider
    {
        public override string ToString()
        {
            HttpContext context = HttpContext.Current;
            if (context == null) return null;
            return context.Request.RawUrl;
        }
    }

However in one of my logging databases, I recently noticed logging entries attributed to me that had clearly come from someone else, which made me worry for a few hours whether this pattern was broken, or broken when using an appender that buffers (like the AdoNetAppender).

Digging through the source code showed that BufferingAppenderSkeleton does indeed attempt to 'fix' logging entries when they go into the buffer, to guard against exactly these kind of multithreading logging mishaps:

 // Because we are caching the LoggingEvent beyond the
// lifetime of the Append() method we must fix any
// volatile data in the event.
loggingEvent.Fix = this.Fix;

This causes all kinds of intrinsic log4net values (like thread ID, UserName), and the message itself to be 'fixed': i.e. fully evaluated (and rendered via the layout) now, rather than later. Otherwise all the logging events in the buffer would end up being written out with the values in-play at the time the appender flushed (ie potentially another thread/users's context).

This fixing also 'fixes' properties from the log4net contexts (ThreadContext, LogicalThreadContext and GlobalContext) if they implement IFixingRequired. And that's what I missed - one obscure interface:

 // Fix any IFixingRequired objects
IFixingRequired fixingRequired = val as IFixingRequired;
if (fixingRequired != null)
{
 val = fixingRequired.GetFixedObject();
}

But I've missed that for the last couple of years. So… actually I'd rather not think about the implications of that. Meanwhile, if anyone who does any log4net dev would actually like to update the Active Property Value doco, that'd be good, thanks.

Better still, 18 months later, can we have our Adaptive Context now please?

Using Log4Net's FileAppender in a web garden

Whilst you might not think you're running a web garden (that is: running your website in two or more processes simultaneously on the same machine), it's worth checking in case your server SOE catches you by surprise (hint: this happened to me):



Obviously in this scenario it's not just log4net you've got to watch out for, but anything you're saving on the local filesystem is a candidate for cross-process resource contention. In log4net's case, the RollingFileAppender can block itself (in the other process).

There's a couple of ways round this. You can configure the FileAppender to minimize the amount of time it locks the file (the MinimalLock attribute), but for diagnostic simplicity I prefer to configure each web application instance to log to a different file. Something like this:

 <appender name="File" type="log4net.Appender.RollingFileAppender">
  <file type="log4net.Util.PatternString" value="C:\temp\MyApp_[%processid].log" />
  <datePattern value="yyyyMMdd"/><!--roll the file daily-->
  <rollingStyle value="Date"/>
  <appendToFile value="true"/>
    
  <layout type="log4net.Layout.PatternLayout">
   <conversionPattern value="%date{ABSOLUTE} [%thread] %-5level %logger.%method() - %message [%identity]%newline" />
  </layout>
 </appender>

This way if anything screwy happens in one of the instances (it didn't start alltogether?) it's easier to isolate.

PS: Blogger is so not the right engine to be doing this XML stuff in...

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.