3
\$\begingroup\$

GitHub

Here is a Castle.Core based service interface decorator providing automatic logging through the ambient logging context. Logging context should be constructed higher in the call stack:

using var log = new Log(log.Debug, log.Info, log.Warning, log.Error);

and used through the static API after:

Log.Info("Hello World");

One could define custom attributes to associate with all the log entries deeper in the call stack:

using var log = new Log(log.Debug, log.Info, log.Warning, log.Error);
using var tag1 = new Tags(("UserId", userId), ("Reason", reason));
          …
   using var tag2 = new Tags(("TenantId", tenantId));
      …               
      Log.Info("Hello World");
      Log.Info("Hello Mr. Postman");

Library types look like this:

public class Log : IDisposable
{
    static AsyncLocal<Log> Context { get; } = new AsyncLocal<Log>();

    public Log(
        Action<string, Dictionary<string, object>> onDebug,
        Action<string, Dictionary<string, object>> onInfo,
        Action<string, Dictionary<string, object>> onWarning,
        Action<string, Exception, Dictionary<string, object>> onError)
    {
        Parent = Context.Value;
        Context.Value = this;

        OnDebug = onDebug;
        OnInfo = onInfo;
        OnWarning = onWarning;
        OnError = onError;
    }

    public virtual void Dispose()
    {
        Context.Value = Parent;
    }

    Log Parent { get; }
    Action<string, Dictionary<string, object>> OnDebug { get; }
    Action<string, Dictionary<string, object>> OnInfo { get; }
    Action<string, Dictionary<string, object>> OnWarning { get; }
    Action<string, Exception, Dictionary<string, object>> OnError { get; }

    public static void Debug(string text, params (string Name, object Value)[] tags)
    {
        using (new Tags(tags))
            Context.Value?.OnDebug(text, Tags.ToDictionary());
    }

    public static void Info(string text, params (string Name, object Value)[] tags)
    {
        using (new Tags(tags))
            Context.Value?.OnInfo(text, Tags.ToDictionary());
    }

    public static void Warning(string text, params (string Name, object Value)[] tags)
    {
        using (new Tags(tags))
            Context.Value?.OnWarning(text, Tags.ToDictionary());
    }

    public static void Error(string text, Exception ex, params (string Name, object Value)[] tags)
    {
        using (new Tags(tags))
            Context.Value?.OnError(text, ex, Tags.ToDictionary());
    }
}

Where:

public class Tags : IDisposable
{
    static AsyncLocal<Tags> Context { get; } = new AsyncLocal<Tags>();

    public Tags(params string[] tags) : this() => List = tags;
    public Tags(params (string Name, object Value)[] tags) : this() => Dictionary = tags;
    Tags()
    {
        Parent = Context.Value;
        Context.Value = this;
    }

    public virtual void Dispose()
    {
        Context.Value = Parent;
    }

    Tags Parent { get; }
    IEnumerable<string> List { get; } = new string[0];
    IEnumerable<(string Name, object Value)> Dictionary { get; } = new (string, object)[0];

    public static Dictionary<string, object> ToDictionary()
    {
        return
            Context.Value == null ? new Dictionary<string, object>() :
            Merge(Context.Value)
                .ToDictionary(kvp => kvp.Item1, kvp => kvp.Item2);

        IEnumerable<(string, object)> Merge(Tags tags) =>
            tags.Parent == null ? tags.Dictionary :
            Merge(tags.Parent)
                .Concat(tags.Dictionary)
                .Distinct();
    }

    public static string[] ToArray()
    {
        return
            Context.Value == null ? new string[0] :
            Merge(Context.Value);

        string[] Merge(Tags tags) =>
            tags.Parent == null ? tags.List.ToArray() :
            Merge(tags.Parent).Concat(tags.List).Distinct()
                .ToArray();
    }
}

We also have an AsLoggable() extension method, which allows to generate a logging proxy for something like this:

public interface IFoo
{
    void Bar();
    …
}  

Let’s setup and test:

