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()

runtime/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

Line 31 in 4071a31

string message = logEntry.Formatter(logEntry.State, logEntry.Exception);

runtime/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

Line 61 in 4071a31

writer.WriteString("Message", message);

Then it emits the state object listing all state properties including the message again.

runtime/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

Line 71 in 4071a31

writer.WriteString("Message", stateMessage);

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: #104409 (comment)

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}"
    }
}

[rmannibucau]

Any hope it gets fixed soon? Can do the PR if it helps.

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

Hmm think you missed some points about opentelemetry, it has two modes, one which is pushing the logs to the collector which is a huge regression since you can just loose the logs by design with the SDK implementation (and if you ensure it is not the case it is insanely inefficient) and the other is to pull the logs using something equivalent to promtail which needs a structure log format which is exactly what this issue is about, so yes this issue blocks to move to opentelemetry in good conditions until you implement a custom logger or formatter which makes default one not that consummable.

Let me know if I should do the PR and on which branch to be able to consume it on next v9 release.

[tarekgh]

.NET 9.0 has already been released, so we cannot modify its behavior. Addressing this might require introducing a new option in the JSON formatter or, at the very least, a configuration switch to control the different behaviors. However, adding new APIs to a released product is not feasible for .NET 9.0, and implementing a configuration switch in servicing releases is risky, as I prefer to have the default behavior be the correct one which avoids duplication. . This can be considered for .NET 10, we can discuss how we can address fixing the issue here. Thanks for your interest @rmannibucau

[rmannibucau]

@tarekgh while I get the high level policy, here we are speaking of something very located and trivial to fix. I agree changing the default would be better but I also ack it can't be done within a minor or .net 9.0 but awaiting 1 year to get a fix also means the solution is mostly not usable - the impact for a prod system is way too high - for one more year, so there must be something in between, should a MS.Logging.JsonFormatter be released and preview net10?

[tarekgh]

should a MS.Logging.JsonFormatter be released and preview net10?

Absolutely, if we address this issue in .NET 10, the fix will be included in the next preview release follow the fix.

As a workaround, you can copy the current JSON provider code into your application, modify it as needed, and use it as a custom provider. I understand this isn't ideal, but it could help unblock you for now if necessary.