String Quoting - global disable switch

rcollina commented 2 weeks ago

[x] the exact package id and version you're using - Serilog.Sinks.Console 5.0.0 via Serilog.AspNetCore 8.0.1
[x] your dotnet toolchain version, target framework, and operating system - dotnet sdk 8.0.205, dotnet 8
[x] the current behavior - string quoting is opt out
[x] what you expect or want to happen instead - a global switch to turn off string quoting for all message and scope properties

Hello, I can't for the life of me find a way to globally disable automatic string quoting, i.e.:

This is my current outputTemplate: [{Timestamp:HH:mm:ss} {Level}] {SourceContext}: {Message:lj}{NewLine}{Exception}

What am I doing wrong?

Thanks for all and any input.

nblumhardt commented 2 weeks ago

Hi, thanks for the ping. That doesn't look like console output - are you using a different sink?

rcollina commented 2 weeks ago

I'm sorry @nblumhardt, that was misleading. Here's more info, which I hope will prove more useful.

Serilog initialization:

_ = builder.UseSerilog((ctx, loggerConfig) => { /* redacted for clarity */ }, preserveStaticLogger: false, writeToProviders: true);

builder is IHostBuilder, writeToProviders is set to true.

I additionally configured the OpenTelemetry ILogger:

_ = builder.ConfigureLogging(loggingBuilder =>
{
    loggingBuilder.AddOpenTelemetry(o =>
    {
        o.IncludeFormattedMessage = true;
        o.IncludeScopes = true;
    });
});

More examples:

Custom log

logger.LogInformation("strings: {QuotedString} {UnquotedString:l}", "quoted string", "unquoted string");

Console output:

Aspire dashboard output for reference - it's the same formatted message, I assumed the separated non-Serilog OTel exporter is piggybacking on Serilog:

ASP.NET Core log, this should be the original string format: https://github.com/dotnet/aspnetcore/blob/release/8.0/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs#L12

private const string OriginalFormat = "Request starting {Protocol} {Method} {Scheme}://{Host}{PathBase}{Path}{QueryString} - {ContentType} {ContentLength}";

Thank you.

nblumhardt commented 2 weeks ago

Thanks; I see 👍 This is the Serilog.Sinks.Console repo, which doesn't play a part in your setup.

For Serilog sinks, the way to disable quoting is to use the ITextFormatter implementation from Serilog.Expressions. Nothing like that exists for MEL providers (the console and OTel outputs you're using).

I think the Serilog.Extensions.Logging project would be the most likely place this could be addressed, if it turns out to be possible. I'll transfer the issue there and hopefully someone will spot it and take a look at what's involved. Cheers!

rcollina commented 2 weeks ago

Thanks, @nblumhardt.

I just realized the console output was duplicated: both Serilog's Console sink and MEL's Console sink were outputting to stdout - hence the wrong screenshot above; apologies for the confusion.

Serilog's Console rendering looks fine.

I amended the configuration:

    _ = builder.ConfigureLogging(loggingBuilder =>
    {
        loggingBuilder.ClearProviders(); // <-- remove MEL Console sink
        loggingBuilder.AddOpenTelemetry(o =>
        {
            o.IncludeFormattedMessage = true;
            o.IncludeScopes = true;
            configurator.ConfigureOpenTelemetryLogger(o);
        });
    });

Before calling

_ = builder.UseSerilog((ctx, loggerConfig) => { /* redacted for clarity */ }, preserveStaticLogger: false, writeToProviders: true);

with writeToProviders = true.

By the way, this is the configuration I'm using so I assumed it was Serilog.Sinks.Console the culprit but it's clearly something else affecting the output to other sinks just as you said.

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console"
    ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      {
        "Name": "Async",
        "Args": {
          "configure": [
            {
              "Name": "Console",
              "Args": {
                "theme": "Serilog.Sinks.SystemConsole.Themes.AnsiConsoleTheme::Code, Serilog.Sinks.Console",
                "outputTemplate": "[{Timestamp:HH:mm:ss} {Level}] {SourceContext}: {Message:lj}{NewLine}{Exception}"
              }
            }
          ]
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithProcessId",
      "WithThreadId"
    ]
  }
}

Odd enough, I enabled a custom formatter inheriting from ExceptionAsObjectJsonFormatter and the double quotes are there again - I assume there's something I can do on my own here like writing a formatter from scratch or copying it from somewhere.

Configuration:

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console"
    ],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Audit": "Verbose"
      }
    },
    "WriteTo": [
      {
        "Name": "Async",
        "Args": {
          "configure": [
            {
              "Name": "Console",
              "Args": {
                "formatter": "MyNamespace.ElasticStackFormatter, MyAssembly"
              }
            }
          ]
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      "WithProcessId",
      "WithThreadId"
    ]
  }
}

The formatter - it's not much at all, really