[Test]
public void Log_Success()
{
  var sb = new StringBuilder();
  using var log = new Log(sb.Debug, sb.Info, sb.Warning, sb.Error);

  var foo = new Mock<IFoo>();
  foo
     .Setup(f => f.Bar())
     .Verifiable();

  var obj = foo.Object.AsLoggable();

  obj.Bar();

  foo
     .Verify(f => f.Bar(), Times.Once);

  Assert.IsTrue(Regex.IsMatch(
      sb.ToString(),
      @"Debug: Instrumentation.IFoo.Bar started. Method=Instrumentation.IFoo.Bar" + NewLine +
      @"Debug: Instrumentation.IFoo.Bar succeeded. Method=Instrumentation.IFoo.Bar, Taken=\d+"));
}

Where test logging helpers are:

static class Logging
{
    public static void Debug(this StringBuilder sb, string e, Dictionary<string, object> p) =>
        sb.AppendLine("Debug: " + e + ". " + string.Join(", ", from kvp in p select $"{kvp.Key}={kvp.Value}"));
    public static void Info(this StringBuilder sb, string e, Dictionary<string, object> p) =>
        sb.AppendLine("Info: " + e + ". " + string.Join(", ", from kvp in p select $"{kvp.Key}={kvp.Value}"));
    public static void Warning(this StringBuilder sb, string e, Dictionary<string, object> p) =>
        sb.AppendLine("Warning: " + e + ". " + string.Join(", ", from kvp in p select $"{kvp.Key}={kvp.Value}"));
    public static void Error(this StringBuilder sb, string e, Exception ex, Dictionary<string, object> p) =>
        sb.AppendLine("Error: " + e + ". " + ex.Message + " " + string.Join(", ", from kvp in p select $"{kvp.Key}={kvp.Value}"));
}

AsLoggable() uses Castle.Core:

public static T AsLoggable<T>(this T obj) where T: class
{
    var proxyGenerator = new ProxyGenerator();
    return proxyGenerator
        .CreateInterfaceProxyWithTarget(obj, new Logger());
}

Where:

class Logger : AsyncInterceptorBase
{
    protected override async Task InterceptAsync(IInvocation invocation, Func<IInvocation, Task> proceed)
    {
        var sw = Stopwatch.StartNew();
        var method = $"{invocation.Method.DeclaringType.FullName}.{invocation.Method.Name}";
        using (new Tags(("Method", method)))
            try
            {
                Log.Debug($"{method} started");
                try
                {
                    await proceed(invocation).ConfigureAwait(false);
                }
                finally
                {
                    sw.Stop();
                }
                using (new Tags(("Taken", sw.ElapsedMilliseconds)))
                {
                    var e = $"{method} succeeded";
                    Log.Debug(e);
                    Stat.Increment(e);
                    Stat.Gauge(e, sw);
                }
            }
            catch (Exception ex)
            {
                using (new Tags(("Taken", sw.ElapsedMilliseconds)))
                {
                    var e = $"{method} failed";
                    Log.Error(e, ex);
                    Stat.Increment(e);
                    Stat.Gauge(e, sw);
                    throw;
                }
            }
    }

    protected override async Task<TResult> InterceptAsync<TResult>(IInvocation invocation, Func<IInvocation, Task<TResult>> proceed)
    {
        TResult result = default;
        var sw = Stopwatch.StartNew();
        var method = $"{invocation.Method.DeclaringType.FullName}.{invocation.Method.Name}";
        using (new Tags(("Method", method)))
            try
            {
                Log.Debug($"{method} started");
                try
                {
                    result = await proceed(invocation).ConfigureAwait(false);
                }
                finally
                {
                    sw.Stop();
                }
                using (new Tags(("Taken", sw.ElapsedMilliseconds)))
                {
                    var e = $"{method} succeeded";
                    Log.Debug(e);
                    Stat.Increment(e);
                    Stat.Gauge(e, sw);
                    return result;
                }
            }
            catch (Exception ex)
            {
                using (new Tags(("Taken", sw.ElapsedMilliseconds)))
                {
                    var e = $"{method} failed";
                    Log.Error(e, ex);
                    Stat.Increment(e);
                    Stat.Gauge(e, sw);
                    throw;
                }
            }
    }
}    

Now we can implement our service interfaces and register them in IoC as loggable.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.