EventLogger does not mix well with LoggerExtensions.BeginScope

[weltkante]

Description

When using LoggerExtensions.BeginScope together with EventLogger the output is not formatted. The ConsoleLogger does not have this behavior and properly formats the scope.

Looking at the source it seems the EventLogger wants to fake "understanding" IEnumerable<KeyValuePair<string, object>> but in the end just dumps them into a string anyways, bypassing the ToString implementation of the scope object which would perform proper formatting.

As far as I can see "understanding" IEnumerable<KeyValuePair<string, object>> is not a well established pattern, for example if you pass a dictionary to ILogger.BeginScope then the ConsoleLogger does not dissect the KeyValuePairs. Even if this were an established pattern it should be left to logging sinks which can actually store structured data, the way EventLogger handles things it loses all benefits of either choice:

• its not structured because you can't parse it for machine consumption (it doesn't attempt any escaping of keys or values)
• its not formatted so you lose the formatting for human consumption.

I believe the EventLogger should prefer human consumption and do proper formatting, if you have backwards compatibility concerns please provide a setting in the EventLogSettings object. As it stands we cannot use LoggerExtensions.BeginScope and have to use our own extension method to work around this behavior and blacklist yours via Analyzer in order to get sensible output in the event log. (and that only works for us because our service is simple enough not to have 3rd party dependencies which might call LoggerExtensions.BeginScope)

repro code

```csharp using System.Threading.Tasks; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Mvc; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; namespace BugRepro { public class Startup { public static void Main(string[] args) { var host = Host.CreateDefaultBuilder(args); host.ConfigureLogging(log => { log.AddEventLog(); log.AddConsole(settings => settings.IncludeScopes = true); }); host.ConfigureWebHostDefaults(web => web.UseStartup()); host.Build().Run(); } public void ConfigureServices(IServiceCollection services) { services.AddControllers(); } public void Configure(IApplicationBuilder app, IWebHostEnvironment env) { if (env.IsDevelopment()) app.UseDeveloperExceptionPage(); app.UseRouting(); app.UseEndpoints(endpoints => endpoints.MapControllers()); } } public class TestController : ControllerBase { private ILogger _logger; public TestController(ILogger logger) { _logger = logger; } [HttpGet("/")] public async Task GetContent() { var number = 1234; var text = "text"; using var logScope = _logger.BeginScope("Loading entry {SomeNumber} from {SomeText}", number, text); await Task.Delay(100); var error = "some error"; _logger.LogError("Load failed due to {Reason}", error); return new JsonResult(new { Error = error }); } } } ```

Actual Output

Category: BugRepro.TestController
EventId: 0
SpanId: 45e5c0fccc53ec40
TraceId: 47d8b6c972072740911e0e793a1c7c23
ParentId: 0000000000000000
ConnectionId: 0HM5JSGST7M13
RequestId: 0HM5JSGST7M13:0000000F
RequestPath: /
ActionId: 2afdf0fd-d1cf-449d-8439-02ddef3f3a29
ActionName: BugRepro.TestController.GetContent (BugRepro)
SomeNumber: 1234
SomeText: text
{OriginalFormat}: Loading entry {SomeNumber} from {SomeText}

Load failed due to some error

Expected Output

Category: BugRepro.TestController
EventId: 0
SpanId: 45e5c0fccc53ec40
TraceId: 47d8b6c972072740911e0e793a1c7c23
ParentId: 0000000000000000
ConnectionId: 0HM5JSGST7M13
RequestId: 0HM5JSGST7M13:0000000F
RequestPath: /
ActionId: 2afdf0fd-d1cf-449d-8439-02ddef3f3a29
ActionName: BugRepro.TestController.GetContent (BugRepro)
Loading entry 1234 from text
Load failed due to some error

Console Logger

fail: BugRepro.TestController[0]
      => SpanId:45e5c0fccc53ec40, TraceId:47d8b6c972072740911e0e793a1c7c23, ParentId:0000000000000000 => ConnectionId:0HM5JSGST7M13 => RequestPath:/ RequestId:0HM5JSGST7M13:0000000F => BugRepro.TestController.GetContent (BugRepro) => Loading entry 1234 from text
      Load failed due to some error

Configuration

.NET 5

Regression?

unknown

[ghost]

Tagging subscribers to this area: @maryamariyan See info in area-owners.md if you want to be subscribed.

Issue Details

---

