Logging with Ninject Interception and Serilog - Part 2
Recap
Part 1 of this series was me attempting to use Ninject.Extensions.Interception in combination with Serilog to do AOP logging for times when fine-grained logging isn’t necessary across larger vertical slices of my application.
Picking up where I left off, I had created 3 classes that inherited IInterceptor:
LogInterceptor for logging method parameters and return values
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);
}
}
LogErrorInterceptor for logging all errors
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;
}
}
}
TimerInterceptor for logging time elapsed
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();
}
}
}
As you can see the only differences in the classes that I didn’t use SimpleInterceptor, is that I wanted more unique behavior in the way that I intercepted the invocation of the method e.g. I wanted to catch any errors thrown or SerilogMetrics required me to wrap the invocation in a using statement.
TimerInterceptor for drop-in performance
The ErrorLogger interceptor is great, pretty straightforward and doesn’t really care what method it’s intercepting (as long as it’s virtual per the requirements of the extension). The TimerInterceptor is also awesome. SerilogMetrics is an extension for Serilog that creates structured log outputs using meters, counters, timers, and gauges. Super easy to use, just like Serilog.
To use this interceptor we add it to our bindings in Ninject
public class ServiceModuleTest : NinjectModule {
public override void Load() {
Bind<ILogger>().ToMethod(x => new LoggerConfiguration()
.WriteTo.Seq(@"http://UrlToSeqSink/")
.CreateLogger());
// Bind that timer interceptor here
Bind<IInterceptedByTimerAttributeTestClass>()
.To<InterceptedByTimerAttributeTestClass>()
.Intercept().With<TimerInterceptor>();
}
Two log entries are created for the start and stop of the method’s timer…
Start timer:
{
"Timestamp": "2015-07-01T11:56:35.6506008-04:00",
"Properties": [
{
"Name": "TimedOperationId",
"Value": "CreatePart"
},
{
"Name": "TimedOperationDescription",
"Value": "CreatePart Timer"
}
],
"MessageTemplateTokens": [
{
"Text": "Beginning operation "
},
{
"PropertyName": "TimedOperationId"
},
{
"Text": ": "
},
{
"PropertyName": "TimedOperationDescription"
}
],
"EventType": "$7151D589",
"Level": "Information",
"Id": "event-a46e8198822d08d22200000000000000",
"Links": {
"Self": "api/events/event-a46e8198822d08d22200000000000000{?download,render}",
"Group": "api/events/resources"
}
}
End timer:
{
"Timestamp": "2015-07-01T11:56:38.8439201-04:00",
"Properties": [
{
"Name": "TimedOperationId",
"Value": "CreatePart"
},
{
"Name": "TimedOperationDescription",
"Value": "CreatePart Timer"
},
{
"Name": "TimedOperationElapsed",
"Value": "00:00:03.1935646"
},
{
"Name": "TimedOperationElapsedInMs",
"Value": 3193.0
}
],
"MessageTemplateTokens": [
{
"Text": "Completed operation "
},
{
"PropertyName": "TimedOperationId"
},
{
"Text": ": "
},
{
"PropertyName": "TimedOperationDescription"
},
{
"Text": " in "
},
{
"PropertyName": "TimedOperationElapsed"
},
{
"Text": " ("
},
{
"PropertyName": "TimedOperationElapsedInMs"
},
{
"Text": " ms)"
}
],
"EventType": "$6A82779B",
"Level": "Information",
"Id": "event-a655c4a1822d08d22300000000000000",
"Links": {
"Self": "api/events/event-a655c4a1822d08d22300000000000000{?download,render}",
"Group": "api/events/resources"
}
}
Now, I have some sweet metric logging that can be filtered in my chosen Serilog sink (Seq is really awesome) to look at the execution times of specific methods in our application over time.
Next part, I’ll talk about the awesomeness of Ninject.Extensions.Interception.Attributes.
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: