Entity Framework Core: Log queries for a single db context instance

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?

Swastika

What is your test runner; NUnit, MsTest, XUnit? – Osteal

Test runner Xunit – Swastika

Did you figure this out? I tried filtering for Microsoft.EntityFrameworkCore.Storage.Internal.SqliteRelationalConnection but don't get anything. – Tonsil

Would including Thread.CurrentThread.ManagedThreadId in your logs help? – Tokoloshe

Have you tried miniprofiler.com – Naresh

@Tokoloshe will try. – Swastika

Answer 1

For EF Core 5.0 Simple Logging (what a name!) was introduced

EF Core logs can be accessed from any type of application through the use of LogTo when configuring a DbContext instance. This configuration is commonly done in an override of DbContext.OnConfiguring. For example:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine);

Alternately, LogTo can be called as part of AddDbContext or when creating a DbContextOptions instance to pass to the DbContext constructor.

Writing to a file. But I'd rather inject some kind of logger into db context and use it instead of writing logging logic inside of context.

private readonly StreamWriter _logStream = new StreamWriter("mylog.txt", append: true);

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(_logStream.WriteLine);

public override void Dispose()
{
    base.Dispose();
    _logStream.Dispose();
}

public override async ValueTask DisposeAsync()
{
    await base.DisposeAsync();
    await _logStream.DisposeAsync();
}

Handgun

Nice and clean solution. – Strathspey

Answer 2

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

Here is a 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 the 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. Don't forget to attach a suitable logger (like Console) 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 a 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;
}

The test class is derived from BaseTest which supports the 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);
    }
}

The 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()
        {
        }
    }
}

We've done here! All the SQL logs will be shown in Rider/Resharper test output window.

Roper

Please, explain how get _loggerFactory to use it like this: new TestContext(_loggerFactory)? – Grus

@Grus : Use DI to get ILoggerFactory implementation. Register it in Startup: services.AddLogging();. Then inject the ILoggerFactory interface via constructor to the class which calls new TestContext(_loggerFactory). – Roper

learn.microsoft.com/en-us/ef/core/miscellaneous/logging wirte:"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." So actually it is impossible to create loggerFactory for "single context"... loggerFactory should be global! Or you should use pool of loggerFactories. – Sorority

@RomanPokrovskij the OP issue is about testing (and mine was the same). You don't need to care about memory leak in integration tests most of time: xUnit re-creates test classes per each test case by default, so it's OK to use the trick described above. – Roper

anyway to get the sql that will be executed but not actually execute it ? – Buhler

Can you please show how you do the DI to get the ILoggerFactory? It's not really clear how this all works together. – Anlace

@JeremyThompson, what exactly do you mean? In this example, a factory instance is created by .GetService<ILoggerFactory>() call, then all you need is to pass the factory to TestContext constructor. – Roper

I did everything, it was going well, but trying to put it altogether the very first line tripped me up... where do you get the _loggerFactory from? using (var context = new TestContext(_loggerFactory)) - ok I think I may have answered my own question, before you execute the test you wire up the ServiceCollection and its from there you get the reference. I'll give it another go. – Anlace

@JeremyThompson you're right, _loggerFactory is set in a test class constructor – Roper

Answer 3

Very simply, Install this Nuget package => Microsoft.Extensions.Logging.Console (right click on your project=> Manage Nuget packages => then look for it) (or on this link https://www.nuget.org/packages/Microsoft.Extensions.Logging.Console/ ) then Rebuild the project // then your db context have to look like this =>

    public class Db : DbContext
    {

    public readonly ILoggerFactory MyLoggerFactory;

        public Db()
        {
            MyLoggerFactory = LoggerFactory.Create(builder => { builder.AddConsole(); });
        }

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

            optionsBuilder.UseLoggerFactory(MyLoggerFactory);
        }
    }

Result =>

Hermineherminia

also make sure you put initialization code into proper constructor. I was configuring mine with DI, so it used this overload public ApplicationDbContext(DbContextOptions<ApplicationDbContext> options) instead of parameterless constructor, giving me no logging at all as a result – Handgun

Answer 4

Read this: learn.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 through constructor.

*P.P.S. Read also this https://github.com/aspnet/EntityFrameworkCore/issues/10420 . This means that adding LoggerFactory broke 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);
            }
        }
    }
}

Sorority

Answer 5

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);
    }
}

Adoration

None of this applies to EF Core though. – Kleiman