String Quoting - global disable switch about serilog-extensions-logging

[nblumhardt]

Collecting some notes; serilog/serilog-sinks-opentelemetry#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.

[nblumhardt]

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

[nblumhardt]

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

[rcollina]

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]

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]

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]

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]

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?

serilog-extensions-logging/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs

Line 89 in 1e9f655

_logger.Write(evt);