Log machine readable & queryable structured log entries

[gdoron]

Hi @rowanmiller,

Currently EF logs raw strings without leveraging ASP.NET logging extensions.
source code
Filtering based on that string is very difficult if not impossible.

I wanted to create a pull request with a fix, I tried to compile the repository for hours but there were mismatch of assemblies I couldn't resolve for some reason.

Anyway the fix seems to be as simple as changing the code to:

logger.LogInformation((int) RelationalEventId.ExecutedCommand,
    RelationalStrings.RelationalLoggerExecutedCommand,
    string.Format(CultureInfo.InvariantCulture, "{0:N0}", elapsedMilliseconds),
    command.Parameters
        .Cast<DbParameter>()
        .Select(
            p => new DbParameterLogData(
                        p.ParameterName,
                        logParameterValues ? p.Value : "?",
                        logParameterValues,
                        p.Direction,
                        p.DbType,
                        p.IsNullable,
                        p.Size,
                        p.Precision,
                        p.Scale))
        .Select(p => $"{p.Name}={p.FormatParameter()}")
        .Join(),
    command.CommandType,
    command.CommandTimeout,
    command.CommandText.TrimEnd()
);

And change RelationalStrings.RelationalLoggerExecutedCommand to:

Executed DbCommand {{elapsed}}ms [Parameters=[{{parameters}}], {{commandType}', {{commandTimeout}} {{commandText}}

(Or simply use LoggerMessage.Define as MVC is doing)

Which will yield a queryable log entry.

The first is EF log entry and the second one is using my code (not exactly as above since I couldn't compile the source code).

Now it is possible to query for all the queries which lasted more than x ms.
Can it please be fixed before 1.1.0?

Thanks

p.s. Please change from elapsed to ElapsedMilliseconds to be in sync with MVC

[rowanmiller]

@gdoron can you explain a little more about your change. The logging passes all the information to the logger as the logData variable in the code you linked to, which can be accessed via the state variable in the logger. It is only turned into a string by passing the state into the formatter we supply.

[gdoron]

@rowanmiller
I believe the guys at serilog & seq can explain it better than me @nblumhardt.

The loggers by convention are looking for placeholders in the logged string to map it to a dictionary that can be later queried:

The call to the log method can utilize a format string with named placeholders (like {path}). These placeholders are populated in the order in which they appear by the args values passed into the method call. Some logging providers will store these names along with their mapped values in a dictionary that can later be queried. In the example below, the request path is passed in as a named placeholder:

logger.LogInformation("No endpoint found for request {path}", context.Request.Path);

https://docs.asp.net/en/latest/fundamentals/logging.html

Problem is, EF doesn't utilize this pattern but log human readable flat log entries but not machine readable structured log entries.

I would love to create a PR for this one, but I didn't manage to add the source code of EF to my application in order to test and fiddle with my changes (compilation errors). Is there a little guide on how to do this?

Anyway, you can add serilog and a sink, Seq is probably the easiest one to install but there are many others, change the message to include placeholders and see the difference for yourself.

[nblumhardt]

Hi folks,

I had a quick look at the current logging statement, @rowanmiller I think the missing detail is that DbCommandLogData does not implement IEnumerable<KeyValuePair<string,object>>, which the new logging framework uses as the contract for payloads with structured properties.

The suggestion of @gdoron's to use a template-based format string would resolve this nicely - MVC uses this approach:

https://github.com/aspnet/Mvc/blob/a78f77afde003c4a3fcf5dd7b6dc13dd9c85f825/src/Microsoft.AspNetCore.Mvc.Razor/Internal/MvcRazorLoggerExtensions.cs#L23

Making DbCommandLogData and other log payloads implement the interface would also cover it, but it's a bit of an anachronism since the templated messages already handle the role of the formatter and avoid the need to specify once explicitly.

Let me know if I can help or provide more info.

[smitpatel]

@nblumhardt , @gdoron @rowanmiller - Can you provide info on how to verify if the output of log is structured?

[nblumhardt]

@smitpatel using the built-in Microsoft.Extensions.Logging framework, you can plug in a mock ILogger, e.g. CollectingLogger, that stores log events into a collection that can be inspected in a unit test.

The state parameter on this one is the object you need to store and verify.

The event data stored this way should be IEnumerable<KeyValuePair<string,object>>, and, crucially, there will be a Key in there for each placeholder in the log message, such as Name below.

logger.LogInformation("Hello, {Name}", "World");

So, assuming you've rigged up the logger to store data in _logger.Events and the event in question is the last one, you might do:

var state = _logger.Events.Last();
var props = (IEnumerable<KeyValuePair<string,object>>)state;
var name = props.Single(kvp => kvp.Key == "Name");
Assert.Equal("World", name);

All pseudocode but hopefully gives you some ideas. Let me know if you need more details.

(To visually determine if the log is structured BTW, you can fire up Seq and see the captured properties highlighted pale yellow within the message, as per @gdoron's screenshots above.)

HTH!

[gdoron]

Thanks @nblumhardt ! 👏

Would it be possible to squeeze it into v1.0.1?
Since it's a low risk, easy to fix and huge value bug?