Mediatr Custom Behavior: Logging

.NET
, , , ,

Warning!

Before I begin, a brief word of warning. I have not yet decided if the technique described below is a good idea or a terrible idea. So far it seems to be working well, but I have not exercised it enough to confidently recommend that others use it. Now that the safety advisory is out of the way, on with the show.

ASP.NET Web API Logging

I have been working on a Web API project where I wanted to have teh API log some basic information on every web request. What I did not want was logging code splattered in my API controllers. I am using Mediatr to decouple my application logic from the Web API framework, but having logging code splattered all over my message handlers did not feel like an improvement. After considering my available options, I decided to try building a custom Mediatr behavior, and adding it to a Mediatr pipeline. To facilitate this, I created an interface to define the metadata that I wanted to be logged.

The interface simply references another class that contains all of my data elements:

1
2
3
4
5
6
7
8
9
10
11
12
13
public interface IAPIRequestContext
{
    APIRequestMetadata APIRequestMetadata { get; set; } 
}

public class APIRequestMetadata
{
    public Guid RequestId { get; set; }
    public string CurrentUser { get; set; }
    public string Controller { get; set; }
    public string Method { get; set; }
    public Dictionary<string, object> Parameters { get; set; }
}

This interface is then added to my Mediatr message definitions:

1
2
3
4
5
public class Query : IRequest<Result>, IAPIRequestContext
{
    public string Status { get; set; }
    public APIRequestMetadata APIRequestMetadata { get; set; }
}

Finally, I have custom Mediatr pipeline behavior that casts the Query object to the IAPIRequestContext and logs (using Serilog) the data in the APIRequestMetadata object:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
public class LoggingBehavior<TRequest, TResponse> : IPipelineBehavior<TRequest, TResponse>
{
    public async Task<TResponse> Handle(TRequest request, RequestHandlerDelegate<TResponse> next)
    {
        Log.Debug("Entering LoggingBehavior with request {Name}", typeof(TRequest).Name);

        var reqCtxt = (request as IAPIRequestContext);
        if (reqCtxt != null)
        {
            if (reqCtxt.APIRequestMetadata != null)
            {
                var metadata = reqCtxt.APIRequestMetadata;
                Log.Information("Request Id: {RequestId}, Current User: {User}, Controller: {Controller}, Method: {Method}", metadata.RequestId, metadata.CurrentUser, metadata.Controller, metadata.Method);
                if (metadata.Parameters != null)
                {
                    foreach (var param in metadata.Parameters)
                    {
                        Log.Debug("Request Id: {RequestId}, {ParameterName}: {ParameterValue}", metadata.RequestId, param.Key, param.Value);
                    }
                }
            }
        }

        var response = await next();

        Log.Debug("Leaving LoggingBehavior with request {Name}", typeof(TRequest).Name);

        return response;
    }
}

With this setup, every controller in my API project emits a standard logging event, with having the logging code located in every one of my Mediatr handler methods. My plan is to combine this with a metrics pipeline behavior so I can track which API methods get used the most, and see how well they perform.

So, do you think this is pretty good idea for handling logging, or do you think this is the worst idea you have ever seen? Feel free to send me comments on Twitter or LinkedIn either way.