It's fair to say I have a love hate relationship with Logging. I love when logging can help identify the issue - when it's enough but not too much! But I hate when logging code obfuscates the reason of the code. Go on just think back to all those code bases you have seen where littered with Log.Write statements that were clearly put in as the result of a very pressured debug session - not that you would have ever done this of course...

One of the simple things I like to do early on in projects is build in a capability to 'configurably' log method entry and exit within my code base. With parameter details this is more often than not enough for those times when your 'actual' logging isn't giving you enough to diagnose the issue. This allows me to essentially ignore logging at the start of development, as I can use this approach to help diagnose, and steer my 'actual' logging to make it targeted and useful rather than overly verbose and redundant!

I have blogged about this approachbefore (apparently quite a while ago) - but as there have been some significant breaking changes to Interception in Unity v 3.5 and the Enterprise Library v 6 logging application block, I thought a refresh was in order.

This approach is obviously possible and probably just as easy with other containers and logging tools - so there really is no excuse for random Log.Write statements everywhere!

So lets start from scratch - first we are going to add the NuGet package Unity.Interception which will also bring in the Unity package. We create a container and register a simple test interface and implementation.

UnityContainer container = new UnityContainer();
container.RegisterType<ICommand, TestCommand>(); 

We resolve that and execute our test command:

ICommand command = container.Resolve<ICommand>();
command.Execute(); 

Simple - so now we have a container we can look to add the configurable logging capability we want.
We are going to use Enterprise Library for logging and also the configurable policy - so add EnterpriseLibrary.Logging and
EnterpriseLibrary.PolicyInjection packages.

Enterprise Libarary logging needs to be configured, for flexibility I tend to use the Xml configuration approach using the config tool that comes with the full binary download, but it can also be done using a fluent interface. There is plenty of documentation on getting started with the logging application block. Because in this simple approach we are going to use the static LogWriter we need to bootstrap logging after we have configured it by calling:

Logger.SetLogWriter(new LogWriterFactory().Create()); 

Then we need to change the creation of the container to enable the Interception extension:

UnityContainer container = new UnityContainer();
container.AddNewExtension<Interception>();
container.LoadConfiguration(); 

Note that we are loading our external configuration LoadConfiguration - which at this point it will fail as we haven't yet sorted the Unity config (be patient).

We also need to change our registrations to add our interception behaviour - we are just using a simple interface interceptor here as our code will be all interface driven!

container.RegisterType<ICommand, TestCommand>(
	new InterceptionBehavior<PolicyInjectionBehavior>(),
         new Interceptor<InterfaceInterceptor>()); 

Obviously this could make registrations a bit verbose - so you can push this it into an extension method.

The configuration is the only fiddly bit. Unity has a fluent config api so we could add:

            container.Configure<Interception>()
              .AddPolicy("logging")
              .AddMatchingRule<AssemblyMatchingRule>(
                new InjectionConstructor(
                  new InjectionParameter("Library")))
              .AddCallHandler<LogCallHandler>(
                new ContainerControlledLifetimeManager(),
                new InjectionConstructor(
                  9001, true, true,
                  "start", "finish", true, false, true, 10, 1)); 

after the container construction. This configuration adds a policy (called "logging") with an assembly matching rule that intercepts everything from assembly "Library" and uses the LogCallHander (from the policy injection block) to log before and after (check out the constructor of LogCallHandler to see what all those bools and ints do!). Useful, but ideally we want to be able to drop the policy in without code change.

So using UNity design time configuration - we create the following Unity config section:

<unity xmlns="http://schemas.microsoft.com/practices/2010/unity">
    <sectionExtension type="Microsoft.Practices.Unity.InterceptionExtension.Configuration.InterceptionConfigurationExtension, Microsoft.Practices.Unity.Interception.Configuration" /> 

    <container>
      <extension type="Interception" />
      <interception>
        <policy name="logging">
          <matchingRule name="library" type="AssemblyMatchingRule">
            <constructor>
              <param name="assemblyName" value="Library" />
            </constructor>
          </matchingRule>
          <callHandler name="LogHandler" type="Microsoft.Practices.EnterpriseLibrary.Logging.PolicyInjection.LogCallHandler,Microsoft.Practices.EnterpriseLibrary.PolicyInjection">
            <constructor>
              <param name="eventId" value="9001" />
              <param name="logBeforeCall" value="true" />
              <param name="logAfterCall" value="true" />
              <param name="beforeMessage" value="Before" />
              <param name="afterMessage" value="After" />
              <param name="includeParameters" value="true" />
              <param name="includeCallStack" value="true" />
              <param name="includeCallTime" value="true" />
              <param name="priority" value="3" />
            </constructor>
          </callHandler>
        </policy>
      </interception>
    </container>
  </unity> 

  don't forget to add the section definition into configSections:

    <section name="unity" type="Microsoft.Practices.Unity.Configuration.UnityConfigurationSection, Microsoft.Practices.Unity.Configuration"/> 

This is doing the same as our fluent configuration - now you can see the named call handler constructor arguments being passed to the LogCallHandler which is applied as part of the "logging" policy with an assembly matching rule. We can then amend the Enterprise Library logging config to allow capture of parameters.

Now we can simply change the config file to remove the logging policy totally, or introduce more specific matchingRules to target the area of the code base that we haven't logged properly yet!

The more businesses and development organisations I work with, the more I see common problem “themes”. In this series of articles I am trying to highlight the problems and show the potential solutions to some of these common symptoms.

“The team can’t deliver anything!”

“They are always late!”

I usually hear this as a general perception from those outside of the development team or those not involved in the day to day delivery of software.

Perception is reality- so there is a problem. What can we do.

Clarify goals and vision

If the development team can list *loads* of stuff they have done, then it may be that the delivery focus is off – so stuff is going out the door, but it’s not what the business need. Ensure the development goals for the deliveries are clear, valuable, understood and agreed by everyone not just the team. Whilst the development team may care that we are “re-factoring to remove the anti-pattern generic repositories to remove the leaky abstraction” (or whatever) – you know that means nothing to the guy selling it! Make sure the goals and vision mean something.

Advertise

It may be that stuff is actually getting out the door, but no one knows. Obviously you need to make sure people know the team have solved this problem or added that feature. This becomes exponentially easier once you have clarified your goals and vision, ensuring they are aligned with business value and understood by all. In fact ultimately if you can aim to measure progress using delivery of goals and value then advertisement is built in!

Do less to do more

When the team are actually really struggling to ship stuff that needs a bit more investigation. One of the reasons I find often is that teams and even organisations trying to do too many things concurrently. If the team can list 50 projects that they are working on, chances are they aren’t going to deliver any of them to time as they are spending most of their time multiplexing. Kanban tells us to limit the amount of work in play to maximise the output. This works in small scale for the team’s day to day work or in larger scale for the organisational release planning. For me this is all about focus, start with one thing - the most important – complete it, then move onto the next. Only attempt to do more stuff in parallel when you have learned how to deliver successfully – even then be mindful not to fall back into the trap of trying to do too much…