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! :)
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..
With great power comes great responsibility:)
Don't know why no one rates this post. Love your work , magician.
Nice work, Daniel!
Will this work if the type you try intercepting is an MVC controller?
Great work, very neat! But, is there a reason that RegisterInterceptor takes an instance instead of a type as the second argument?
@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...
a must read on AOP, I rated 5 with responsibility, @Daniel, you are Challenging POSTSHARP :)
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...
@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?
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
Logging parameters are now default turned off since controllers for instance spam a lot. Then you get logs like:
Enjoy!
Awesome! :)
Nuget packages updated to support Episerver 10 fyi