Entity Framework Core: Log queries for a single db

Question

Using EF Core (or any ORM for that matter) I want to keep track of the number of queries the ORM makes to the database during some operation in my software.

I've used SQLAlchemy under Python earlier, and on that stack this is faily easy to set up. I typically have unit tests that assert on the number of queries made for a scenario, against an in-memory SQLite database.

Now I want to do the same thing using EF Core, and have looked at the Logging documentation.

In my test setup code I do as the documentation says:

using (var db = new BloggingContext())
{
    var serviceProvider = db.GetInfrastructure<IServiceProvider>();
    var loggerFactory = serviceProvider.GetService<ILoggerFactory>();
    loggerFactory.AddProvider(new MyLoggerProvider());
}

But I run into problems that I suspect are the results of the following (also from the docs):

You only need to register the logger with a single context instance. Once you have registered it, it will be used for all other instances of the context in the same AppDomain.

The problems I see in my tests indicates that my logger implementation is shared across multiple contexts (this is in accordance with the docs as I read them). And since a) my test runner runs tests in parallell and b) my entire test suite creates hundreds of db contexts - it does not work very well.

Question/issues:

• Is what I want possible?
• I.e. can I register a logger with a db context that is only used for that db context instance?
• Are there other ways to accomplish what I am trying to do?

Answer 1

Read this: docs.microsoft.com/en-us/ef/core/miscellaneous/logging

It is very important that applications do not create a new ILoggerFactory instance for each context instance. Doing so will result in a memory leak and poor performance.1

If you want to log to static destionation (e.g. console) Ilja's answer works, but if you want to log first to custom buffers, when each dbContext collects log messages to its own buffer (and that what you would like to do in multiuser service), then UPSSS - memory leaks (and memory leak is about 20 mb per almost empty model)...

When EF6 had simple solution to subscribe to an Log event in one line, now to inject your logging this way:

        var messages = new List<string>();
        Action<string> verbose = (text) => {
            messages.Add(text);
        }; // add logging message to buffer

        using (var dbContext = new MyDbContext(BuildOptionsBuilder(connectionString, inMemory), verbose))
        {
             //..
        };

you should write the pooling monster.

P.S. Somebody tell to Ef Core architects that they have wrong understanding of DI and those fancy service locators that they call "containers" and fluent UseXXX that they borrow from ASP.Core can't replace "vulgar" DI from constructor. At least log function should be normally injectable.

*P.P.S. Read also this https://github.com/aspnet/EntityFrameworkCore/issues/10420 . This means that adding LoggerFactory brokes access to InMemory data provider. This is an Abstraction Leak as it is. EF Core has problems with architecture.

ILoggerFactory pooling code:

public class StatefullLoggerFactoryPool
{
    public static readonly StatefullLoggerFactoryPool Instance = new StatefullLoggerFactoryPool(()=> new StatefullLoggerFactory());
    private readonly Func<StatefullLoggerFactory> construct;
    private readonly ConcurrentBag<StatefullLoggerFactory> bag = new ConcurrentBag<StatefullLoggerFactory>();

    private StatefullLoggerFactoryPool(Func<StatefullLoggerFactory> construct) =>
        this.construct = construct;

    public StatefullLoggerFactory Get(Action<string> verbose, LoggerProviderConfiguration loggerProviderConfiguration)
    {
        if (!bag.TryTake(out StatefullLoggerFactory statefullLoggerFactory))
            statefullLoggerFactory = construct();
        statefullLoggerFactory.LoggerProvider.Set(verbose, loggerProviderConfiguration);
        return statefullLoggerFactory;
    }

    public void Return(StatefullLoggerFactory statefullLoggerFactory)
    {
        statefullLoggerFactory.LoggerProvider.Set(null, null);
        bag.Add(statefullLoggerFactory);
    }
}

 public class StatefullLoggerFactory : LoggerFactory
{
    public readonly StatefullLoggerProvider LoggerProvider;
    internal StatefullLoggerFactory() : this(new StatefullLoggerProvider()){}

    private StatefullLoggerFactory(StatefullLoggerProvider loggerProvider) : base(new[] { loggerProvider }) =>
        LoggerProvider = loggerProvider;
}

public class StatefullLoggerProvider : ILoggerProvider
{
    internal LoggerProviderConfiguration loggerProviderConfiguration;
    internal Action<string> verbose;
    internal StatefullLoggerProvider() {}

    internal void Set(Action<string> verbose, LoggerProviderConfiguration loggerProviderConfiguration)
    {
        this.verbose = verbose;
        this.loggerProviderConfiguration = loggerProviderConfiguration;
    }

