Getting EF Core to output SQL statements to xUnit's ITestOutputHelper

Viewed 1023

I'm using EF Core 2.2.4 and am trying to figure out which SQL statements EF Core is sending to our SQLite database in our unit tests. Since we're using xUnit (2.4.1), we have to write log messages to the ITestOutputHelper instance xUnit is injecting into our test classes instead of the console. For the console, I have found this code:

private static ILoggerFactory GetLoggerFactory()
{
    IServiceCollection serviceCollection = new ServiceCollection();
    serviceCollection.AddLogging(builder =>
        builder.AddConsole()
            .AddFilter(DbLoggerCategory.Database.Command.Name,
                LogLevel.Information));
    return serviceCollection.BuildServiceProvider()
        .GetService<ILoggerFactory>();
}

What do I have to do to redirect this output to ITestOutputHelper.WriteLine()?

1 Answers

First, create some boilerplate logging code to allow outputting to ITestOutputHelper:

class TestLoggerProvider : ILoggerProvider
{
    ITestOutputHelper _output;

    public TestLoggerProvider(ITestOutputHelper output)
        => _output = output;

    public ILogger CreateLogger(string categoryName)
        => new TestLogger(categoryName, _output);

    public void Dispose()
    {
    }
}

class TestLogger : ILogger
{
    string _categoryName;
    ITestOutputHelper _output;

    public TestLogger(string categoryName, ITestOutputHelper output)
    {
        _categoryName = categoryName;
        _output = output;
    }

    public bool IsEnabled(LogLevel logLevel)
        // NB: Only logging things related to commands, but you can easily expand
        //     this
        => _categoryName == DbLoggerCategory.Database.Command.Name;

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception exception,
        Func<TState, Exception, string> formatter)
    {
        // TODO: Customize the formatting even more if you want
        //if (eventId == RelationalEventId.CommandExecuting)
        //{
        //    var structure = (IReadOnlyList<KeyValuePair<string, object>>)state;
        //    var parameters = (string)structure.First(i => i.Key == "parameters")
        //        .Value;
        //    var commandText = (string)structure.First(i => i.Key == "commandText")
        //        .Value;
        //}

        _output.WriteLine(formatter(state, exception));
    }

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

Next, make sure your DbContext can accept external options.

class MyDbContext : DbContext
{
    public MyDbContext(DbContextOptions<MyDbContext> options)
        : base(options)
    {
    }
}

Finally, wire it all up. Here is an example of creating a new context per test. Use a class or collection fixture to extend the lifetime of the context.

public class UnitTest1 : IDisposable
{
    IServiceProvider _serviceProvider;
    MyDbContext _db;

    public UnitTest1(ITestOutputHelper output)
    {
        _serviceProvider = new ServiceCollection()
            .AddLogging(x => x.AddProvider(new TestLoggerProvider(output)))
            .AddEntityFrameworkSqlite()
            .BuildServiceProvider();

        _db = new MyDbContext(
            new DbContextOptionsBuilder<MyDbContext>()
                // Don't call UseLoggerFactory! (a new service provider would be
                // created every time without ever getting disposed)
                .UseInternalServiceProvider(_serviceProvider)
                .UseSqlite("Data Source=:memory:")
                .Options);
    }

    [Fact]
    public void Test1()
    {
        _db.Database.ExecuteSqlRaw("-- Can you see me?");
    }

    public void Dispose()
    {
        _db.Dispose();
        (_serviceProvider as IDisposable)?.Dispose();
    }
}
Related