Steeltoe 3.2.0 breaks Serilog structured logging

christianerbsmehl commented 2 years ago

Describe the bug

After upgrading Steeltoe.Extensions.Logging.DynamicSerilogBase from version 3.1.3 to 3.2.0, structured logging with Serilog is broken, which means that message properties are not extracted from the log message. Additionally, the console output is not colored anymore. I created a sample project to demonstrate the issue: https://github.com/christianerbsmehl/steeltoe-serilog

To narrow down the problem, I configured the Serilog file sink with the compact JSON formatter. I found out, that with DynamicSerilogBase 3.2.0 the message template is missing the curly braces around the message properties:

{"@t":"2022-07-27T06:47:51.8714481Z","@mt":"Log should have a value property which value is 'value'.","SourceContext":"TestLogger","RequestId":"0HMJFJFMGJECV:00000001","RequestPath":"/log","ConnectionId":"0HMJFJFMGJECV","Scope":["MyScope"],"Application":"MyApplication"}

Using DynamicSerilogBase 3.1.3, output looks like this:

{"@t":"2022-07-27T06:48:30.0176676Z","@mt":"Log should have a {value} property which value is 'value'.","value":"value","SourceContext":"TestLogger","Scope":["MyScope"],"RequestId":"0HMJFJG1S4BTS:00000001","RequestPath":"/log","ConnectionId":"0HMJFJG1S4BTS","Application":"MyApplication"}

Note the curly braces around value in the message template and the extracted "value":"value" property.

Steps to reproduce

Steps to reproduce the behavior:

Create a .NET 6 App using Steeltoe.Extensions.Logging.DynamicSerilogBase 3.2.0 and Serilog.AspNetCore 6.0.1
Configure Logging using

In Program.cs:

builder.Logging.AddDynamicSerilog(new LoggerConfiguration().ReadFrom.Configuration(builder.Configuration));

In appSettings.json:

"Serilog": {
    "IncludeScopes": false,
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Warning",
        "System.Net.Http.HttpClient": "Warning"
      }
    },
    "Properties": {
      "Application": "MyApplication"
    },
    "Enrich": [ "FromLogContext" ],
    "Using": [ "Serilog.Sinks.Console" ],
    "WriteTo": [
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u3}] {Application} {SourceContext}: {Message:lj}{NewLine}{Exception}"
        }
      },
      {
        "Name": "File",
        "Args": {
          "path": "./logs/serilog-sample.json",
          "formatter": "Serilog.Formatting.Compact.CompactJsonFormatter, Serilog.Formatting.Compact"
        }
      }
    ]
  }

For details please refer to the sample project I provided above.

Expected behavior

Message properties should be extracted again and the message template should have curly braces around properties.

Environment

Steeltoe Version: 3.2.0
Platform: Cloud Foundry Linux / local Windows development environment
OS: Linux/Windows
.NET Version: .NET 6

hananiel commented 2 years ago

@christianerbsmehl I took a look at this. In 3.2 we added the feature to add support for IDynamicMessageProcessor which adds things like span and traceID to add context to logs. Unfortunately, I think this broke compatibility with the structured logging. I am looking for a work around.

hananiel commented 2 years ago

@christianerbsmehl the short answer to this is that the IDynamicMessageProcessor adds context to logs by calling the formatter ahead of time and then appends data. Whereas the serilog implementation uses the values in TState of Log to render the the structured logs. So this is obviously a problem - we can pick one or the other - either have structured logs preserved or lose the ability add trace context. I am guessing this cannot be fixed in Steeltoe code base.

christianerbsmehl commented 2 years ago

The IDynamicMessageProcessor is a Steeltoe thing, isn't it? Can you give me some context why this was introduced and what's the use case? From the linked issue (https://github.com/SteeltoeOSS/Steeltoe/issues/835) I understood that TraceId and SpanId should be included in the console output. With .NET Core 3.1 and using Serilog, SpandId and TraceId were automatically included in the properties of every log message, but with .NET 6 (also .NET 5) they are missing by default (https://github.com/serilog/serilog-aspnetcore/issues/207). So maybe the problem you were trying to solve with the IDynamicMessageProcessor should have been solved elsewhere (e.g. only for the console logger provider) or can be solved using a serilog enricher?

SteeltoeOSS / Steeltoe