    public ILogger CreateLogger(string categoryName) =>
        new Logger(categoryName, this);

    void IDisposable.Dispose(){}
}

public class MyDbContext : DbContext
{
    readonly Action<DbContextOptionsBuilder> buildOptionsBuilder;
    readonly Action<string> verbose;
    public MyDbContext(Action<DbContextOptionsBuilder> buildOptionsBuilder, Action<string> verbose=null): base()
    {
        this.buildOptionsBuilder = buildOptionsBuilder;
        this.verbose = verbose;
    }

     private Action returnLoggerFactory;
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        if (verbose != null)
        {
            var loggerFactory = StatefullLoggerFactoryPool.Instance.Get(verbose, new LoggerProviderConfiguration { Enabled = true, CommandBuilderOnly = false });
            returnLoggerFactory = () => StatefullLoggerFactoryPool.Instance.Return(loggerFactory);
            optionsBuilder.UseLoggerFactory(loggerFactory);
        }
        buildOptionsBuilder(optionsBuilder);
    }

    // NOTE: not threadsafe way of disposing
    public override void Dispose()
    {
        returnLoggerFactory?.Invoke();
        returnLoggerFactory = null;
        base.Dispose();
    }
}

    private static Action<DbContextOptionsBuilder> BuildOptionsBuilder(string connectionString, bool inMemory)
    {
        return (optionsBuilder) =>
        {
            if (inMemory)
                optionsBuilder.UseInMemoryDatabase(
                  "EfCore_NETFramework_Sandbox"
                );
            else
                //Assembly.GetAssembly(typeof(Program))
                optionsBuilder.UseSqlServer(
                        connectionString,
                        sqlServerDbContextOptionsBuilder => sqlServerDbContextOptionsBuilder.MigrationsAssembly("EfCore.NETFramework.Sandbox")
                        );
        };
    }

class Logger : ILogger
{
    readonly string categoryName;
    readonly StatefullLoggerProvider statefullLoggerProvider;
    public Logger(string categoryName, StatefullLoggerProvider statefullLoggerProvider)
    {
        this.categoryName = categoryName;
        this.statefullLoggerProvider = statefullLoggerProvider;
    }

    public IDisposable BeginScope<TState>(TState state) =>
        null;

    public bool IsEnabled(LogLevel logLevel) =>
        statefullLoggerProvider?.verbose != null;

    static readonly List<string> events = new List<string> {
            "Microsoft.EntityFrameworkCore.Database.Connection.ConnectionClosing",
            "Microsoft.EntityFrameworkCore.Database.Connection.ConnectionClosed",
            "Microsoft.EntityFrameworkCore.Database.Command.DataReaderDisposing",
            "Microsoft.EntityFrameworkCore.Database.Connection.ConnectionOpened",
            "Microsoft.EntityFrameworkCore.Database.Connection.ConnectionOpening",
            "Microsoft.EntityFrameworkCore.Infrastructure.ServiceProviderCreated",
            "Microsoft.EntityFrameworkCore.Infrastructure.ContextInitialized"
        };

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        if (statefullLoggerProvider?.verbose != null)
        {
            if (!statefullLoggerProvider.loggerProviderConfiguration.CommandBuilderOnly ||
                (statefullLoggerProvider.loggerProviderConfiguration.CommandBuilderOnly && events.Contains(eventId.Name) ))
            {
                var text = formatter(state, exception);
                statefullLoggerProvider.verbose($"MESSAGE; categoryName={categoryName} eventId={eventId} logLevel={logLevel}" + Environment.NewLine + text);
            }
        }
    }
}

Answer 2

Call DbContextOptionsBuilder.UseLoggerFactory(loggerFactory) to log all SQL output of a particular context instance. You could inject a logger factory in the context's constructor.

Usage example:

//this context writes SQL to any logs and to ReSharper test output window
using (var context = new TestContext(_loggerFactory))
{
    var customers = context.Customer.ToList();
}

//this context doesn't
using (var context = new TestContext())
{
    var products = context.Product.ToList();
}

Generally I use this feature for manual testing. To keep an original context class clean, a derived testable context is declared with overridden OnConfiguring method:

public class TestContext : FooContext
{
    private readonly ILoggerFactory _loggerFactory;

    public TestContext() { }

    public TestContext(ILoggerFactory loggerFactory)
    {
        _loggerFactory = loggerFactory;
    }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        base.OnConfiguring(optionsBuilder);

