No properties from Enricher on update from 7.2.0 to 8.0.0

[milbrandt]

Describe the bug

For a long time we have an Enricher set up to add several properties to the logs send to Kibana. Target framework either net6 or net 8.

Everything worked with Serilog.Sinks.Http 7.2.0. We updated only this single NuGet to 8.0.0 and added "queueLimitBytes": null to the appsettings for WriteTo of Http sink.

Update: With some testing on old betas it could be cut back to the update from 8.0.0-beta.10 (still working) to 8.0.0-beta.11 (data no longer arriving)

Now, the out of the box properties still arrive at Kibana, but no longer the properties of the Enricher. We saw, that the Enricher is still called for each event.

public class ContextLogEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        _ = logEvent ?? throw new ArgumentNullException(nameof(logEvent));
        _ = propertyFactory ?? throw new ArgumentNullException(nameof(propertyFactory));

        foreach (var context in LogManager.ContextHandlers.RetrieveContextInfo())
        {
            logEvent.AddOrUpdateProperty(propertyFactory.CreateProperty(context.Key, context.Value));
        }
        logEvent.AddOrUpdateProperty(propertyFactory.CreateProperty("testKey", "testValue")); // only for testing
    }
}

internal SerilogLogManager(LoggerConfiguration configuration)
{
    _coreLogger = configuration.CreateLogger();
    _logger =
        _coreLogger
            .ForContext(new ContextLogEnricher());
}

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.File",
      "Serilog.Sinks.Http"
    ],
    "MinimumLevel": {
      "Default": "Information",
    },
    "WriteTo": [
      {
        "Name": "Http",
        "Args": {
          "requestUri": "http://ugg-sw-monitoring.grinding.ch:5000",
          "queueLimitBytes": null
        }
      },
      {
        "Name": "Logger",
        "Args": {
          "configureLogger": {
            "Using": [
              "Serilog.Sinks.Console",
              "Serilog.Expressions"
            ],
            "MinimumLevel": "Verbose",
            "Filter": [
              {
                "Name": "ByExcluding",
                "Args": {
                  "expression": "@Properties['TraceOperation'] is not null"
                }
              }
            ]
          }
        }
      }
    ]
  }
}

Expected behavior

To receive still the same added properties in 8.0.0 as with 7.2.0. Especially the testKey/testValue should be visible in Kibana.

Screenshots

• OS: Windows 10
• Kibana 8.11.1

[github-actions[bot]]

Hi there and welcome to this repository!

A maintainer will be with you shortly, but first and foremost I would like to thank you for taking the time to report this issue. Quality is of the highest priority for us, and we would never release anything with known defects. We aim to do our best but unfortunately you are here because you encountered something we didn't expect. Lets see if we can figure out what went wrong and provide a remedy for it.

[milbrandt]

Example can be reduced by using Serilog.Enrichers.Environment instead of a custom Enricher.

            var logconfig =
                new LoggerConfiguration()
                    .ReadFrom.Configuration(configuration)
                    .Enrich.WithMachineName();

reports the machine name with Serilog.Sinks.Http 8.0.0-beta.10, but no longer with 8.0.0-beta.11

[milbrandt]

The problem is a result of #235 The Wiki mentions a breaking change in v8 and states Applications that relied on this batch formatter had to keep a copy of the class. Unfortunately, this was not obvious, that already using Enrichers require this custom formatter for Kibana.

