Decoding Entity Framework Core logs into runnable SQL

This isn’t one of my long articles, but just a bit of fun I had trying to convert Entity Framework Core’s (EF Core) CommandExecuted logs back into real SQL. EF Core’s logging is much improved over EF6.x and it returns very readable SQL (see this example below)

var id = 1;
var book = context.Books.Single(x => x.BookId == id);

Produces this log output

Executed DbCommand (1ms) [Parameters=[@__id_0='1'],
    CommandType='Text', CommandTimeout='30']
SELECT TOP(2) [p].[BookId], [p].[Description], [p].[ImageUrl]
    , [p].[Price], [p].[PublishedOn], [p].[Publisher]
    , [p].[SoftDeleted], [p].[Title]
FROM [Books] AS [p]
WHERE ([p].[SoftDeleted] = 0) AND ([p].[BookId] = @__id_0)

Now I spend quite a bit of time understanding and performance tuning EF Core code, so it’s very useful if I can copy & paste the SQL into something like Microsoft’s SQL Server Management Studio (SSMS) to see how they perform. The problem is I have to hand-edit the SQL to add the correct values to replace any parameters (see @__id_0 in last code).

So, in my spare time (??), I decided to try to create some code that would automatically replace the property reference with the actual value. It turns out it’s quite difficult and you can’t quite get everything right, but its good enough to help in lots of places. Here is the story of how I added this feature to my EfCore.TestSupport library.

The steps to building a my DecodeMessage method

The steps I needed to do were:

1. Capture EF Core’s logging output
2. Turn on EnableSensitiveDataLogging
3. Catch any EF Core CommandExecuted logs
4. Decode the Parameters
5. Replace any property references in the SQL with the ‘correct’ parameter value

Now I did say I was going to keep this article short so I’m going to give you some code that handles the first three parts. You can see the EnableSensitiveDataLogging method near the end of building the options.

var logs = new List<LogOutput>();
var options = new DbContextOptionsBuilder<BookContext>()
    .UseLoggerFactory(new LoggerFactory(new[] 
          { new MyLoggerProviderActionOut(l => logs.Add(l))}))
    .UseSqlite(connection)
    .EnableSensitiveDataLogging()
    .Options;
using (var context = new BookContext(options)) 
{
    //… now start using context

NOTE: Sensitive data logging is fine in your unit tests, but you should NOT have sensitive data logging turned on in production. Logging the actual data used is a security risk and could break some user privacy rules like GPRS.

In fact I have methods in my EFCore.TestSupport library that handle building the options and turning on sensitive logging, plus a load of other things. Here is an example of one helper that creates an in-memory database options, with logging.

var logs = new List<LogOutput>();
var options = SqliteInMemory.CreateOptionsWithLogging
     <BookContext>(log => logs.Add(log));
using (var context = new BookContext(options)) 
{
    //… now start using context

The EfCore.TestSupport library has another version of this that works for SQL Server. It creates a unique database name per class, or per method, because xUnit (the favourite unit test framework for NET Core) runs each test class in parallel.

NOTE: The EfCore.TestSupport uses a logging provider that calls an action method for every log. This makes it easy to write logs to the console, or capture them into list.

Decoding the Parameters

Having captured the EF Core’s logs now I need to decode the first line that has the parameters. There are a few permutations, but it’s clear that Regex is the way to go. This problem is I’m not an expert on Regex, but LinqPad came to my rescue!

LinqPad 5.36 has a very nice Regex tool – the best I have found so far.  Here is a screenshot of its regex feature, which is called up via Ctrl+Shift+F1.

WARNING: It’s a great tool, but I thought if I saved the code it would keep the pattern I had created, but it doesn’t. I spent hours getting the regex right and then lost it when I entered something else. Now I know its all OK, but be warned.

All my trials came up with the following Regex code

new Regex(@"(@p\d+|@__\w*?_\d+)='(.*?)'(\s\(\w*?\s=\s\w*\))*(?:,\s|\]).*?");

If you don’t know regex then it won’t mean anything to you, but it does the job of finding the a) param name, b) param value, and c) extra information on the parameter (like its size). You can see the whole decode code here.

Limitations of the decoding

It turns out that EF Core’s logged data doesn’t quite give you all you need to perfectly decode the log back to correct SQL. Here are the limitations I found:

1. You can’t distinguish the different between an empty string and a null string, both are represented by ”. I decided to make ” return NULL.
2. You can’t work out if it’s a byte[] or not, so byte[] is treated as a SQL string. This will FAIL in SQL Server.
3. You can’t tell if something is a Guid, DateTime etc., which in SQL Server need ” around them. In the end I wrapped most things in ”, including numbers. SQL Server accepts numbers as strings (but other databases won’t).

Example of a different decoded SQL

If we go back to the book lookup at the start of this article then the decoded result is shown below

SELECT TOP(2) [p].[BookId], [p].[Description]
   , [p].[ImageUrl], [p].[Price], [p].[PublishedOn]
   , [p].[Publisher], [p].[SoftDeleted], [p].[Title]
FROM [Books] AS [p]
WHERE ([p].[SoftDeleted] = 0) AND ([p].[BookId] = '1') 

As you can see on the last line the integer is represented as a string. This isn’t the normal way to do this but works in SQL Server. I took the decision to wrap things that I didn’t think were strings because this what is needed to make other types, such as GUIDs, Datetime etc. to work.

My really complex test contained lots of different NET Types, and here is the output.

SET NOCOUNT ON;
INSERT INTO [AllTypesEntities] ([MyAnsiNonNullString]
    , [MyBool], [MyBoolNullable], [MyByteArray], [MyDateTime]
    , [MyDateTimeNullable], [MyDateTimeOffset], [MyDecimal]
    , [MyDouble], [MyGuid], [MyGuidNullable], [MyInt]
    , [MyIntNullable], [MyString], [MyStringEmptyString]
    , [MyStringNull], [MyTimeSpan])
VALUES ('ascii only', 1, NULL, '0x010203', '2000-01-02T00:00:00',
NULL, '2004-05-06T00:00:00.0000000+01:00', '3456.789', '5678.9012', 
'ba65d636-65d4-4c07-8ddc-50c615cef539', NULL, '1234', NULL, 
'string with '' in it', NULL, NULL, '04:05:06');
SELECT [Id]
FROM [AllTypesEntities]
WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity(); 

In this complex version the parts that fail are:

1. The MyByteArray has ” around it and FAILS – taking off the string delimiters fixes that.
2. The MyStringEmptyString is set to NULL instead of an empty string.

Not perfect, but quite usable.

How can you access this code?

If you just want to use this feature its build into the latest EfCore.TestSupport NuGet package (1.7.0 to be precise). Its build into the LogOutput class which is used by the loggers in this library. There are methods that create options for SQLite (in-memory) and SQL Server database that allow logging. There are plenty of examples of these in the library – have a look at the unit tests for this in the TestEfLoggingDecodeBookContext class.

If you want to play with the code yourself then take a copy of the EfCoreLogDecoder class which contains the decode parts.

Conclusion

Well it was a bit of fun, maybe not something I would do on a job but still a useful tool. I was a bit disappointed I couldn’t decode the log completely but what it does is still useful to me. Maybe you will find it useful to you too.

Now I need to get back to my real work for my clients. See you on the other side!

Happy coding.