A lot of log messages with messageTemplate equal {State:l}

[ThomasArdal]

I have a range of Azure functions logging to Serilog and through Microsoft.Extensions.Logging and Serilog.Extensions.Logging. The logging is configured like this:

var elasticsearchSinkOptions = new ElasticsearchSinkOptions(new Uri(config["Elasticsearch"]))
{
    AutoRegisterTemplate = false
};
var loggerConfiguration = new LoggerConfiguration()
    .WriteTo.Elasticsearch(elasticsearchSinkOptions)
    .MinimumLevel.Information();
Log.Logger = loggerConfiguration.CreateLogger();
builder.Services.AddLogging(logging =>
{
    logging.AddSerilog(dispose: true);
});

I'm getting a lot of log messages in Elasticsearch (from Azure Functions) where the messageTemplate is equal to {State:l}. When looking in the code for Serilog.Extensions.Logging, I see that this value is set when the state parameter is null in the Log method.

Can you help put some light on why this happens? Also, I would love to hear the decision around using {State:l} and {Message:l} for the messageTemplate field, rather than just copying the formated value to the messageTemplate field.

[ThomasArdal]

Any help here would be appreciated 👍

[nblumhardt]

Hey Thomas! Sorry, was taking a few days off, and have just come back to a packed inbox :-)

Serilog internally caches message templates; using pre-formatted strings in the place of message templates can reduce the effectiveness/efficiency of the cache, and is generally discouraged in favor of recording structured data. Not sure how much that applies here, but pretty sure the original thinking was along those lines.

[adamchester]

Hi @ThomasArdal, I think you’ll find these are coming Azure Functions host, so asking them why they wrote the log messages that way might help shed some light.

[adamchester]

P.s. I see them too, and they slightly annoy me, but I haven’t yet been motivated to ask why or dig deeper.

[nblumhardt]

Here's where the conversion happens: https://github.com/serilog/serilog-extensions-logging/blob/dev/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs#L116

It'll be something to do with Azure Functions logging objects rather than templates. Doesn't seem to be an issue with the rest of the stack, so probably is up to them to make the improvement 👍

[adamchester]

That's right - they don't provide a template :+1:

[adamchester]

I wonder if we could/should iterate over the public properties and turn that into the template?

[nblumhardt]

With a lot of enrichment, the resulting template and rendered message could get arbitrarily large - I'm okay with the status quo, personally :-)

[ThomasArdal]

@nblumhardt No worries at all. Vacation is important. I hope you had a good one 👍

I've looked into the WebJobs.Host code. They sure do some funky stuff. I guess it's fine, but something like this (simplified from their code):

log.Log(LogLevel.Information, 0, new ReadOnlyDictionary<string, object>(new Dictionary<string, object>
{
    ["AvgDurationMs"] = TimeSpan.FromSeconds(1),
}), null, (s, e) => null);

Does indeed cause message to be null and messageTemplate to be {State:l}. At least generating something is better than nothing. I checked in the Microsoft.Extensions.Logging I did for elmah.io. Logging the above data will cause both message and messageTemplate to be null 😒 Not sure I want to put {State:l} in there, though. Generating something from the properties is an option. But I definitely see problems there as well.

Maybe I should just accept the {State:l} template for this kind of logging 🤔

[nblumhardt]

Could be the way to go 👍 :-)