Tuesday, April 7, 2009

Capturing context data using log4net

It was a little bit of trial and error to get this working, so I thought I would post the code.

The problem we were trying to solve was this: we wanted to track which batch job was logging the given message. In our situation, each job is a separate class. Each job had its own unique ID number. So, we needed to use some context to determine which job logged the message.

Here is the solution we came up with. First we created a custom attribute to hold the metadata we needed:
public class BatchJobAttribute : Attribute
public int ProcessorId { get; private set; }
public BatchJobAttribute(int processorId)
ProcessorId = processorId;

For each processor class, we add this attribute:
class SampleProcessor

Note: It would be very nice to use an enum instead of magic numbers. This would be a fairly simple change.

Then we created a context class. The ToString() method on this class is called each time a message is logged. In this method, the code walks up the stack trace looking for a class that has the custom attribute. Please note, this is using reflection and is called every time a message is logged, so be careful in performance critical situations. This particular situation was for off-line processing, so performance was not as critical.

class ProcessorContext
private const string UnknownValue = "-1";

public override string ToString()
StackTrace stackTrace = new StackTrace(false);
foreach (var frame in stackTrace.GetFrames())
var type = frame.GetMethod().ReflectedType;
var attributes = type.GetCustomAttributes(typeof(BatchJobAttribute), false);
if (attributes.Length > 0)
var procAtt = (ProcessorAttribute)attributes[0];
return procAtt.ProcessorId.ToString();
return UnknownValue;

Finally, when configuring log4net at application start, we add the context class as a thread context property. This is what causes log4net to call the ToString() method on each call.

log4net.ThreadContext.Properties["ProcessorContext"] = new ProcessorContext();

In the configuration of the adapter, we add a pattern layout to display this property:

<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} %property{ProcessorContext} %m%n" />

And there you go. Hopefully this will be helpful to someone else. Please keep in mind there are other solutions that may work better in your specific scenario. One good option would be the context stacks described in this article. Another option would be to simply use the class name which is already part of the metadata captured by log4net.

Good luck!

Monday, April 6, 2009

Training Update 2

I finally decided on which triathlon I'm going to do. I'm registered for the Eastman Splash, Mash and Dash Triathlon in Grantham, New Hampshire. It is a 1/3 mile swim, a 12 mile bike ride and a 5k run.

The race is 11 weeks away now and I have started a training schedule. I looked around on the interwebs and found a couple training schedules for sprint triathlons. The schedules seemed a little wimpy to me. I don't really consider a sprint triathlon wimpy, but these training programs had training days that would consist of a 12 minute run. Some schedules even worked up to running by including walking days. So, instead I decided to overtrain. I know, I know, overtraining is bad. I'm increasing the chance of injury. I just felt I wanted more of a challenge than the training programs I had found.

I took a training schedule for an olympic triathlon and adapted it slightly. The schedule was balanced, meaning it did not stress any one of the 3 sports. The only thing I changed was that the swim times seemed quite long, so I halved them. Even halving the swim practices, the shortest swim practice is longer than I think it will take me in the actual race.

A couple months ago I made up some goals for myself. I really didn't have much to base my goals on, so I found some data on the web and chose average times for my age group. Now that I've been training a little bit, I can get an idea of how close I am to those relatively arbitrary goals.

My swim goal was to shoot for 1 minute per 50 yards. For 1/3 mile, that is just under 12 minutes. I timed myself in the pool a couple days ago and I swam 1/3 mile in a little over 13 minutes. I tried not to push off too much on the turns, but open water is going to be significantly different. My swim started at a decent pace, but I slowed at the end. With a little more endurance I think the swim goal will be reached, at least in a pool, without people kicking me in the head.

My bike goal was to average 15 MPH. For a 12 mile course, that would be around 45 minutes. I think this goal is going to be difficult. I went for a ride today and averaged 12 miles an hour. The bike is still quite difficult for me, I don't think I have my bike muscles back yet from the winter.

My running goal was to run at a pace of 7:30. Right now that seems a little ridiculous. I'm finally feeling like I'm back to my normal speed before taking a break from training over the winter. My last run felt great. The course I ran is quite hilly and longer than the race distance. I averaged an 8:42 pace. I have a serious amount of time to make up if I want to meet my goal.

Well, at least my goals are stretch goals. I may have to adjust my training as I go. I may swap out a couple swiming sessions for biking or running.

Okay, that's it for now.