Migrations: SQL not logged on SqlServerCompact

[ErikEJ]

The logger implementation here (based on a sample from @rowanmiller ) works well for logging both INSERTS/UPDATES and SELECT, except for SQL statements generated by EnsureCreated (migrations)

https://github.com/ErikEJ/EntityFramework.SqlServerCompact/blob/master/src/Provider40/Extensions/Logging/DbLoggerProvider.cs

(I was unable to find an existing issue for this)

Further technical details

EF Core version: 1.2.0-preview1-22878
Database Provider: EntityFrameworkCore.SqlServerCompact40
Operating system: Windows 10
IDE: (e.g. Visual Studio 2015): VS 2015 Update 3

[ajcvickers]

Hi @ErikEJ. I tried this with the following code and got the output below. It seems like commands from EnsureCreated are getting logged. Is there something else I need to do to repro this?

public class Blog
{
    public int Id { get; set; }
    public string Title { get; set; }

    public ICollection<Post> Posts { get; set; }
}

public class Post
{
    public int Id { get; set; }

    public int BlogId { get; set; }
    public Blog Blog { get; set; }
    public string Title { get; set; }
}

public class BlogContext : DbContext
{
    public DbSet<Blog> Blogs { get; set; }
    public DbSet<Post> Posts { get; set; }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    {
        optionsBuilder.UseSqlite(@"Data Source=.db");
    }
}

public class Program
{
    private static void Main()
    {
        using (var context = new BlogContext())
        {
            context.GetService<ILoggerFactory>().AddProvider(new DbLoggerProvider());

            context.Database.EnsureDeleted();
            context.Database.EnsureCreated();

            var blog = new Blog {Posts = new List<Post> { new Post() } };

            context.Add(blog);

            context.SaveChanges();
        }
    }
}

internal class DbLoggerProvider : ILoggerProvider
{
    private static readonly string[] Whitelist =
    {
        typeof(IRelationalCommandBuilderFactory).FullName
    };

    public ILogger CreateLogger(string name) 
        => Whitelist.Contains(name) ? (ILogger)new MyLogger() : NullLogger.Instance;

    public void Dispose()
    {
    }

