Logging pipeline with MediatR
Tags: csharp, dotnet, mediatr
Published: 2020-04-25 14:19:57

I recently came across the need to start logging requests being executed via [MediatR](https://github.com/jbogard/MediatR), a popular NuGet package that implements the mediator pattern. The goal was to understand:

1. What request is being executed?
2. How long did the request take to execute?
3. 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 `Request`s. 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 `RequestHandler`s, 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](https://github.com/jbogard/MediatR/wiki/Behaviors):
```csharp
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:
```csharp
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.

```csharp
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:

```csharp
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:

```csharp
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`:
```csharp
await mediator.Send(new PingCommand(123, "Give me a call!"));
```

And voila, we get the result:
![Result](https://dev-to-uploads.s3.amazonaws.com/i/mzx0ckzxqjia466wks3s.png)

### Caveats

This is a quick and dirty implementation and I'd like to bring attention to a couple of issues:
1. 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`. 
2. 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.
3. 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