Daniel Ovaska
Sep 27, 2016
  5976
(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
Optimizely Forms: You cannot submit this form because an administrator has turned off data storage.

Do not let this error message scare you, the solution is quite simple!

Tomas Hensrud Gulla | Oct 4, 2024 | Syndicated blog

Add your own tools to the Optimizely CMS 12 admin menu

The menus in Optimizely CMS can be extended using a MenuProvider, and using the path parameter you decide what menu you want to add additional menu...

Tomas Hensrud Gulla | Oct 3, 2024 | Syndicated blog

Integrating Optimizely DAM with Your Website

This article is the second in a series about integrating Optimizely DAM with websites. It discusses how to install the necessary package and code t...

Andrew Markham | Sep 28, 2024 | Syndicated blog

Opticon 2024 - highlights

I went to Opticon in Stockholm and here are my brief highlights based on the demos, presentations and roadmaps  Optimizely CMS SaaS will start to...

Daniel Ovaska | Sep 27, 2024

Required fields support in Optimizely Graph

It's been possible to have "required" properties (value must be entered) in the CMS for a long time. The required metadata haven't been reflected i...

Jonas Bergqvist | Sep 25, 2024

How to write a bespoke notification management system

Websites can be the perfect vehicle for notifying customers of important information quickly, whether it’s the latest offer, an operational message...

Nicole Drath | Sep 25, 2024