Logging pipeline with MediatR

Raulis Masiukas — Sat, 25 Apr 2020 14:19:57 +0000

I recently came across the need to start logging requests being executed via MediatR, a popular NuGet package that implements the mediator pattern. The goal was to understand:

What request is being executed?
How long did the request take to execute?
What data was used to execute the request?

If you're unfamiliar with MediatR I would urge you to quickly sift through the samples on the public repo. The context of this post will only briefly touch over Requests. A high-level overview of how a request in MediatR works:

A request implements the IRequest<TResponse> interface. The default TResponse value is Unit, but it can be any return value.
Requests are handled by RequestHandlers, which implement the IRequestHandler<TRequest, TResponse> interface, where TRequest is the request object and TResponse is the return value.
Before each request, all pipeline behaviours are called, if there are any, which wrap requests. This is what makes this blog post possible. That's the basic gist of it. Of course, there's more to it but that information is unnecessary for the purpose of this article.

A great example of a Logging pipeline, as a starting point, was already provided in the MediatR documentation:



public class LoggingBehavior<TRequest, TResponse> : IPipelineBehavior<TRequest, TResponse>
{
    private readonly ILogger<LoggingBehavior> _logger;

    public LoggingBehavior(ILogger<LoggingBehavior> logger)
    {
        _logger = logger;
    }

    public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
    {
        await _logger.LogInformation($"Handling {typeof(TRequest).Name}");
        var response = await next();
        await _logger.LogInformation($"Handled {typeof(TResponse).Name}");

        return response;
    }
}

What request is being executed?

Using the example, we can tweak the injected ILogger instance to wrap the Request instead of LoggingBehavior itself:



private readonly ILogger<TRequest> _logger;

public LoggingBehavior(ILogger<TRequest> logger)
{
    _logger = logger;
}

public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
{
    var requestName = request.GetType().Name;
    var requestGuid = Guid.NewGuid().ToString();

    var requestNameWithGuid = $"{requestName} [{requestGuid}]";

    _logger.LogInformation($"[START] {requestNameWithGuid}");
    TResponse response;

    try
    {
        response = await next();
    }
    finally
    {
        _logger.LogInformation(
            $"[END] {requestNameWithGuid}");
    }

    return response;
}

Now, the logger will automatically prefix every message with the request that's being executed, given that we log at least a single message using it. This satisfies the first goal.

Note: We generate a GUID and log it together with the request. This is for the sake of convenience when trying to trace a particular request in an environment where there's an abundance of similar requests being executed at once.

How long did the request take to execute?

Within the Handle method, we need to call next at some point to execute the next step in the pipeline. It could be the Request itself or another behaviour. Given this information, we're able to instantiate a stopwatch, start it before we execute the "next" request and stop it straight after.



public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
{
    var requestName = request.GetType().Name;
    var requestGuid = Guid.NewGuid().ToString();

    var requestNameWithGuid = $"{requestName} [{requestGuid}]";

    _logger.LogInformation($"[START] {requestNameWithGuid}");
    TResponse response;
    var stopwatch = Stopwatch.StartNew();

    try
    {
        response = await next();
    }
    finally
    {
        stopwatch.Stop();
        _logger.LogInformation(
            $"[END] {requestNameWithGuid}; Execution time={stopwatch.ElapsedMilliseconds}ms");
    }

    return response;
}

What data was used to execute the request?

The easiest way to get get the data we're working with is by using a JSON serializer to convert the request object into string format: System.Text.Json.JsonSerializer.Serialize(request). Which leaves us with:



public async Task<TResponse> Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate<TResponse> next)
{
    var requestName = request.GetType().Name;
    var requestGuid = Guid.NewGuid().ToString();

    var requestNameWithGuid = $"{requestName} [{requestGuid}]";

    _logger.LogInformation($"[START] {requestNameWithGuid}");
    TResponse response;

    var stopwatch = Stopwatch.StartNew();
    try
    {
        try
        {
            _logger.LogInformation($"[PROPS] {requestNameWithGuid} {JsonSerializer.Serialize(request)}");
        }
        catch (NotSupportedException)
        {
            _logger.LogInformation($"[Serialization ERROR] {requestNameWithGuid} Could not serialize the request.");
        }

        response = await next();
    }
    finally
    {
        stopwatch.Stop();
        _logger.LogInformation(
            $"[END] {requestNameWithGuid}; Execution time={stopwatch.ElapsedMilliseconds}ms");
    }

    return response;
}

We want to handle the edge cases where we're unable to serialize the request. This could be due to the request containing an argument of type Dictionary<int, T>, for example.

... And we're done!

Wrap up

Let's create a simple request to test out the pipeline:



public class PingCommand : IRequest<Unit>
{
    public int UserId { get; set; }
    public string Message { get; set; }

    public PingCommand(int userId, string message)
    {
        UserId = userId;
        Message = message;
    }
}

public class PingCommandHandler : IRequestHandler<PingCommand, Unit>
{
    private readonly ILogger<PingCommand> _logger;

    public PingCommandHandler(ILogger<PingCommand> logger)
    {
        _logger = logger;
    }

    public Task<Unit> Handle(PingCommand request, CancellationToken cancellationToken)
    {
        // ... do some work
        return Task.FromResult(Unit.Value);
    }
}

Execute it with MediatR:



await mediator.Send(new PingCommand(123, "Give me a call!"));

And voila, we get the result:

Caveats

This is a quick and dirty implementation and I'd like to bring attention to a couple of issues:

If the request executes further requests, the GUID will change and you won't be able to trace the caller in a reassuring way. Each subsequent request will have a different GUID.
All available data will be serialized using the JsonSerializer. This can be an issue, especially when dealing with private user data. The easiest way to overcome this is to annotate fields that you don't want to log with the [JsonIgnore] attribute but that comes with its own catch, for example: if you're using the IRequest object as the request body ([FromBody]) in a controller method then you're gonna miss out on the ignored values.
ALL available data will be serialized. Long text files may muddy your logs, you'll hear sirens in the distance.

Thank you

All code is available on https://github.com/Kunigaikstis/MediatRLoggingPipelineExample