2
\$\begingroup\$

I use my own logger adapter that collects data into a dictionary:

public class Log : Dictionary<string, object> { }

This is really all I have. I then pass it to my NLogRx - this is an IObserver<Log> that translates my Log into NLog's entries.

I need this layer for all kinds of freaky stuff I do with that dictionary: add stopwatch, contexts with correlation-ids or default attachmentes that are applied to each entry.

Currently I just pass it to the actual logger but... I had that idea (and a need) of adding a transaction. That should act like a buffer and collect entries until I commit them. This should help me avoid unnecessary logging for code paths that actually didn't do anything useful (and would mean only garbage). It required a lot of workarounds with my current design (it's even super difficult to explain) so I was looking for something more structured.


Core

After some reaserch and trail-and-error I created the following proof-of-concept (LINQPad, not extra dependencies). It uses the idea of a middleware and is a doubly-linked-list that acts as a chain of responsibility.

LoggerMiddleware is the node. It maintains the Previous and Next link in the chain. When disposed, it removes itself from it (an example follows).

public abstract class LoggerMiddleware : IDisposable
{
    public LoggerMiddleware Previous { get; private set; }
    public LoggerMiddleware Next { get; private set; }

    public T Add<T>(T next) where T : LoggerMiddleware
    {
        next.Previous = this;
        next.Next = Next;
        Next = next;
        return next;
    }

    public abstract void Invoke(Log request);

    public void Dispose()
    {
        if (!(Previous is null))
        {
            Previous.Next = Next;
            Previous = null;
            Next = null;
        }
    }
}

Based on this class, I created four more middlewares.

  • LoggerInitializer - this is supposed to add the name of the logger to Log
  • LoggerLambda - allows me to let the caller modify the Log as he pleases
  • LoggerTransaction - allows me to buffer logs and commit them
  • LoggerFilter - allows me to filter logs and short-circuit the pipeline
  • LoggerEcho - this is the final link that forwards Log to the actual adapter
public class LoggerInitializer : LoggerMiddleware
{
    private readonly string _name;

    public LoggerInitializer(string name)
    {
        _name = name;
    }

    public override void Invoke(Log request)
    {
        request["name"] = _name;
        Next?.Invoke(request);
    }
}

public class LoggerLambda : LoggerMiddleware
{
    private readonly Action<Log> _transform;

    public LoggerLambda(Action<Log> transform)
    {
        _transform = transform;
    }

    public override void Invoke(Log request)
    {
        _transform(request);
        Next?.Invoke(request);
    }
}

public class LoggerTransaction : LoggerMiddleware
{
    private readonly IList<Log> _buffer = new List<Log>();

    public override void Invoke(Log request)
    {
        _buffer.Add(request);
        //Next?.Invoke(request); // <-- don't call Next until Commit
    }

    public void Commit()
    {
        foreach (var request in _buffer)
        {
            Next?.Invoke(request);
        }
    }

    public void Rollback()
    {
        _buffer.Clear();
    }
}


public class LoggerFilter : LoggerMiddleware
{
    public Func<Log, bool> CanLog { get; set; }

    public override void Invoke(Log request)
    {
        if (CanLog(request))
        {
            Next?.Invoke(request);
        }
    }
}

public class LoggerEcho : LoggerMiddleware
{
    public override void Invoke(Log request)
    {
        request.Dump();
    }
}

Logger

A Logger is constructed with a middleware and interally adds the echo for writing. It provides a helper API Add that chains a new middleware just before the echo. This middleware is automatically removed from the chain when it's disposed. This way I can intercept the flow of Logs and filter or buffer them... I guesss other ideas will pop-up later.

public class Logger
{
    private readonly LoggerMiddleware _middleware;

    public Logger(LoggerMiddleware middleware)
    {
        _middleware = middleware;
        _middleware.Add(new LoggerEcho());
    }

    public T Add<T>(T next) where T : LoggerMiddleware
    {
        return _middleware.NextToLast().Add(next);
    }

    public void Log(Log log)
    {
        _middleware.Invoke(log);
    }
}

Utilities

The raw API would be cumbersome to use so I also created a couple of convenience extensions.

  • LogExtensions - simplifies setting various log properties
  • LoggerExtensions - simplifies Log transformations
  • LoggerMiddlewareExtensions - simplifies finding the next-to-last middleware
public static class LogExtensions
{
    public static Log Message(this Log log, string message)
    {
        log["message"] = message;
        return log;
    }
}

public static class LoggerExtensions
{
    public static void Log(this Logger logger, Action<Log> transform)
    {
        using (logger.Add(new LoggerLambda(transform)))
        {
            logger.Log(new Log());
        }
    }
}

public static class LoggerMiddlewareExtensions
{
    public static LoggerMiddleware NextToLast(this LoggerMiddleware loggerMiddleware)
    {
        while (!(loggerMiddleware.Next is null))
        {
            loggerMiddleware = loggerMiddleware.Next;
        }
        return loggerMiddleware.Previous;
    }
}

Example

By all these powers combined I am now able to chain all features and inject new ones at the end (before last) when necessary:

void Main()
{
    var logger = new Logger(new LoggerInitializer("init"));
    // Include to filter certain messages out.
    //logger.Add(new LoggerFilter { CanLog = l => !l["message"].Equals("tran-2-commit") });

    logger.Log(l => l.Message("begin"));
    using (var tran = logger.Add(new LoggerTransaction()))
    {
        logger.Log(l => l.Message("tran-1-commit"));
        logger.Log(l => l.Message("tran-2-commit"));
        tran.Commit(); // both messages are logged
    }
    using (var tran = logger.Add(new LoggerTransaction()))
    {
        logger.Log(l => l.Message("tran-1-rollback"));
        logger.Log(l => l.Message("tran-2-rollback"));
        tran.Rollback(); // both messages are ignored
    }
    logger.Log(l => l.Message("end"));
}

Questions

I know there are a lot of convenience extensions necessary to make it more user-friendly (like creating a new transaction) but what do you think about it as a low level API? Do the middlewares make sense as nodes of a linked-list and links in the chain of responsibility? What would you improve and how?

\$\endgroup\$
  • 1
    \$\begingroup\$ I put the code on GitHub Gist for easier copy/paste if anyone wanted to. It's from LINQPad and it uses Dump. \$\endgroup\$ – t3chb0t Aug 3 at 14:06
  • 1
    \$\begingroup\$ Minor nit: I am not really a fan of !(x is null) notation - I prefer seeing positive condition tests and that can read x is object. \$\endgroup\$ – Jesse C. Slicer Aug 6 at 18:48
  • \$\begingroup\$ @JesseC.Slicer me either. I always prefer postive conditions but somtimes there is just no other way to handle it :-[ an is not operator would be awsome! \$\endgroup\$ – t3chb0t Aug 6 at 18:56
1
\$\begingroup\$

Review

  • Add usually means append at the back of a list. I would prefer InsertAfter.
  • Disposing the root LoggerMiddleware of the chain is not possible. Is this as designed?
  • Should LoggerTransaction be idempotent? If so, use a Queue instead of List and dequeue the items on Commit.
\$\endgroup\$
  • 1
    \$\begingroup\$ If you call Commit twice, you wish to forward the log entries twice to the next in chain? \$\endgroup\$ – dfhwze Aug 3 at 12:32
  • 1
    \$\begingroup\$ Oh! Of course not! Good catch. \$\endgroup\$ – t3chb0t Aug 3 at 12:32
  • 1
    \$\begingroup\$ I have made a similar log wrapper in my current project. The way I use it is similar to your transaction. But I also allow to combine the logs, and forward a single log entry to the next in chain. This way, multiple logs can be grouped together to get a nice 'report' layout in some log backend. Might be an interesting concept to put in your framework as well. \$\endgroup\$ – dfhwze Aug 3 at 12:34
  • 1
    \$\begingroup\$ Yeah, I already thought of it ;-) I call my system semantic-logging and I actually very rarely log any messages. I use my logs directly to generate reports. They have multiple levels of correlation ids, layer ids like business, service, io, snapshot in json format or elapsed times; so I can join or put together virtually any data I want ;-) \$\endgroup\$ – t3chb0t Aug 3 at 12:38
  • 1
    \$\begingroup\$ I once read about async logging in an article about the logger in microsoft extensions. They meant logging should be fast and that's why they don't provide an async API. I like that theory and I think I won't be considering making it async currently... until I stumble on something else that would convince me of the opposite. \$\endgroup\$ – t3chb0t Aug 3 at 13:11
1
\$\begingroup\$

(self-answer)


This pattern has proven itself in practice so I'll keep it for my logging layer. I extended the POC in many places. The middleware has gotten an interface and each middleware I now call Nodes. I have implemented also many ideas from other related questions (like IsActive or queues). Thanks a lot! ;-)

public interface ILinkedListNode<T>
{
    T Previous { get; }

