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

**Date:** 2021-08-04  
**Author:** Kees C. Bakker  
**Categories:** .NET / C#  
**Original:** https://keestalkstech.com/the-swiss-army-knife-decorator-exception-logging-latency-metrics-and-jaeger-spans-combined/

![The Swiss Army Knife Decorator: exception logging, latency metrics and Jaeger spans combined](https://keestalkstech.com/wp-content/uploads/2021/08/patrick-2NuEzrmD2xQ-unsplash.jpg)

---

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:

## Prerequisites

You'll need to install the following packages:

```shell
dotnet add package prometheus-net --version 4.2.0
dotnet add package OpenTracing.Contrib.NetCore --version 0.7.1
```

Next, we'll need to make sure we have the `Decoration` base class from the [Prometheus Latency Metrics & Exception Logging with Scrutor Decorators](https://keestalkstech.com/2020/08/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.

```csharp
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](https://docs.microsoft.com/en-us/dotnet/csharp/language-reference/keywords/using-statement) - a C# 8.0 feature.*

## Example

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

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