Logging with Ninject Interception and Serilog - Part 3
Recap
Part 2 of this series demonstrated the usage of SerilogMetrics with Ninject.Extensions.Interception to make a simple drop-in, AOP-style metric logging interceptor over any (virtual) method in my application. It’s with this interceptor that I want to demonstrate interception via an [Attribute] rather than traditional Ninject binding syntax.
Here’s my LogErrorInterceptor
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;
}
}
}
The LogErrorInterceptor uses the IInterceptor interface and simply wraps the invocation of the method in a try-catch with the catch instructed to send a Serilog Error event to my chosen Serilog sink (to reiterate - Seq - is awesome).
Intercepting with [Attributes]
So what if I don’t really want to mess around with bloating my Ninject bindings with .Intercept().With<>()? I use InterceptAttribute. This nifty little class lets me simply attribute my class or method with [LogError] when I want to log the method’s errors.
It’s simply a matter of inheriting the InterceptAttribute and overriding the public override CreateInterceptor(IProxyRequest request) method.
public class LogErrorAttribute : InterceptAttribute {
public override IInterceptor CreateInterceptor(IProxyRequest request) {
return request.Kernel.Get<LogErrorInterceptor>();
}
}
So I can take out the code from my Ninject bindings:
public class ServiceModuleTest : NinjectModule {
public override void Load() {
Bind<ILogger>().ToMethod(x => new LoggerConfiguration()
.WriteTo.Seq(@"http://localhost:5341/")
.CreateLogger());
Bind<IInterceptedTestClass>()
.To<InterceptedTestClass>()
// Take out this junk
// .Intercept().With<LogInterceptor>();
}
}
And I can just do something like this:
public class InterceptedByAttributeTestClass : IInterceptedByAttributeTestClass {
public InterceptedByAttributeTestClass(string someParameter) {
}
[LogError]
public virtual void InterceptMyError() {
throw new Exception("I'm an exception");
}
}
And lo and behold we get an error in our Serilog sink:
{
"Timestamp": "2015-07-22T11:34:11.7669739-04:00",
"Properties": [
{
"Name": "Name",
"Value": "InterceptMyError"
},
{
"Name": "Arguments",
"Value": []
},
{
"Name": "SourceContext",
"Value": "MyClass.IntegrationTests.Logging.InterceptedByAttributeTestClass"
}
],
"MessageTemplateTokens": [
{
"Text": "Error at Method: "
},
{
"PropertyName": "Name"
},
{
"Text": " Arguments: "
},
{
"PropertyName": "Arguments"
}
],
"EventType": "$537C5CF4",
"Level": "Error",
"Exception": "System.Exception: I'm an exception\r\n at blah blah blah inner exception,
"Id": "event-fe16e36b92aa08d22104000000000000",
"Links": {
"Self": "api/events/event-fe16e36b92aa08d22104000000000000{?download,render}",
"Group": "api/events/resources"
}
}
var floodGates = “open”;
Now there’s more flexibility if all of my interceptors have these additional InterceptAttribute
public class LogAttribute : InterceptAttribute {
public override IInterceptor CreateInterceptor(IProxyRequest request) {
return request.Kernel.Get<LogInterceptor>();
}
}
public class LogTimerAttribute : InterceptAttribute {
public string TimerName { get; set; }
public override IInterceptor CreateInterceptor(IProxyRequest request) {
return request
.Kernel
.Get<TimerInterceptor>(
new ConstructorArgument("timerName",
TimerName)
);
}
}
(notice you can pass in constructor arguments to the Kernel.Get<>() method
Now I’m tagging all kinds of methods with my logger attributes
public class InterceptedByAttributeTestClass : IInterceptedByAttributeTestClass {
public InterceptedByAttributeTestClass(string someParameter) {
}
[Log(Order = 0)]
[LogError(Order = 1)]
public Part InterceptMe(Part part) {
return part;
}
[LogError]
public virtual void InterceptMyError() {
throw new Exception("I'm an exception");
}
[Log]
public void InterceptMeAlso() {
}
}
public class InterceptedByTimerAttributeTestClass : IInterceptedByTimerAttributeTestClass {
[Log(Order = 0)]
[LogTimer(Order = 1, TimerName = "Interceptor Timer")]
public virtual void InterceptMeWithATimer() {
Thread.Sleep(2000);
}
}
The [Log(Order=0)] and [LogError(Order = 1)] means that I want to intercept with my LogInterceptor first, then my LogErrorInterceptor.
With the LogTimer, I’m passing in TimerName = "Interceptor Timer", which travels all the way down to the SerilogMetrics extension for my Serilog ILogger instance in the LogTimerInterceptor constructor.
So, there you have it - my experience implementing drop-in logging for any dependency that I’m managing through Ninject. Also a bit of Serilog and Seq, which I’m becoming more of a fan of every day. Thanks and feel free to shoot me an email here or talk to me on Twitter.
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: