Logging with Ninject Interception and Serilog - Part 1
The Problem
I have a project with a lot of places where I want to “cross-cut” the concern of logging into. This is also called “AOP” - Aspect Oriented Programming. AOP claims to “increase modularity by allowing the separation of cross-cutting concerns… by adding additional behavior to existing code (an advice) without modifying the code itself”. By managing dependencies differently, I’ve found myself moving into the anti-pattern of constructor over-injection. Adding an ILogger interface as a new dependency for multiple classes is going to be a burden. This experiment is to see if I can avoid making my constructors too heavy, while broadly covering my code with basic logging.
I plan to use Ninject for this. I’d like to achieve broad logging of events and errors AROUND methods of my choosing. I will also end up needing more specific, behavior-driven logging where I can see what is happening throughout a vertical slice of my application, but this will probably require adding an ILogger dependency later.
Enter Ninject Interception
For my logging that isn’t specific to the behavior of the app, which includes “Method: x executed with x parameters and returned with x values” and “An error was thrown while processing x Entity” - I’m going to use Ninject.Extensions.Interception. A good introduction is here. And some good coverage of the topic in the book Mastering Ninject for Dependency Injection: .
I decided to use Serilog because of its ability to “destructure” objects, which is simply .ToJson() and inserting the result into the formatted string output. Serilog also leaves the doors open to whatever “sink” I’d like to send logs to in the future. I chose Seq as the sink for the greenfield applicaiton that I’m working on.
The way Ninject.Extensions.Interception works is that it provides a wrapper “proxy” around any virtual method that is owned by a dependency that you are injecting. So:
namespace Project {
// We are intercepting a method in this class
public class InterceptedTestClass : IInterceptedTestClass {
public virtual void InterceptMe() {
};
}
// We are going to intercept this method
public interface IInterceptedTestClass {
void InterceptMe();
}
// Unit test project's Ninject Service Module for configuring bindings
public class ServiceModuleTest : NinjectModule {
public override void Load() {
Bind<IInterceptedTestClass>().To<InterceptedTestClass>();
}
}
}
// The test to prove it
[Fact]
public void Bind_test_class() {
using (var kernel = new StandardKernel(new ServiceModuleTest())) {
var testClass = kernel.Get<IInterceptedTestClass>();
Assert.IsType<InterceptedTestClass>(testClass)
}
}
In order to get the project we run Install-Package Ninject.Extensions.Interception.DynamicProxy
This will install the infrastructure needed and the actual Ninject.Extensions.Interception project.
To instal the Serilog and the SerilogMetrics libraries - Install-Package Serilog and Install-Package SerilogMetrics
First thing I need to do is create some interceptors. These are the classes you need to inherit in order to use the interception library. I chose to use a mix of both the SimpleInterceptor and the IInterceptor to build my own interceptor classes:
#region Standard logging interceptor
public class LogInterceptor : SimpleInterceptor {
private readonly ILogger _logger;
public LogInterceptor(ILogger logger) {
_logger = logger;
}
protected override void BeforeInvoke(IInvocation invocation) {
}
protected override void AfterInvoke(IInvocation invocation) {
_logger.ForContext(invocation.Request.Target.GetType())
.Information("Method: {Name} called with arguments {@Arguments} returned {@ReturnValue}",
invocation.Request.Method.Name,
invocation.Request.Arguments,
invocation.ReturnValue);
}
}
#endregion
#region Error logging interceptor
public class LogErrorInterceptor : IInterceptor {
private readonly ILogger _logger;
public LogErrorInterceptor(ILogger logger) {
_logger = logger;
}
public void Intercept(IInvocation invocation) {
try {
invocation.Proceed();
}
catch (Exception exception) {
_logger.ForContext(invocation.Request.Target.GetType())
.Error(exception, "Error at Method: {@Name} Arguments: {@Arguments}",
invocation.Request.Method.Name,
invocation.Request.Arguments);
throw;
}
}
}
#endregion
#region Timer interceptor
public class TimerInterceptor : IInterceptor {
private readonly string _timerName;
private readonly ILogger _logger;
public TimerInterceptor(string timerName, ILogger logger) {
_timerName = timerName;
_logger = logger;
}
public void Intercept(IInvocation invocation) {
using (_logger.ForContext(invocation.Request.Target.GetType())
.BeginTimedOperation(_timerName, invocation.Request.Method.Name)) {
invocation.Proceed();
}
}
}
#endregion
Here, I have three utility interceptor classes. They are going to take care of my AOP-style logging. I have a simple LogInterceptor that is just going to write which method and with which parameters is being called. This uses the SimpleInterceptor provided by the extension. The SimpleInterceptor allows you to call BeforeInvoke and AfterInvoke surrounding the actual method call. I can also use some properties of the actual invocation using the IInvocation interface that is passed into the interceptor’s methods e.g. invocation.Request.Method.Name and invocation.Request.Arguments.
So to use this SimpleInterceptor class, I define the interception within our Ninject binding definition:
public class ServiceModuleTest : NinjectModule {
public override void Load() {
Bind<IInterceptedTestClass>()
.To<InterceptedTestClass>()
.Intercept().With<LogInterceptor>();
}
}
And in my Serilog sink (in my case it’s Seq), I get this output on the call of a method. This is the output of logging a method called “CreatePart”.
Here’s the BeforeInvoke interceptor log output:
{
"Timestamp": "2015-07-01T11:50:39.9740367-04:00",
"Properties": [
{
"Name": "Name",
"Value": "CreatePart"
},
{
"Name": "Arguments",
"Value": [
"FF56D337-A113-E511-B04D-005056BC69BC",
"D990B9D2-2355-E211-8AB5-001EC9E3D8F3"
]
}
],
"MessageTemplateTokens": [
{
"Text": "Method: "
},
{
"PropertyName": "Name"
},
{
"Text": " called with arguments "
},
{
"PropertyName": "Arguments"
}
],
"EventType": "$0573D34D",
"Level": "Information",
"Id": "event-d06e91cf822c08d20500000000000000",
"Links": {
"Self": "api/events/event-d06e91cf822c08d20500000000000000{?download,render}",
"Group": "api/events/resources"
}
}
And here’s the AfterInvoke interceptor log output:
{
"Timestamp": "2015-07-01T11:50:48.2028595-04:00",
"Properties": [
{
"Name": "Name",
"Value": "CreatePart"
},
{
"Name": "ReturnValue",
"Value": "GA1008-36-07G|04"
}
],
"MessageTemplateTokens": [
{
"Text": "Method: "
},
{
"PropertyName": "Name"
},
{
"Text": " returned "
},
{
"PropertyName": "ReturnValue"
}
],
"EventType": "$2BEAAA84",
"Level": "Information",
"Id": "event-d5563033822c08d20800000000000000",
"Links": {
"Self": "api/events/event-d5563033822c08d20800000000000000{?download,render}",
"Group": "api/events/resources"
}
}
So that’s the first bit of my basic implementation of Ninject.Extensions.Interception for AOP-style logging. I’ll follow up with more details about the LogErrorInterceptor and the TimerInterceptor as well as the awesome InterceptAttribute.
If you like this post and want to see more come right to your inbox - be sure to sign up for my newsletter. I always try to cover interesting and helpful topics for .NET developers like you!
Related Posts: