The Elapsed property for CommandExecuted event is defined as string in the logs.

[fiseni]

Hi,

This is a minor issue regarding the logs that EF produces. For the CommandExecuted event, among other properties, EF adds an elapsed field. The field is added as a string, instead of int or any other numeric format (e.g. the commandTimeout is properly added as a number). It's a minor annoyance while querying the logs. The elapsed field is very useful information actually.

Here is a sample output:

{
  "Properties": {
    "elapsed": "2",
    "parameters": "@__age_0='30' (Nullable = true)",
    "commandType": "Text",
    "commandTimeout": 30,
    "newLine": "\r\n",
    "commandText": "SELECT [c].[Id], [c].[Age], [c].[Email], [c].[Name]\r\nFROM [Customers] AS [c]\r\nWHERE [c].[Age] > @__age_0",
    "EventId": {
    	"Id": 20101,
    	"Name": "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted"
    },
    "SourceContext": "Microsoft.EntityFrameworkCore.Database.Command",
    "ActionId": "4f25e37c-3bf6-4ca1-b509-eb7b09499790",
    "ActionName": "SerilogDemo.Web.TestController.TestDb (SerilogDemo.Web)",
    "RequestId": "0HN33J2941FQR:0000000B",
    "RequestPath": "/test-db",
    "ConnectionId": "0HN33J2941FQR",
  }
}

Thanks!

[fiseni]

Looking at the source code, it seems EF adds the elapsed property as TimeSpan. If you can confirm that, then we'll discuss the issue with the logging providers. The issue can be closed if that's the case. Sorry for the inconvenience.

EDIT: I cross-checked and the logging providers handle TimeSpan in a different format. So, most probably, EF adds "elapsed" as a string.

[ardalis]

Also related issue, any property like commandTimeout should include the units in the property name. In the sample you shared above, it's not clear what "commandTimeout": 30 means. Could be 30 minutes. 30 days. 30 seconds. 30 picoseconds. Why not call it commandTimeoutSeconds (or whatever it's supposed to be, in terms of units).

[ajcvickers]

@dotnet/efteam Does anyone remember if there is a reason we are using all strings here?

[fiseni]

As a side note, ASP.NET Core uses decimal type for ElapsedMilliseconds. I'm not sure if it's done to display sub-millisecond values or to handle large numbers. The Stopwatch.ElapsedMilliseconds returns long and perhaps that's sufficient.

{
  "Properties": {
    "ElapsedMilliseconds": 41.8144,
    "StatusCode": 200,
    "ContentType": null,
    "ContentLength": 0,
    "Protocol": "HTTP/2",
    "Method": "GET",
    "Scheme": "https",
    "Host": "localhost:7001",
    "PathBase": "",
    "Path": "/test",
    "QueryString": "",
    "EventId": {
    	"Id": 2
    },
    "SourceContext": "Microsoft.AspNetCore.Hosting.Diagnostics",
    "RequestId": "0HN358CCU70UO:00000009",
    "RequestPath": "/test",
    "ConnectionId": "0HN358CCU70UO"
  }
}

[ajcvickers]

Note from team meeting: we should use non-string values where we can. We should also make sure that units are used in names, or at least well documented. Note that this will be a breaking change for any code expecting these values to be strings.

[kasthack]

#13324