Positional placeholder in format strings interpreted as fields

[bonza]

Hi,

we've encountered an issue with our logging format strings which looks like this:

logger.LogInformation("Some testing! {0} {1}", 123, 456);

because these numerical placeholders ended up in Graylog like this

Is it possible to make structured logging optional, or maybe ignore numbers in format strings?

[mattwcole]

Hi, apologies for the delay getting back to you. The first argument passed to the logger is the message template, and it should not contain numbered placeholders. This is explained in the official documentation on message templates.

Each log API uses a message template. The message template can contain placeholders for which arguments are provided. Use names for the placeholders, not numbers.

If you give the placeholders meaningful names then you will be able to easily query your logs for these values. If you have no requirement to do so, you can use string interpolation instead, but you will be reducing the usefulness of your logs, by removing the structured data.

[jane-u]

Hi Matt! Thank you for your response. It is not the problem for us to understand how this feature works. It is a problem that we cannot switch it off at all unless we use some hacky ways which is not good. We can use names instead of numbers, but we do NOT want them to appear in log fields and we need to keep a deferred string formatting. Is it possible to have this feature configured to be able to switch it off? Now these fields are added unconditionally: https://github.com/mattwcole/gelf-extensions-logging/blob/2c58eb6a556feca1daaab9f590e636d058fddc1d/src/Gelf.Extensions.Logging/GelfLogger.cs#L98 Would you accept a pull request from us?

[mattwcole]

I'm reluctant to make that change because there is already a way to omit properties from logs. Just don't pass them to the logger.

// Structured
_logger.LogInformation("Getting item {Id} at {RunTime}", id, DateTime.Now);

// Non structured
_logger.LogInformation($"Getting item {id} at {DateTime.Now}");
_logger.LogInformation(string.Format("Getting item {0} at {1}", id, DateTime.Now));

This is the intended API usage, and importantly will work with every provider for Microsoft.Extensions.Logging. A feature toggle in this library that ignores properties may fix your immediate problem with Graylog, but it makes the library non-standard. If you switched to any other logging provider, your unwanted properties would be back. The best solution here is the one that works for all providers.

we need to keep a deferred string formatting

I'm open to hearing more about this if the above really isn't an option for you.

[jane-u]

I'm not too familiar with other logging providers, but I've checked one of them https://github.com/serilog/serilog-extensions-logging/blob/7141ae23125cbdb6b67df6f9aab1c42f1fa58366/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs and it looks like it already works in a different way in regard of our topic. There is no any Regex to reject some properties, only basic null-empty check, and, instead, @ and $ used to distinguish some types of properties. I am sure there are other behaviour differences, as well as extra features (extensions methods, etc) which exist only for one logging provider, I saw some for Serilog. I can see that configuration is also different anyway and some things might stop or start working after provider switch.

About our needs. Earlier we used log4net, mostly, where we used message templates, and for our NET Core apps we had not that many log messages and templates at all. Now we need to have a lot of logs with a lot of properties in NET core apps.

Why we use message templates: we use very wide range of log levels and we have use cases when we configure different log levels (local run, different environments). When we have many debug logs with many properties, we have to take care that none of formatting happens before the log level is checked, and it is checked before formatting by any decent logging provider, for instance: https://github.com/mattwcole/gelf-extensions-logging/blob/2c58eb6a556feca1daaab9f590e636d058fddc1d/src/Gelf.Extensions.Logging/GelfLogger.cs#L39

https://github.com/serilog/serilog-extensions-logging/blob/7141ae23125cbdb6b67df6f9aab1c42f1fa58366/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs#L62

So this does NOT work and it is bad especially for production:

logger.LogDebug($"Test data: {testDataTitle} {testDataBody}.");
logger.LogDebug(string.Format("Test data: {0} {1}.", testDataTitle, testDataBody));

And in order to make this work, we have to do that:

if(logger.IsEnabled(LogLevel.Debug)
{
   logger.LogDebug($"Test data: {testDataTitle} {testDataBody}.");
}

And it clutters our code. A lot. This is one line per debug log vs FOUR lines per debug log and there is a chance that if/when log level will be modified, one of these two places will be forgotten.

Behavioural compatibility is one thing. Another important thing is code compatibility and a possibility to use standard logger interfaces without any extra wrappers or extension methods. If they are decorators or outer extension methods with the same interface, then it is easy not to use them accidentally. If there has to be some other interface, it makes extra layer, non-standard interfaces and this is worse, than reconfiguring, because it affects all the code and not only the startup, it brings the same wrappers to any application which has to be managed additionally, and this is not good. This is why the option of putting extra IsEnabled check into these wrappers is not preferable. A workaround to make this library not write the fields with current implementation is also possible, using specific names for template placeholders, but that also affects ALL the code and so it is not preferable, too.

We already have a way to write log properties consistently without using these fields, and fields actually bring only chaos into this system and can even override something accidentally.

I hope it helps to understand our request.

[mattwcole]

Thank you for the detailed explanation. I understand that you are concerned about the performance penalty of eagerly formatting log messages when the log level may be disabled.

There is a solution that exists already if you are willing to decorate ILogger with something like this. It has the advantage of working with all logging providers. This is how it looks in a .NET 6 minimal API (using Scrutor).

var builder = WebApplication.CreateBuilder(args);

builder.Services.Decorate<ILoggerFactory, CustomLoggerFactory>();
builder.Logging.AddGelf(options =>
{
    options.Host = "localhost";
    options.LogSource = "DemoApi";
});

using var app = builder.Build();

app.MapGet("/", (ILogger<Program> logger) =>
{
    logger.LogInformation("{Foo} is {Bar}", "Semantic logging", "disabled");
    return "Hello World!";
});

app.Run();

If this is too convoluted for you I will accept a PR that adds IncludeTemplateParameters (or similar) that functions in the same way as GelfLoggerOptions.IncludeScopes.

[mattwcole]

Closing for now as there is a way forward without modifying the library.