    T Next { get; }

    T InsertNext(T next);

    /// <summary>
    /// Removes this node from the chain an returns the Previous item or Next if Previous is null.
    /// </summary>
    /// <returns></returns>
    T Remove();
}

Thre is also a default implementation with linked-list operations that I need for this framework only so some of them are missing.

public abstract class LoggerNode : ILinkedListNode<LoggerNode>, IDisposable
{
    public LoggerNode(bool isActive)
    {
        IsActive = isActive;
    }

    public virtual bool IsActive { get; set; } = true;

    #region ILinkeListNode

    [JsonIgnore]
    public LoggerNode Previous { get; private set; }

    [JsonIgnore]
    public LoggerNode Next { get; private set; }

    #endregion

    // Inserts a new middleware after this one and returns the new one.
    public LoggerNode InsertNext(LoggerNode next)
    {
        (next.Previous, next.Next, Next) = (this, Next, next);
        return next;
    }

    public LoggerNode Remove()
    {
        var result = default(LoggerNode);

        if (!(Previous is null))
        {
            result = Previous;
            (Previous.Next, Previous) = (Next, null);
        }

        if (!(Next is null))
        {
            result = result ?? Next;
            (Next.Previous, Next) = (Previous, null);
        }

        return result;
    }

    public void Invoke(LogEntry request)
    {
        if (IsActive)
        {
            InvokeCore(request);
        }
        else
        {
            Next?.Invoke(request);
        }
    }

    protected abstract void InvokeCore(LogEntry request);

    // Removes itself from the middleware chain.
    public virtual void Dispose()
    {
        Remove();
    }
}

TransactionNode was a little bit challenging. It now uses a LoggerScope<T> helper that is borrowed from the asp.net-core console logger and made reusable because I need it for other nodes too. It maintains a State in an async context which allows to open many independent scopes:

public class LoggerScope<T>
{
    private static readonly AsyncLocal<LoggerScope<T>> State = new AsyncLocal<LoggerScope<T>>();

    private LoggerScope(T value)
    {
        Value = value;
    }

    public T Value { get; }

    private LoggerScope<T> Parent { get; set; }

    public static LoggerScope<T> Current
    {
        get => State.Value;
        private set => State.Value = value;
    }

    public static bool IsEmpty => Current is null;

    public static LoggerScope<T> Push(T value)
    {
        return Current = new LoggerScope<T>(value) { Parent = Current };
    }

    public void Dispose()
    {
        Current = Current?.Parent;
    }
}

Here, I use it for keeping Queue buffers fol log-entries.

public class TransactionNode : LoggerNode, ILoggerScope<TransactionNode.Scope, object>
{
    public TransactionNode() : base(false) { }

    public override bool IsActive => !LoggerScope<Scope>.IsEmpty;

    protected override void InvokeCore(LogEntry request)
    {
        LoggerScope<Scope>.Current.Value.Buffer.Enqueue(request);
        // Don't call Next until Commit.
    }

    public Scope Push(object parameter)
    {
        return LoggerScope<Scope>.Push(new Scope { Next = Next }).Value;
    }

    public class Scope : IDisposable
    {
        internal Queue<LogEntry> Buffer { get; } = new Queue<LogEntry>();

        internal LoggerNode Next { get; set; }

        public void Commit()
        {
            while (Buffer.Any())
            {
                Next?.Invoke(Buffer.Dequeue());
            }
        }

        public void Rollback()
        {
            Buffer.Clear();
        }


        public void Dispose()
        {
            Buffer.Clear();
            LoggerScope<Scope>.Current.Dispose();
        }
    }
}

The entire framework has grown a lot. If anyone would like to take a look at the API, it's in my repo here.

\$\endgroup\$
  • 1
    \$\begingroup\$ A cool thing you can do now with the node is to add methods cloack and uncloack. Cloacking a node removes itself from the chain, but keeps the references to prev and next in the deleted node. Uncloacking the node lets the node put itself back in the chain at its location before cloacking. Whether you would need this, is up to you. It's an alternative for IsActive. \$\endgroup\$ – dfhwze Aug 6 at 18:43
  • 1
    \$\begingroup\$ @dfhwze haha, this is pretty cool, indeed. I have currently no idea why I would need it but it may be fun to implement it anyway :-P Why not go all out and make a node move along the chain handling outputs of each previous node like a walking telemetry node - so whacked out! At the end it could jump back to the beginning. \$\endgroup\$ – t3chb0t Aug 6 at 18:51

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.