Daniel Ovaska
Sep 27, 2016
  5419
(6 votes)

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! :)

Sep 27, 2016

Comments

valdis
valdis Sep 27, 2016 07:27 PM

power of DI :) you might need to intercept an interceptor (inception!? ;)) to avoid some sensitive data output to log files, like passwords or other similar data..

Sep 27, 2016 07:47 PM

With great power comes great responsibility:)

Vincent
Vincent Sep 29, 2016 11:45 AM

Don't know why no one rates this post. Love your work , magician.

Per Magne Skuseth
Per Magne Skuseth Sep 29, 2016 12:06 PM

Nice work, Daniel!

Lars Iversen
Lars Iversen Sep 29, 2016 12:18 PM

Will this work if the type you try intercepting is an MVC controller?

Sep 30, 2016 07:41 AM

Great work, very neat! But, is there a reason that RegisterInterceptor takes an instance instead of a type as the second argument?

Sep 30, 2016 09:30 AM

@Per Yes, it's to let user configure interceptor by using constructor of the interceptor. In this case above though I just use default settings so not really needed there. I'll add an overload that takes just the type as well...

K Khan
K Khan Sep 30, 2016 10:13 AM

a must read on AOP, I rated 5 with responsibility, @Daniel, you are Challenging POSTSHARP :) 

Sep 30, 2016 02:11 PM

Basically what the interceptor does is that it code generates (scary yes I know) a decorator to match the interface in the background and that wraps the original class. This will then be returned instead of the actual class.

@Lars New version that is waiting for approval on Episerver nuget does have support for controllers yes. These are concrete classes and the technique in the background is a bit different. You code generate a child class instead that inherits from the original class (the controller). You can just use the same method though and the magic will happen under the hood. Be careful though not to log parameters on controllers since those contain vast amounts of information and will fill your logs fast.

New version only logs execution time by default and you can also supply the jsonserialization settings to control the json you get to avoid some problems if you have large objects you are passing back and forth / circular references etc...

Oct 3, 2016 10:14 PM

@Daniel Great that you would add that overload :) Is it version 1.0.1.0 that has controller support? Is the code on GitHub or similar, perhaps?

Oct 4, 2016 09:07 AM

Yup, it's that version 1.0.1 for LogInterceptor and 1.1.8 for base interceptors. 

Feel free to copy/paste code from Github which is updated if you don't want the nuget package dependency.

Then you can just do

container.RegisterInterceptor(new LoggingInterceptor());

Logging parameters are now default turned off since controllers for instance spam a lot. Then you get logs like:

2016-09-30 15:19:59,077 [82] INFO Mogul.Interceptor.Logging.LoggingInterceptor: ModifyLayout executed in: 64 ms
2016-09-30 15:19:59,191 [82] INFO Mogul.Interceptor.Logging.LoggingInterceptor: OnResultExecuted executed in: 0 ms
2016-09-30 15:19:59,237 [82] INFO Mogul.Interceptor.Logging.LoggingInterceptor: EndExecuteCore executed in: 1233 ms
2016-09-30 15:19:59,295 [82] INFO Mogul.Interceptor.Logging.LoggingInterceptor: EndExecute executed in: 1291 ms
2016-09-30 15:19:59,360 [82] INFO Mogul.Interceptor.Logging.LoggingInterceptor: Dispose executed in: 0 ms
...

Enjoy!

Lars Iversen
Lars Iversen Oct 4, 2016 09:21 PM

Awesome! :)

Nov 21, 2016 04:11 PM

Nuget packages updated to support Episerver 10 fyi

Please login to comment.
Latest blogs
Caching & Rendering of metadata from the DAM

For the EPiServer.Cms.WelcomeIntegration.UI 1.2.0 release, we have facilitated the ability to cache and render metadata from assets within the DAM....

Matthew Slim | Jun 2, 2023

Conversion Rate Optimization: Maximizing ROI through Data-Driven Decisions

In today's digital landscape, businesses are constantly looking for ways to improve their online presence and drive more conversions. One effective...

JessWade | Jun 1, 2023

Enhance Your Writing with Suggestions

Are you tired of staring at a blank screen, struggling to find the right words? The Epicweb.Optimizely.AIAssistant Addon is here to revolutionize...

Luc Gosso (MVP) | May 31, 2023 | Syndicated blog

Content Graph - Letting GraphQL do all the hard work for you

Background As we have seen before, setting up Content Graph on the CMS side is pretty easy. However, when it comes to the “head” part of the setup,...

Kunal Shetye | May 26, 2023 | Syndicated blog

Improved headless functionality in Customized Commerce

Did you know that with the release of Content Delivery Commerce API 3.7 we have massively improved the out of the box headless capabilities of...

Marcus Hoffmann | May 25, 2023

Boost Your Productivity with the AI Assistant Addon for Optimizely Content Cloud

In today's fast-paced digital world, efficiency and convenience are paramount. That's why we're excited to introduce the Optimizely AI-Assistant...

Luc Gosso (MVP) | May 25, 2023 | Syndicated blog