Thursday, June 22, 2023

Implement TAP/multithread friendly logging scopes for Microsoft.Extensions.Logging.ILogger

Some time ago I wrote a post how to implement custom logger which writes logs to Azure storage blob container: Custom logger for .Net Core for writing logs to Azure BLOB storage. This logger implements ILogger interface from Microsoft.Extensions.Logging namespace. It works quite well but doesn't support logging scopes:

public IDisposable BeginScope<TState>(TState state) => default!;

Logging scopes are quite useful - they allow to specify additional information e.g. from each method log record was added, etc:

public void Foo()
{
    using (logger.BeginScope("Outer scope"))
    {
        ...
        using (logger.BeginScope("Inner scope"))
        {
        }
    }
}

Important requirement for logging scopes is that it should work properly in Task-based asynchronous pattern (TAP) and multithread code (which is widely used nowadays). For that we will use AsyncLocal<T> class from .NET. For implementing scopes themselves we will use linked list (child-parent relation).

For implementing it we will create LogScopeProvider class which implements Microsoft.Extensions.Logging.IExternalScopeProvider interface (for creating this custom LogScopeProvider I used code from Microsoft.Extensions.Logging.Console namespace as base example):

public class LogScopeProvider : IExternalScopeProvider
{
    private readonly AsyncLocal<LogScope> currentScope = new AsyncLocal<LogScope>();

    public object Current => this.currentScope.Value?.State;

    public LogScopeProvider() {}

    public void ForEachScope<TState>(Action<object, TState> callback, TState state)
    {
        void Report(LogScope current)
        {
            if (current == null)
            {
                return;
            }
            Report(current.Parent);
            callback(current.State, state);
        }

        Report(this.currentScope.Value);
    }

    public IDisposable Push(object state)
    {
        LogScope parent = this.currentScope.Value;
        var newScope = new LogScope(this, state, parent);
        this.currentScope.Value = newScope;

        return newScope;
    }

    private class LogScope : IDisposable
    {
        private readonly LogScopeProvider provider;
        private bool isDisposed;

        internal LogScope(LogScopeProvider provider, object state, LogScope parent)
        {
            this.provider = provider;
            State = state;
            Parent = parent;
        }

        public LogScope Parent { get; }

        public object State { get; }

        public override string ToString()
        {
            return State?.ToString();
        }

        public void Dispose()
        {
            if (!this.isDisposed)
            {
                this.provider.currentScope.Value = Parent;
                this.isDisposed = true;
            }
        }
    }
}

Note that LogScopeProvider stores scopes as AsyncLocal<LogScope> which allows to use it in TAP code. So e.g. if we have await inside using(scope) it will be handled correctly:

public async Task Foo()
{
    using (logger.BeginScope("Outer scope"))
    {
        var result = await Bar();
        ...
    }
}

Now returning to our BlobStorage: all we have to is to pass LogScopeProviderto its constructor, add current scope to the log record and return new scope when it is requested (check bold code):

public class BlobLogger : ILogger
{
    private const string CONTAINER_NAME = "custom-logs";
    private string connStr;
    private string categoryName;
    private LogScopeProvider scopeProvider;
 
    public BlobLogger(string categoryName, string connStr, LogScopeProvider scopeProvider)
    {
        this.connStr = connStr;
        this.categoryName = categoryName;
        this.scopeProvider = scopeProvider;
    }
 
    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        if (!IsEnabled(logLevel))
        {
            return;
        }
 
        string scope = this.scopeProvider.Current as string;
        using (var ms = new MemoryStream(Encoding.UTF8.GetBytes($"[{this.categoryName}: {logLevel,-12}] {scope} {formatter(state, exception)}{Environment.NewLine}")))
        {
            var container = this.ensureContainer();
            var now = DateTime.UtcNow;
            var blob = container.GetAppendBlobClient($"{now:yyyyMMdd}/log.txt");
            blob.CreateIfNotExists();
            blob.AppendBlock(ms);
        }
    }
 
    private BlobContainerClient ensureContainer()
    {
        var container = new BlobContainerClient(this.connStr, CONTAINER_NAME);
        container.CreateIfNotExists();
        return container;
    }
 
    public bool IsEnabled(LogLevel logLevel) => true;
 
    public IDisposable BeginScope<TState>(TState state) => this.scopeProvider.Push(state);
}

That's it: now our logger also supports logging scopes.

No comments:

Post a Comment