Duplicate information in structured json logs

[Scal-Human]

Description

Using the json structured log with the intent to collect them from all containers without having to parse them, the message appears twice in full (bug) plus a third with the original format. Either I missed the documentation or there is no way to configure what appears in the structure (with the built-in logger). One could say I can writer a logger, but is it really the purpose of reinventing the wheel ... again ?

Reproduction Steps

var builder = WebApplication.CreateBuilder(args);
builder.Logging.AddJsonConsole((JsonConsoleFormatterOptions options) => {
    options.TimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffffffzzz";
    options.JsonWriterOptions = new JsonWriterOptions {
        Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping // Because + is a dangerous character
    };
});

Expected behavior

I am expecting, out-of-the-box, logging that contain usable information but without repetition.

Actual behavior

Here is an indented version of a single log line.

{
    "Timestamp": "2024-07-04T01:11:36.9360021+02:00",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.AspNetCore.Hosting.Diagnostics",
    "Message": "Request finished HTTP/1.1 GET http://venium:8076/api/really/anything - 200 54 text/plain;charset=utf-8 17.1633ms",
    "State": {
        "Message": "Request finished HTTP/1.1 GET http://venium:8076/api/really/anything - 200 54 text/plain;charset=utf-8 17.1633ms",
        "ElapsedMilliseconds": 17.1633,
        "StatusCode": 200,
        "ContentType": "text/plain; charset=utf-8",
        "ContentLength": 54,
        "Protocol": "HTTP/1.1",
        "Method": "GET",
        "Scheme": "http",
        "Host": "venium:8076",
        "PathBase": "",
        "Path": "/api/really/anything",
        "QueryString": "",
        "{OriginalFormat}": "Request finished {Protocol} {Method} {Scheme}://{Host}{PathBase}{Path}{QueryString} - {StatusCode} {ContentLength} {ContentType} {ElapsedMilliseconds}ms"
    }
}

The message appears 2 times in plain text (this is a bug). It appears a third time in the form of the original format which should be disableable in the options (JsonConsoleFormatterOptions).

Regression?

With x services times y nodes, it generates an unnecessary volume of logs leading back to a text-based log, custom logger or thirdparty solution while the information is already there.

Known Workarounds

As mentioned above, custom or thirdparty logger, but what is the framework for then ?

Configuration

I am using net8.0 on Windows 10/11 x64 (dev) and Unix 5.10 (prod).

Other information

I surfed a while now about the subject and did not found mention of this issue (duplicate message in single log). If it is a duplicate, sorry for that and please point me to it.

[tarekgh]

@Scal-Human did you try to call builder.Logging.ClearProviders(); before builder.Logging.AddJsonConsole? You may review the first section of the logging providers article for more info.

[Scal-Human]

Hello Tarek, Yes I call it. I only showed the lines i thought were relevent, but indeed I clear the providers just before. I have CreateBuilder, ClearProviders, then AddJsonConsole. Scal

[tarekgh]

@Scal-Human thanks for your response. Could you please provide a complete sample? Just if we suggest solution ensure it will work for your scenario.

[Scal-Human]

Sure, Tarek, I simply created a web

dotnet new web

Then added the json console logger to have the program.cs look like

var builder = WebApplication.CreateBuilder(args);
builder.Logging.AddJsonConsole();
var app = builder.Build();
app.MapGet("/", () => "Hello World!");
app.Run();

When I dotnet run it gives

