Detailed logging using interceptors (AOP)

...now available on Episerver nuget feed!

Background

Most development time in large projects is spent on integrations. Most time on integrations are spent on trying to figure out what is really going on, what is sent and what is received and how long it took. Adding logging code with log4net for this is pretty boring if you have a large solution. There will be a lot of copy paste. Another way to solve it is adding a new layer above the class you want to log (typically a repository type of class) that handles this. You can do this using the decorator pattern but still it's a lot of copy/paste. Boring! Enter interceptors and AOP to the resque...

How to use it

1. Install nuget package for logging interceptor. It's available on the Episerver nuget feed for Episerver version 9+. 
If you feel more confident adding the code directly into your project or want to know how it was built, feel free to copy/paste from Github here. It uses the same castle component in the background for the magic as Episerver uses for building parts of the CMS fyi.

2. Configure what classes to log 

Let's add some logging to our sample NewsRepository class. You only need to modify the ioc container. By default it's in the DependencyResolverInitialization class and add:

container.For<INewsRepository>().Use<NewsRepository>();
container.RegisterInterceptor<INewsRepository>(new LoggingInterceptor());

This will add the logging interceptor in a layer above the actual NewsRepository.

3. Turn on log4net logging

Logging is on info level so you need to turn that on since it's on error level by default. There are a couple of ways to do this by modifying EpiserverLog.config. One is adding:

<appender name="debugFileLogAppender" type="log4net.Appender.RollingFileAppender" >
    <!-- Consider moving the log files to a location outside the web application -->
    <file value="App_Data\Debug.log" />
    <encoding value="utf-8" />
    <staticLogFileName value="true"/>
    <datePattern value=".yyyyMMdd.'log'" />
    <rollingStyle value="Date" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    <appendToFile value="true" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %level %logger: %message%n" />
    </layout>
  </appender>
  <logger name="Mogul" additivity="false">
    <level value="Info" />
    <appender-ref ref="debugFileLogAppender" />
  </logger>

Did you notice the magic? No code changes to existing classes!
Want to add it to a 100 classes. Np. No code changes needed if you have a SOLID solution! Now that's reusability!

Result

The logs you will get for logged classes will now include input parameter (none), execution time (fast as hell in this case), return parameters in json format:

2016-09-27 16:01:16,675 [11] INFO Mogul.Interceptor.Logging.LoggingInterceptor: Requesting method GetAllNews
2016-09-27 16:01:16,702 [11] INFO Mogul.Interceptor.Logging.LoggingInterceptor: GetAllNews executed in: 0 ms
2016-09-27 16:01:16,726 [11] INFO Mogul.Interceptor.Logging.LoggingInterceptor: Responding method GetAllNews has return value [
  {
    "Title": "News1"
  },
  {
    "Title": "News2"
  }
]

Hope that helps a few integrations. There are some more configuration options in the background for the advanced user if you need.

Happy intercepting everyone! :)