internal sealed class ElasticStackFormatter
    : ExceptionAsObjectJsonFormatter
{
    public ElasticStackFormatter(bool omitEnclosingObject = false,
                                 string? closingDelimiter = null,
                                 bool renderMessage = true,
                                 IFormatProvider? formatProvider = null,
                                 ISerializer? serializer = null,
                                 bool inlineFields = false,
                                 bool renderMessageTemplate = true,
                                 bool formatStackTraceAsArray = false)
        : base(omitEnclosingObject, 
               closingDelimiter, 
               renderMessage, 
               formatProvider, 
               serializer, 
               inlineFields,
               renderMessageTemplate,
               formatStackTraceAsArray)
    {

    }
}

The output:

{
  "@timestamp": "2024-06-19T15:52:44.9203512+02:00",
  "level": "Information",
  "messageTemplate": "Request starting {Protocol} {Method} {Scheme}://{Host}{PathBase}{Path}{QueryString} - {ContentType} {ContentLength}",
  "message": "Request starting \"HTTP/1.1\" \"GET\" \"http\"://\"localhost:3244\"\"\"\"/swagger/v1/swagger.json\"\"\" - null null",
  "fields": {
    "Protocol": "HTTP/1.1",
    "Method": "GET",
    "ContentType": null,
    "ContentLength": null,
    "Scheme": "http",
    "Host": "localhost:3244",
    "PathBase": "",
    "Path": "/swagger/v1/swagger.json",
    "QueryString": "",
    "EventId": {
      "Id": 1
    },
    "SourceContext": "Microsoft.AspNetCore.Hosting.Diagnostics",
    "RequestId": "0HN4GCSC288FE:00000002",
    "RequestPath": "/swagger/v1/swagger.json",
    "ConnectionId": "0HN4GCSC288FE",
    "MachineName": "NOTEBOOK",
    "ProcessId": 33980,
    "ThreadId": 19
  }
}

Still, it would be nice to format the message once for all downstream consumers, as it were.

nblumhardt commented 2 weeks ago

Hi @rcollina,

The quoted string output is produced by the default MessageTemplate.Render(), I looked into changing this fairly recently but there's a lot of existing historical usage that would likely break, so this is indefinitely on hold.

Serilog.Exprssions provides a flexible formatter that can be used in a variety of situations, and implements the same interface as your custom formatter above. The Serilog.Expressions formatter option looks like:

// dotnet add package Serilog.Expressions

var formatter = new ExpressionTemplate(
    "{ { '@timestamp': @t, level: @l, message: @m, messageTemplate: @mt, fields: @p, exception: Inspect(@x) } }");

Aside from that I think we'll look at making it easier for components/sinks to use the more modern rendering style - some work is needed though.

rcollina commented 2 weeks ago

Hello @nblumhardt, Thank you. Your suggestion helps - JSON output looks okay now.

{
  "@timestamp": "2024-06-21T12:49:58.8373640+02:00",
  "level": "Information",
  "message": "Request starting HTTP/1.1 GET http://localhost:3244/swagger/v1/swagger.json - null null",
  "messageTemplate": "Request starting {Protocol} {Method} {Scheme}://{Host}{PathBase}{Path}{QueryString} - {ContentType} {ContentLength}",
  "fields": {
    "Protocol": "HTTP/1.1",
    "Method": "GET",
    "ContentType": null,
    "ContentLength": null,
    "Scheme": "http",
    "Host": "localhost:3244",
    "PathBase": "",
    "Path": "/swagger/v1/swagger.json",
    "QueryString": "",
    "EventId": {
      "Id": 1
    },
    "SourceContext": "Microsoft.AspNetCore.Hosting.Diagnostics",
    "RequestId": "0HN4HRVI3MEPK:00000002",
    "RequestPath": "/swagger/v1/swagger.json",
    "ConnectionId": "0HN4HRVI3MEPK",
    "MachineName": "NOTEBOOK",
    "ProcessId": 23312,
    "ThreadId": 10
  }
}

However, this has no impact on what gets passed to MEL ILoggers - so I assume MessageTemplate.Render() is hardcoded somewhere. Unless there's a configuration that gets passed down through the layers just before MEL's ILogger that may apply here?

https://github.com/serilog/serilog-extensions-logging/blob/1e9f655aec4fa4335c68dcce64daac9a25f0011e/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs#L89

nblumhardt commented 1 week ago

JSON output looks good! Yes, this repo will need changes if we're to pass the cleaner-style messages through to MEL providers.

nblumhardt commented 1 week ago

Collecting some notes; https://github.com/serilog/serilog-sinks-opentelemetry/pull/50 is another case where clean formatting has been implemented; the amount of code involved makes a pretty strong case for adding a core Serilog API to do this.

serilog / serilog-extensions-logging

String Quoting - global disable switch #253