Redeveloping WordTutor
Logging Implementation

To implement the logging interfaces described earlier, there are some issues we need to consider. There are two different usage patterns we need to support, plus we need to support concurrent use, and avoid code duplication.

Usage Scenarios

The first scenario is when a method controls the context of its logging; the logger reference it needs is immediate to hand and easily used. Different parts of the application will pass around the logger as required.

The second, and more complex, is when a helper method wants to ensure that its logging is properly included in the active scope. We need to have some way for the current logging context to be found when required. Preferably, this would be a technique that doesn’t require adding a logger to every method signature.

For each of these scenarios, we will create a different logging class - a ScopedLogger for the case where we are keeping explicit references to our current logging context, and a DelegatingLogger for the case where we need to coordinate with a context created elsewhere. They will share the common base class LoggerBase to avoid code duplication.

Asynchronous support

To cleanly associate a distinct logger with each asynchronous task, we want something akin to the [ThreadLocal] attribute; fortunately, we don’t need to look far to find the AsyncLocal<T> class. We use this to declare a static property to give us access to the logger wherever needed:

public abstract class LoggerBase
{
    private static readonly AsyncLocal<ScopedLogger?> _currentLogger
        = new AsyncLocal<ScopedLogger?>();

    protected static ScopedLogger? CurrentLogger
    {
        get => _currentLogger.Value;
        set => _currentLogger.Value = value;
    }
}

With this in place, we can introduce methods to actually write the message out:

public abstract class LoggerBase
{
    protected abstract void WriteLogMessage(
        LogKind logKind, 
        string message);

    protected void WriteLogMessage(
        ScopedLogger? currentAction, 
        LogKind logKind, 
        string message)
    {
        var level = currentAction?.Level ?? 0;
        var now = DateTimeOffset.Now;
        WriteLine($"{now:u} {Indent(level)}{_prefixes[logKind]} {message}");
    }
}

For DelegatingLogger, we implement the abstract WriteLogMessge using CurrentLogger:

public sealed class DelegatingLogger : LoggerBase, ILogger
{
    protected override void WriteLogMessage(
        LogKind logKind, string message)
        => WriteLogMessage(CurrentLogger, logKind, message);
}

Conversely, for ScopedLogger, we already know the necessary context and we can pass it directly:

public sealed class ScopedLogger: LoggerBase, IScopedLogger
{
    protected override void WriteLogMessage(
        LogKind logKind, 
        string message)
    {
        if (_disposed)
        {
            throw new ObjectDisposedException(
                "Scoped loggers may not be used after disposal.");
        }

        base.WriteLogMessage(this, logKind, message);
    }
}

I’ve thrown in a little sanity check to ensure we’re not continuing to use a scoped logger after the scope has been completed.

Avoiding code duplication

We introduced the base class LoggerBase that provides functionality common to both logging situations. As a part of that class, let us declare an enumeration that captures the different kinds of logging messages we want to emit:

protected enum LogKind
{
    None,
    Debug,
    Info,
    OpenAction,
    CloseAction,
    Success,
    Failure
}

We can then implement most of our desired logging methods as simple helpers that all delegate to WriteLogMessage():

public void Success(string message)
    => WriteLogMessage(LogKind.Success, message);

public void Failure(string message)
    => WriteLogMessage(LogKind.Failure, message);

public void Info(string message)
    => WriteLogMessage(LogKind.Info, message);

public void Debug(string message)
    => WriteLogMessage(LogKind.Debug, message);

The remaining log method is Action, which returns a scoped logger after updating CurrentLogger to match.

public IScopedLogger Action(string message)
{
    WriteLogMessage(LogKind.OpenAction, message);
    CurrentLogger = new ScopedLogger(CurrentLogger);
    return CurrentLogger;
}

For each kind of log message, we define a dictionary of prefixes to use so that they’re easily distinguishable in the output:

private readonly Dictionary<LogKind, string> _prefixes
    = new Dictionary<LogKind, string>
    {
        { LogKind.Debug, " · " },
        { LogKind.Info, "[•]" },
        { LogKind.OpenAction, "[>]" },
        { LogKind.CloseAction, "[<]" },
        { LogKind.Success, "[✔]" },
        { LogKind.Failure, "[✘]" }
    };

It’s very common for text-based loggers to use somewhat cryptic abbreviations for the different log levels. Here we could have instead used DBG, INF, STA, FIN, SUC and ERR - but I wanted something with a little more visual appeal, so I’ve used some Unicode characters instead.

Conclusion

With this text-based logger in place, we can review the use of the application using the Output window of Visual Studio. Later on, we might want to replace this with something built into the application to allow troubleshooting without Visual Studio.