Formatter	Output
DefaultBatchFormatter	{"events":[{"Timestamp":"2024-04-10T09:47:39.9917731Z","Level":"Information","MessageTemplate":"XX","RenderedMessage":"XX","Properties":{"SourceContext":"Logging.TestApplication.Program","CorrelationId":"startupcorrelation/5ba919a8-c5ea-4513-bc2a-58638a3b86b5","MachineName":"CLNBCRMKX3","ApplicationId":"TestLoggingApplication","EnvironmentUserName":"milbrandt"}}
ArrayBatchFormatter	[{"Timestamp":"2024-04-10T09:48:52.5534533Z","Level":"Information","MessageTemplate":"XX","RenderedMessage":"XX","Properties":{"SourceContext":"Logging.TestApplication.Program","CorrelationId":"startupcorrelation/1610e8da-1dbf-4a58-b9ad-caa25f04e626","MachineName":"CLNBCRMKX3","ApplicationId":"TestLoggingApplication","EnvironmentUserName":"milbrandt"}}

With ArrayBatchFormatter in the log of LogStash we found:

[2024-04-08T16:01:55,601][WARN ][logstash.filters.split ][main][b8a778ff14b56223f94b0b8ce8aab229e9c4b53f09861f36597f22b88497dfb5] Only String and Array types are splittable.

field:events is of type = NilClass [2024-04-08T16:01:55,603][ERROR][logstash.filters.ruby ][main][4e050d468c9905ee4eeb9afdd8999ce9c3f7bb54328f953b87342c1078e46812] Ruby exception occurred: undefined method to_hash' for nil:NilClass {:class=>"NoMethodError", :backtrace=>["(ruby filter code):3:inblock in register'", "C:/ELK Stack/logstash-8.11.1/vendor/bundle/jruby/3.1.0/gems/logstash-filter-ruby-3.1.8/lib/logstash/filters/ruby.rb:96:in inline_script'", "C:/ELK Stack/logstash-8.11.1/vendor/bundle/jruby/3.1.0/gems/logstash-filter-ruby-3.1.8/lib/logstash/filters/ruby.rb:89:infilter'", "C:/ELK Stack/logstash-8.11.1/logstash-core/lib/logstash/filters/base.rb:158:in do_filter'", "C:/ELK Stack/logstash-8.11.1/logstash-core/lib/logstash/filters/base.rb:176:inblock in multi_filter'", "org/jruby/RubyArray.java:1987:in each'", "C:/ELK Stack/logstash-8.11.1/logstash-core/lib/logstash/filters/base.rb:173:inmulti_filter'", "org/logstash/config/ir/compiler/AbstractFilterDelegatorExt.java:133:in multi_filter'", "C:/ELK Stack/logstash-8.11.1/logstash-core/lib/logstash/java_pipeline.rb:304:inblock in start_workers'"]}

[FantasticFiasco]

Hi @milbrandt. Will start looking into this issue.

[FantasticFiasco]

I'd like your feedback. How should I phrase this breaking change in the change log and in the wiki, making sure that a reader understands the affect of the change?

[milbrandt]

As our installation of Kibana 8.11.1 from Nov. 2023 is even newer that Serilog.Sinks.Http v8, Kibana is common log server, and the not-enriched parts were arriving, I didn't were aware of the relevance of this note.

As Elastic Stack is already mentioned in the Introduction of the Readme, IMHO already there in the Readme it should mentioned, that data from Serilog Enrichers are only available with custom batch formatters.

In the change log of #178 and also in the wiki I would like a hint, that Enricher data are no longer available on Kibana with the new default ArrayBatchFormatter and that one needs to keep a copy of the DefaultBatchFormatter if one uses log enrichers.

[FantasticFiasco]

Perhaps I need to update Serilog and the Elastic Stack because on Elastic Stack v7.17.0 Serilog enrichers still do their job, they are represented as any other property on the log event. Are you telling me that v8 of the stack has changed the way properties are read and parsed by Elastic?

[milbrandt]

As I'm not in Elastic Stack development nor did I configure the installation and configuration of our Kibana server, I can't tell you if there was any change in the stack. As a hint I can only reference to the exception reported by LogStash. Also I'm not entitled in the company to downgrade Kibana to 7.x.y for testing.

The only thing I know for sure, the data from the ContextLogEnricher in my initial posting failed to be reported after upgrading from Serilog.Sinks.Http 8.0.0-beta.10 to 8.0.0-beta.11 without any change of our Kibana installation.

During my investigations on this issue I tried other enrichers, like Serilog.Enrichers.Environment using .Enrich.WithMachineName(), and observed the same issue of the machine name no longer showing up in the json displayed in the Kibana UI.

[FantasticFiasco]

I think this has to do with the configuration of your Logstash instance. I'm guessing that you've configured it to split the log events from the .events JSON property, and now that the events are located at the root of the JSON document, the configuration no longer matches the structure of the sent log events.

I've updated the example Serilog and the Elastic Stack to use a recent version of the Elastic stack, and everything works as expected.

I'm sorry for any inconvenience this major update caused you.