### Description When using `LoggerExtensions.BeginScope` together with `EventLogger` the output is not formatted. The `ConsoleLogger` does not have this behavior and properly formats the scope. Looking at the [source](https://github.com/dotnet/runtime/blob/master/src/libraries/Microsoft.Extensions.Logging.EventLog/src/EventLogLogger.cs#L98) it seems the `EventLogger` wants to fake "understanding" `IEnumerable>` but in the end just dumps them into a string anyways, bypassing the `ToString` implementation of the scope object which would perform proper formatting. As far as I can see "understanding" `IEnumerable>` is not a well established pattern, for example if you pass a dictionary to `ILogger.BeginScope` then the `ConsoleLogger` does not dissect the KeyValuePairs. Even if this were an established pattern it should be left to logging sinks which can actually store structured data, the way EventLogger handles things it loses all benefits of either choice: - its not structured because you can't parse it for machine consumption (it doesn't attempt any escaping of values) - its not formatted so you lose the formatting for human consumption. I believe the EventLogger should prefer human consumption and do proper formatting, if you have backwards compatibility concerns please provide a setting in the `EventLogSettings` object. As it stands we cannot use `LoggerExtensions.BeginScope` and have to use our own extension method and blacklist yours via Analyzer in order to get sensible output in the event log.

repro code

```csharp using System.Threading.Tasks; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Mvc; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; namespace BugRepro { public class Startup { public static void Main(string[] args) { var host = Host.CreateDefaultBuilder(args); host.ConfigureLogging(log => { log.AddEventLog(); log.AddConsole(settings => settings.IncludeScopes = true); }); host.ConfigureWebHostDefaults(web => web.UseStartup()); host.Build().Run(); } public void ConfigureServices(IServiceCollection services) { services.AddControllers(); } public void Configure(IApplicationBuilder app, IWebHostEnvironment env) { if (env.IsDevelopment()) app.UseDeveloperExceptionPage(); app.UseRouting(); app.UseEndpoints(endpoints => endpoints.MapControllers()); } } public class TestController : ControllerBase { private ILogger _logger; public TestController(ILogger logger) { _logger = logger; } [HttpGet("/")] public async Task GetContent() { var number = 1234; var text = "text"; using var logScope = _logger.BeginScope("Loading entry {SomeNumber} from {SomeText}", number, text); await Task.Delay(100); var error = "some error"; _logger.LogError("Load failed due to {Reason}", error); return new JsonResult(new { Error = error }); } } } ```

#### Actual Output ``` Category: BugRepro.TestController EventId: 0 SpanId: 45e5c0fccc53ec40 TraceId: 47d8b6c972072740911e0e793a1c7c23 ParentId: 0000000000000000 ConnectionId: 0HM5JSGST7M13 RequestId: 0HM5JSGST7M13:0000000F RequestPath: / ActionId: 2afdf0fd-d1cf-449d-8439-02ddef3f3a29 ActionName: BugRepro.TestController.GetContent (BugRepro) SomeNumber: 1234 SomeText: text {OriginalFormat}: Loading entry {SomeNumber} from {SomeText} Load failed due to some error ``` #### Expected Output ``` Category: BugRepro.TestController EventId: 0 SpanId: 45e5c0fccc53ec40 TraceId: 47d8b6c972072740911e0e793a1c7c23 ParentId: 0000000000000000 ConnectionId: 0HM5JSGST7M13 RequestId: 0HM5JSGST7M13:0000000F RequestPath: / ActionId: 2afdf0fd-d1cf-449d-8439-02ddef3f3a29 ActionName: BugRepro.TestController.GetContent (BugRepro) Loading entry 1234 from text Load failed due to some error ``` #### Console Logger ``` fail: BugRepro.TestController[0] => SpanId:45e5c0fccc53ec40, TraceId:47d8b6c972072740911e0e793a1c7c23, ParentId:0000000000000000 => ConnectionId:0HM5JSGST7M13 => RequestPath:/ RequestId:0HM5JSGST7M13:0000000F => BugRepro.TestController.GetContent (BugRepro) => Loading entry 1234 from text Load failed due to some error ``` ### Configuration .NET 5 ### Regression? unknown

Author:	weltkante
Assignees:	-
Labels:	`area-Extensions-Logging`, `untriaged`
Milestone:	-

[qsdfplkj]

The output:

SomeNumber: 1234 SomeText: text {OriginalFormat}: Loading entry {SomeNumber} from {SomeText}

Shows the oringal template and the variables... you might not expected this but it is called a template. if you don't want this you should log:

_logger.BeginScope($"Loading entry {number} from {text}");

[maryamariyan]

As far as I can see "understanding" IEnumerable<KeyValuePair<string, object>> is not a well established pattern... its not formatted so you lose the formatting for human consumption.

@weltkante For console logging have you tried using the Json console log formatter? In your sample code changing AddConsole to AddJsonConsole, should give you that. (Refer to docs here too.)

[maryamariyan]

@tarekgh @noahfalk are there specific guidelines around using scopes alongside EventLogger?

[weltkante]

@qsdfplkj I know this, its part of the issue description. I believe you are wrong though, your workaround defeats the whole purpose of the extension method capturing the arguments without formatting (only paying the performance for formatting when the logging is enabled).

please reread the issue description

• no other of the default loggers does this (for what its worth the Log extension methods don't do this either, just the scopes)
• the output is not parseable by machine
• the output is not (easily) readable by humans

The source implementation goes to great lengths to make the message object passed to the logger formattable (and not just a dictionary) so the fact that the EventLogger discards all that work (while other formatters don't do this) is clearly a mistake. I'm not against keeping the current behavior for backwards compatibility if thats a concern, but there should be an option to properly format the output for people who actually want a readable event log.

@maryamariyan

For console logging have you tried using the Json console log formatter?

No I did not notice it. However json is a structured parseable format (it will escape properly so its machine-readable) so it does not have the concerns I'm raising with the EventLogger.

Also notice that even the json console logger will output the formatted text (in addition to the structured data):

"Message":"Loading entry 1234 from text"

[tarekgh]

@maryamariyan I think the ask here is more generic to give the ability to attach a custom formatter to the logger to allow formatting specific type. So, I am seeing this is as a feature request and not just a bug we need to fix.

@weltkante do you have specific proposal in your mind?

[weltkante]

I think the ask here is more generic to give the ability to attach a custom formatter to the logger to allow formatting specific type.

The type used by the extension methods is intentionally kept internal, so I don't think you could write a formatter for it. The custom formatter would just do a ToString to invoke the default behavior of the object generated by the BeginScope extension. IMHO invoking ToString on formattable objects should be the default behavior of everything and not require custom formatters. The problem is that EventLogger has a non-default implementation and tries to present structured data in an unstructured way (text dump, not escaped, not machine readable). The console json formatter does a better job, it exposes the formatted message and adds the structured data. Of course its not easily readable, so I don't think it would be a good fit for the event log.

do you have specific proposal in your mind?

I'd be happy with a flag on the EventLogger settings object to fix this mistreatment of the message object, putting it in line with the other loggers.

If you are looking for a more general solution theres the question to solve how to differentiate objects which only want to expose structured data (e.g. a Dictionary<string, object> vs. a structured formattable object generated by the extension method)

[qsdfplkj]

Just some research but maybe this helps: https://source.dot.net/#Microsoft.Extensions.Logging.Abstractions/LoggerMessage.cs It seems to generate the scopes where the {OriginalFormat} comes from. Maybe writing a similar class can help you out. Or: https://source.dot.net/#Microsoft.Extensions.Logging.Abstractions/LogValuesFormatter.cs,

[noahfalk]

Searching through source history it appears the suspect logger scope formatting appeared in this change. I didn't see anything specific in the commit message, test changes, bug, or PR links clarifies why this aspect of the formatting was changed, but there is the general mention of:

Clean up the formatting a bit

• Added headings for various bits of info.

which is the best info I can find on the rationale.

Its been a few years but maybe @davidfowl remembers the reasoning for it? My personal guess is that David was trying to address the case where someone passes Dictionary<string,object> as the scope and didn't notice the change ignored the formatting of the FormattedLogValues type at the same time. Unlike FormattedLogValues, Dictionary<string,object>.ToString() produces a very unhelpful string to include in a log: "System.Collections.Generic.Dictionary`2[System.String,System.Object]"

My hunch is that modifying line 98 to be:

if (scope is IEnumerable<KeyValuePair<string, object>> properties &&
    scope is not FormattedLogValues)

might satisfy everyone?

[KalleOlaviNiemitalo]

My hunch is that modifying line 98 to be:

if (scope is IEnumerable<KeyValuePair<string, object>> properties &&
    scope is not FormattedLogValues)

might satisfy everyone?

FormattedLogValues is currently internal in Microsoft.Extensions.Logging.Abstractions. To let Microsoft.Extensions.Logging.EventLog access it, would you make it public or add another InternalsVisibleToAttribute?