    private class MyLogger : ILogger
    {
        public bool IsEnabled(LogLevel logLevel) => true;

        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
            Func<TState, Exception, string> formatter)
            => Console.WriteLine(formatter(state, exception));

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

Output:

Executed DbCommand (4ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
PRAGMA foreign_keys=ON;
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
PRAGMA foreign_keys=ON;
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
PRAGMA foreign_keys=ON;
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
PRAGMA foreign_keys=ON;
Executed DbCommand (1ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE "Blogs" (
    "Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT,
    "Title" TEXT
);
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE "Posts" (
    "Id" INTEGER NOT NULL CONSTRAINT "PK_Posts" PRIMARY KEY AUTOINCREMENT,
    "BlogId" INTEGER NOT NULL,
    "Title" TEXT,
    CONSTRAINT "FK_Posts_Blogs_BlogId" FOREIGN KEY ("BlogId") REFERENCES "Blogs" ("Id") ON DELETE CASCADE
);
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE INDEX "IX_Posts_BlogId" ON "Posts" ("BlogId");
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
PRAGMA foreign_keys=ON;
Executed DbCommand (5ms) [Parameters=[@p0='?'], CommandType='Text', CommandTimeout='30']
INSERT INTO "Blogs" ("Title")
VALUES (@p0);
SELECT "Id"
FROM "Blogs"
WHERE changes() = 1 AND "Id" = last_insert_rowid();
Executed DbCommand (0ms) [Parameters=[@p1='?', @p2='?'], CommandType='Text', CommandTimeout='30']
INSERT INTO "Posts" ("BlogId", "Title")
VALUES (@p1, @p2);
SELECT "Id"
FROM "Posts"
WHERE changes() = 1 AND "Id" = last_insert_rowid();```

[ErikEJ]

Thanks @ajcvickers I guess my event filtering is too strict: https://github.com/ErikEJ/EntityFramework.SqlServerCompact/blob/master/src/Provider40/Extensions/Logging/DbSimpleLogger.cs#L25

[ErikEJ]

Actually, it was not a filtering issue, it is due to this: https://github.com/aspnet/EntityFramework/blob/aff7bef4db688325af12cc45f825e19fc2b2bd00/src/Microsoft.EntityFrameworkCore.Relational/Storage/RelationalDataReader.cs#L77

(Dispose of the DbCommand causes the SQL CE provider to clear the CommandText) 😢

[ajcvickers]

Marking for re-triage. Questions to consider:

• Is this only for SQL CE?
• Is it worth trying to work around it by saving away the command text somewhere?
• Can this be done by any provider that needs to do it without it being done always?

[ErikEJ]

@ajcvickers Thanks for reconsidering, found this older related issue: #3654

[ErikEJ]

Actually, it might not be what I thought was the issue, that is: #3654 command?.Dispose(); - All statements, even INSERTs are logged correctly in the standard SaveChanges/Query pipeline, only the Migration SQL is not logged.

When I run this test: https://github.com/ErikEJ/EntityFramework.SqlServerCompact/blob/master/test/EntityFramework.SqlServerCompact.FunctionalTests/BasicEndToEndScenarioForIdentity.cs I get this output, notice that the initial CREATE TABLE statement is missing

Executed DbCommand (26ms) [Parameters=[@p0='?' (Size = 4000)], CommandType='Text', CommandTimeout='0']
INSERT INTO [Blogs] ([Url])
VALUES (@p0)

Executed DbCommand (7ms) [Parameters=[@p0='?' (Size = 4000)], CommandType='Text', CommandTimeout='0']
SELECT [Id]
FROM [Blogs]
WHERE 1 = 1 AND [Id] = CAST (@@IDENTITY AS int)

Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='0']
SELECT [b].[Id], [b].[Url]
FROM [Blogs] AS [b]

[ajcvickers]

@ErikEJ Is there something you wan us to investigate here?

[ErikEJ]

@ajcvickers Yes, I am wondering why statement logging works only for query and update pipeline, but not for migrations - am I doing something wrong, or is it "by design" ?

[ajcvickers]

@ErikEJ When I run that test against SQL Server, this is what I see getting logged. If you modify the test on your machine to hit SQL Server do you see the migrations commands being logged? Or are you saying that you don't see the migrations commands only when trying to filter? If so, that's probably covered by #7217.

Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Closing connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'master' on server '(localdb)\mssqllocaldb'.
Executed DbCommand (18ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
IF SERVERPROPERTY('EngineEdition') <> 5 EXEC(N'ALTER DATABASE [EF11Test] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;');
Executed DbCommand (21ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
DROP DATABASE [EF11Test];
Closing connection to database 'master' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'master' on server '(localdb)\mssqllocaldb'.
Executed DbCommand (258ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
CREATE DATABASE [EF11Test];
Executed DbCommand (68ms) [Parameters=[], CommandType='Text', CommandTimeout='60']
IF SERVERPROPERTY('EngineEdition') <> 5 EXEC(N'ALTER DATABASE [EF11Test] SET READ_COMMITTED_SNAPSHOT ON;');
Closing connection to database 'master' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Closing connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Beginning transaction with isolation level 'Unspecified'.
Executed DbCommand (9ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE [Blogs] (
    [Id] int NOT NULL IDENTITY,
    [Url] nvarchar(max),
    CONSTRAINT [PK_Blogs] PRIMARY KEY ([Id])
);
Committing transaction.
Closing connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Beginning transaction with isolation level 'Unspecified'.
Executed DbCommand (37ms) [Parameters=[@p0='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [Blogs] ([Url])
VALUES (@p0);
SELECT [Id]
FROM [Blogs]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();
Committing transaction.
Closing connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Compiling query model: 
'from Blog <generated>_0 in DbSet<Blog>
select <generated>_0'
Optimized query model: 
'from Blog <generated>_0 in DbSet<Blog>
select <generated>_0'
TRACKED: True
(QueryContext queryContext) => IEnumerable<Blog> _ShapedQuery(
    queryContext: queryContext, 
    shaperCommandContext: SelectExpression: 
        SELECT [b].[Id], [b].[Url]
        FROM [Blogs] AS [b]
    , 
    shaper: UnbufferedEntityShaper<Blog>
)

Opening connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT [b].[Id], [b].[Url]
FROM [Blogs] AS [b]
Closing connection to database 'EF11Test' on server '(localdb)\mssqllocaldb'.

[ErikEJ]

OK, so it is a SQL CE only issue, probably due to #3654 - and only when running Migration commands - never mind...

[ErikEJ]

@ajcvickers Re-opening - wonder why the logging of commands in the standard update pipeline works, as I would expect them to be affected by the same issue as the migrations commands (.CommandText being cleared by the SQL Compact ADO.NET provider on SqlCeCommand.Dispose() ) - and can you think of any workarounds (other that writing a wrapping ADO.NET provider) ?

[ErikEJ]

I ended up doing this hack for now:

https://github.com/ErikEJ/EntityFramework.SqlServerCompact/blob/master/src/Provider40/Migrations/SqlCeMigrationsSqlGenerator.cs#L50

[rowanmiller]

@bricelam to see if we can reorder so we don't dispose before logging

[divega]

@bricelam [closed-fixed] but not closed?

[bricelam]

I use that to represent "out for review" so it doesn't show up in my TODO query.

[divega]

That is fine. I will keep it in mind for next time.