        optionsBuilder.UseLoggerFactory(_loggerFactory);
    }
}

It's enough to log SQL queries (attach loggers to loggerFactory before you pass it to context).

Part II: Pass logs to xUnit output and ReSharper test output window

We can create a loggerFactory in test class constructor:

public class TestContext_SmokeTests : BaseTest
{
    public TestContext_SmokeTests(ITestOutputHelper output)
        : base(output)
    {
        var serviceProvider = new ServiceCollection().AddLogging().BuildServiceProvider();

        _loggerFactory = serviceProvider.GetService<ILoggerFactory>();

        _loggerFactory.AddProvider(new XUnitLoggerProvider(this));
    }

    private readonly ILoggerFactory _loggerFactory;
}

Test class is derived from BaseTest which allows writing to xUnit output:

public interface IWriter
{
    void WriteLine(string str);
}

public class BaseTest : IWriter
{
    public ITestOutputHelper Output { get; }

    public BaseTest(ITestOutputHelper output)
    {
        Output = output;
    }

    public void WriteLine(string str)
    {
        Output.WriteLine(str ?? Environment.NewLine);
    }
}

Most tricky part is to implement a logging provider accepting IWriter as a parameter:

public class XUnitLoggerProvider : ILoggerProvider
{
    public IWriter Writer { get; private set; }

    public XUnitLoggerProvider(IWriter writer)
    {
        Writer = writer;
    }
    public void Dispose()
    {
    }

    public ILogger CreateLogger(string categoryName)
    {
        return new XUnitLogger(Writer);
    }

    public class XUnitLogger : ILogger
    {
        public IWriter Writer { get; }

        public XUnitLogger(IWriter writer)
        {
            Writer = writer;
            Name = nameof(XUnitLogger);
        }

        public string Name { get; set; }

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
            Func<TState, Exception, string> formatter)
        {
            if (!this.IsEnabled(logLevel))
                return;

            if (formatter == null)
                throw new ArgumentNullException(nameof(formatter));

            string message = formatter(state, exception);
            if (string.IsNullOrEmpty(message) && exception == null)
                return;

            string line = $"{logLevel}: {this.Name}: {message}";

            Writer.WriteLine(line);

            if (exception != null)
                Writer.WriteLine(exception.ToString());
        }

        public bool IsEnabled(LogLevel logLevel)
        {
            return true;
        }

        public IDisposable BeginScope<TState>(TState state)
        {
            return new XUnitScope();
        }
    }

    public class XUnitScope : IDisposable
    {
        public void Dispose()
        {
        }
    }
}

Required packages:

<PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="1.1.0" />
<PackageReference Include="Microsoft.Extensions.Logging" Version="1.1.1" />
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="1.1.1" />
<PackageReference Include="xunit" Version="2.2.0" />
<PackageReference Include="xunit.runner.visualstudio" Version="2.2.0" />

Answer 3

You can use a bounded context. I used EF Coed first to create two different contexts

Customer bounded context will not log any queries

public class CustomerModelDataContext : DbContext
{
    public DbSet<Customer> Customers { get; set; }

    public DbSet<PostalCode> PostalCodes { get; set; }

    public CustomerModelDataContext()
        : base("ConnectionName")
    {
        Configuration.LazyLoadingEnabled = true;
        Configuration.ProxyCreationEnabled = true;
        Database.SetInitializer<CustomerModelDataContext>(new Initializer<CustomerModelDataContext>());
        //Database.Log = message => DBLog.WriteLine(message);
    }

    protected override void OnModelCreating(DbModelBuilder modelBuilder)
    {
        base.OnModelCreating(modelBuilder);
    }
}

API bounded context will log the queries

public class ApiModelDataContext : DbContext
{
    public DbSet<ApiToken> ApiTokens { get; set; }

    public DbSet<ApiClient> ApiClients { get; set; }

    public DbSet<ApiApplication> ApiApplications { get; set; }

    public ApiModelDataContext() 
        : base("ConnectionName")
    {
        Configuration.LazyLoadingEnabled = true;
        Configuration.ProxyCreationEnabled = true;
        Database.SetInitializer<ApiModelDataContext>(new Initializer<ApiModelDataContext>());
        Database.Log = message => DBLog.WriteLine(message);
    }

    protected override void OnModelCreating(DbModelBuilder modelBuilder)
    {
        base.OnModelCreating(modelBuilder);
    }
}

this will log the query to debug output window in VS

public static class DBLog
{
    public static void WriteLine(string message)
    {
        Debug.WriteLine(message);
    }
}