Building...
{"EventId":14,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Now listening on: http://localhost:5173","State":{"Message":"Now listening on: http://localhost:5173","address":"http://localhost:5173","{OriginalFormat}":"Now listening on: {address}"}}
{"EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Application started. Press Ctrl\u002BC to shut down.","State":{"Message":"Application started. Press Ctrl\u002BC to shut down.","{OriginalFormat}":"Application started. Press Ctrl\u002BC to shut down."}}
{"EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Hosting environment: Development","State":{"Message":"Hosting environment: Development","EnvName":"Development","{OriginalFormat}":"Hosting environment: {EnvName}"}}
{"EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Content root path: C:\\Study\\AspNetMinimal","State":{"Message":"Content root path: C:\\Study\\AspNetMinimal","ContentRoot":"C:\\Study\\AspNetMinimal","{OriginalFormat}":"Content root path: {ContentRoot}"}}

Note that all messages outputed contain the message twice, plus the original format. The first line in indented format gives:

{
    "EventId": 14,
    "LogLevel": "Information",
    "Category": "Microsoft.Hosting.Lifetime",
    "Message": "Now listening on: http://localhost:5173",
    "State": {
        "Message": "Now listening on: http://localhost:5173",
        "address": "http://localhost:5173",
        "{OriginalFormat}": "Now listening on: {address}"
    }
}

A dotnet --version gives

8.0.301

Thank you for your interest, Scal

[tarekgh]

Unfortunately, this is how Json console formatter work. It emits log entry state as a message (which just calls state.ToString() https://github.com/dotnet/runtime/blob/4071a312c407c52dd891f208de5c935d7869745a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs#L31 https://github.com/dotnet/runtime/blob/4071a312c407c52dd891f208de5c935d7869745a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs#L61

Then it emits the state object listing all state properties including the message again. https://github.com/dotnet/runtime/blob/4071a312c407c52dd891f208de5c935d7869745a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs#L71 The workaround I can think of is you create the console logger and provide your custom formatter and you can format the entries the way you like. Let me know if you want to do that and need any help.

I am closing the issue, feel free to send any more questions if you still have any. Thanks for your report!

[Scal-Human]

Thank you for those explanations. I am working with dotnet since the beta 2, back in early 2000 and I was hoping not to have to write/select yet another logger/formatter, but this is the way things go. So you do not consider this is a bug ? I disagree, but this is how open-source works. Yet I do not understand why time has been spent writting this formatter if we cannot use it. It should simply be removed from the framework. Thanks anyway, Scal

[tarekgh]

@Scal-Human To be honest, I don't know why this was originally done this way, and I don't have information on whether changing it would cause any issues. We might consider fixing it with a configuration switch or something similar, but this is not a high priority at the moment due to other pressing tasks we're currently handling. I'll reactivate the issue to track if we can do something about it in the future.

[Scal-Human]

Tarek, Thank you for re-activating it (you have no idea how much it touches me ;-) but I agree (and understand) this is not a priority. To be honest too, I think that it may cause problems to persons that are already using this format to collect logs. Some may rely on the Message field, while some others may rely on the State.Message field. So anyhow, solving this kind of bug causes a breaking change. In the meantime, I wrote a formatter of my own ... the Nth one.

[julealgon]

@Scal-Human have you considered just moving to a more modern approach to grabbing logs from applications, such as OpenTelemetry?

I know this is not a direct answer to your problem, but I honestly believe you are moving in the wrong direction by approaching the problem the way you are currently.

[Scal-Human]

@julealgon thank you for your remark, but I wanted a reusable out-of-the-box solution to produce formatted trace and avoid parsing. With a solution in the framework itself, it prevents having X ways to do the same thing, avoid dependencies on thridparty tools, and improve the quality of information. At first glance, the Json formatter was exactly what I wanted, at the price of 2 or 3 lines of a configuration that can be reused from service to service, but I really have a problem with the duplication of the messages. The way the logging have been implemented allows not only message identification (category, eventId), but preserves the actual information the message is related to in separate state fields. This is great as it allows not only humans to analyze a particular event, but allows automated analyzis with data extraction without (possibly faulty) parsing. Yet, I will definitely have a deeper look at OpenTelemetry, thank you.

[jmbryan4]

I have this issue as well. Same steps to reproduce as above: https://github.com/dotnet/runtime/issues/104409#issuecomment-2209489924

example:

{
    "Timestamp": "2024-08-14 20:24:34Z",
    "EventId": 101,
    "LogLevel": "Information",
    "Category": "System.Net.Http.HttpClient.ITwilioHttpClient.LogicalHandler",
    "Message": "End processing HTTP request after 797.5402ms - 201",
    "State": {
        "Message": "End processing HTTP request after 797.5402ms - 201",
        "ElapsedMilliseconds": 797.5402,
        "StatusCode": 201,
        "{OriginalFormat}": "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}"
    }
}