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.

Saturday, June 17, 2023

Profile MySQL db with Neor Profile SQL

If you need to profile MySQL db you may use builtin MySQL shell profiler (CLI). Also there is free GUI alternative - Neor Profile SQL. There are few things which should be done before to use it.

When you launch Profile SQL it asks to establish connection using default parameters for localhost:

If you click Test button you may get "Test is failed" error even with correct credentials of the root user. In order to avoid it you need to enable native MySQL password for the root user:

ALTER USER 'root'@'localhost' IDENTIFIED WITH mysql_native_password BY '...'

after that connection should be successful.

But that is not all. If after that you will run application which connects to MySQL you won't see sessions and queries in profiler - because profiler works as a proxy with own port (4040 by default):

and in order to collect data your application should connect to profiler (not to MySQL directly). I.e. we need to change port in connection string from MySQL port (3306 by default) to profiler port (4040):

{
  "ConnectionStrings": {
    "Default": "Server=localhost;Port=4040;Database=Test;User ID=test;Password=..."
  }
}

If after that connection will fail with System.IO.IOException (from MySql.Data.Common.Ssl namespace methods) add ";SSL Mode=None" to connection string:

{
  "ConnectionStrings": {
    "Default": "Server=localhost;Port=4040;Database=Test;User ID=test;Password=...;SSL Mode=None"
  }
}

After that application should connect to profiler successfully and you should see profiled data.

StackOverflowException when use hierarchical object mapping with AutoMapper and Fluent NHibernate lazy loading

Suppose that we have the following class Category with self-reference (regular parent-child hierarchy):

public class Category
{
    public virtual T Id { get; set; }
    public virtual string Name { get; set; }
    public virtual Category ParentCategory { get; set; }
    public virtual IList<Category> ChildCategories { get; set; }
}

(properties are virtual which is required by NHibernate). Regular Fluent NHibernate mapping for this class looks like this:

public class CategoryMap : ClassMap<Category>
{
    public CategoryMap()
    {
        Table("[Category]");
        Id(x => x.Id);
        
        Map(x => x.Name);

        References(x => x.ParentCategory)
            .Column("ParentCategoryId");
        
        HasMany(x => x.ChildCategories)
            .KeyColumn("ParentCategoryId")
            .Inverse()
            .AsBag();
    }
}

Then we want to show category in the view of ASP.Net Core MVC app and use the following view model for that:

public class CategoryModel
{
    public int? Id { get; set; }

    public string Name { get; set; }

    public string ParentCategoryName { get; set; }
}

For mapping Category to CategoryModel the following AutoMapper mapping is used:

public class ViewModelProfile : Profile
{
    public ViewModelProfile()
    {
        CreateMap<Category, CategoryModel>()
            .ForMember(x => x.ParentCategoryName, o => o.MapFrom(c => c.ParentCategory == null ? "" : c.ParentCategory.Name))
    }
}

i.e. when ParentCategory is null then ParentCategoryName property of view model is empty string, otherwise ParentCategoryName will return name of parent category. Until now everything looks good. Problems will start when we will try to create category of nesting level which is greater than 1, i.e. this will work:

child category -> parent category

but with deeper hierarchy:

child category1 -> child category2 -> parent category

we will get StackOverflowException when will try to pass view model (created by AutoMapper) to the view. Googling this problem suggests to use MaxDepth(2) call when create AotuMapper map profile to limit number of processed hierarchy levels but it didn't help because of some reason.

Solution which worked was to specify to not use lazy loading for ParentCategory property in Fluent NHibernate mapping (NHibernate uses lazy loading by default):

public class CategoryMap : ClassMap<Category>
{
    public CategoryMap()
    {
        Table("[Category]");
        Id(x => x.Id);
        
        Map(x => x.Name);

        References(x => x.ParentCategory)
            .Column("ParentCategoryId")
            .Not.LazyLoad();
        
        HasMany(x => x.ChildCategories)
            .KeyColumn("ParentCategoryId")
            .Inverse()
            .AsBag();
    }
}

In theory it may cause performance problems with large amount of data and deep hierarchy levels but with reasonable amount of data should work quite well.