The Swiss Army Knife Decorator: exception logging, latency metrics and Jaeger spans combined

At Wehkamp, we use decoration a lot. Decoration is a nice way of separating concerns from the actual code. Most of our repositories need the same set of decorators: exception logging, latency metrics and Jaeger spans. In this article I'll be joining these 3 types of decorator into a single Swiss Army Knife decorator: one decorator to rule them all.

Why?

Normally, I'm all for separation of concerns and I would advise to separate these 3 types of decorators. But as time progresses and we see more classes that need decoration, decoration becomes burdensome. Having to implement an IRandomRepositoryName 4 times (once for real and thrice for decoration) takes all the fun out of them. You also need to hook up all the decorators in your Startup class. No more! Time to quit repetition.

Let's combine these decorators into a single class:

1. Exception Logging
2. Prometheus Latency Logging
3. Jaeger Spans

Prerequisites

You'll need to install the following packages:

Next, we'll need to make sure we have the Decoration base class from the Prometheus Latency Metrics & Exception Logging with Scrutor Decorators article.

The Swiss Army Knife Decorator

We're going to inject the decorated object, the tracer and the logger. We can access the logger via the protected Logger property. Tracing can be done through the provided IScope argument.

using Microsoft.Extensions.Logging;
using OpenTracing;
using Prometheus;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading.Tasks;

/// <summary>
/// Implements exception logging, latency metrics and Jaeger spans as 1 decorator.
/// </summary>
/// <typeparam name="TDecorated">The decorated type.</typeparam>
public class SwissArmyKnifeDecorator<TDecorated> : Decorator<TDecorated>
{
    private static readonly Summary _summary = Metrics.CreateSummary(
                "elapsed_time_ms_summary",
                "Records latency of methods.",
                new SummaryConfiguration()
                {
                    AgeBuckets = 5,
                    BufferSize = 500,
                    MaxAge = new TimeSpan(0, 0, 2, 0),
                    LabelNames = new[] { "class_name", "method_name" },
                    Objectives = new List<QuantileEpsilonPair>
                    {
                        new QuantileEpsilonPair(0.01, 0.001),
                        new QuantileEpsilonPair(0.05, 0.005),
                        new QuantileEpsilonPair(0.5, 0.05),
                        new QuantileEpsilonPair(0.9, 0.01),
                        new QuantileEpsilonPair(0.95, 0.005),
                        new QuantileEpsilonPair(0.99, 0.001),
                        new QuantileEpsilonPair(0.999, 0.0001)
                    }
                });

    private ITracer _tracer;
    protected ILogger<TDecorated> Logger { get; }

    protected SwissArmyKnifeDecorator(TDecorated decorated, ITracer tracer, ILogger<TDecorated> logger) : base(decorated)
    {
        _tracer = tracer ?? throw new ArgumentNullException(nameof(tracer));
        Logger = logger ?? throw new ArgumentNullException(nameof(logger));
    }

    protected virtual void CollectElapsedTime(
        string methodName,
        Stopwatch stopwatch)
    {
        stopwatch.Stop();
        _summary.Labels(DecoratedClassName, methodName).Observe(stopwatch.ElapsedMilliseconds);
    }

    protected virtual IScope StartScope(string methodName)
    {
        return _tracer
            .BuildSpan($"{DecoratedClassName}.{methodName}")
            .WithTag("method", methodName)
            .WithTag("class", DecoratedFullClassName)
            .StartActive(true);
    }

    protected virtual void HandleException(Exception ex, IScope scope, string methodName)
{
        Logger.LogError(ex, $"Exception in {DecoratedClassName}.{methodName}: {ex.Message}");

        scope.Span.SetTag("error", true);
        scope.Span.Log($"Exception: {ex.Message}");
    }

    protected async Task Decorate(
        Func<Task> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            await action();
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }
    protected async Task Decorate(
        Func<IScope, Task> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);
            
        try
        {
            await action(scope);
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected async Task<TReturn> Decorate<TReturn>(
        Func<Task<TReturn>> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            return await action();
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected async Task<TReturn> Decorate<TReturn>(
        Func<IScope, Task<TReturn>> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            return await action(scope);
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected TReturn Decorate<TReturn>(
        Func<TReturn> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            return action();
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected TReturn Decorate<TReturn>(
        Func<IScope, TReturn> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            return action(scope);
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected void Decorate(
        Action action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            action();
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }

    protected void Decorate(
        Action<IScope> action,
        [CallerMemberName] string methodName = "")
    {
        var stopwatch = Stopwatch.StartNew();
        using var scope = StartScope(methodName);

        try
        {
            action(scope);
        }
        catch (Exception ex)
        {
            HandleException(ex, scope, methodName);
            throw;
        }
        finally
        {
            CollectElapsedTime(methodName, stopwatch);
        }
    }
}

Note: the code uses the simple using syntax - a C# 8.0 feature.

Example

Now, let's implement a decorator that uses the IScope and ILogger:

public interface IMyInterface
{
    bool InOutMethod(int x);
}

public class MyInterfaceLatencyDecorator : SwissArmyKnifeDecorator<IMyInterface>, IMyInterface
{
    protected MyInterfaceLatencyDecorator(IMyInterface decorated, ITracer tracer, ILogger<IMyInterface> logger) : base(decorated, tracer, logger)
    {
    }

    public bool InOutMethod(int x) =>
        Decorate((scope) =>
        {
            scope.Span.SetTag("x", x);

            Logger.LogDebug($"Argument for {nameof(InOutMethod)}({nameof(x)}: {x}");

            return Decorated.InOutMethod(x);
        });
}

So there you go: one decorator to rule them all: logging, metrics and Jaeger spans!