Practically investigating why "CA2254: Template should be a static expression" exists and what we can do about it.

CA2254: Template should be a static expression is a warning that the log message doesn't have a consistent structure due to being interpolated or concatenated.

The solution is to use a message template.

If that isn't enough, the rest of this readme explains the benefits of using templates for logging.

In short, giving structure to our logs helps us more easily read, parse, and query our logs.

The NLog wiki:

Structured logging makes it easier to store and query log-events, as the logevent message-template and message-parameters are preserved, instead of just transforming them into a formatted message.

To take an example from the .NET logging documentation, consider the following logger method:

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

For example, when logging to Azure Table Storage:

• Each Azure Table entity can have ID and RunTime properties.
• Tables with properties simplify queries on logged data. For example, a query can find all logs within a particular RunTime range without having to parse the time out of the text message.

Though, it may be the case that you're doing a small hobby project, or throwaway code, or anything that isn't going to have a massive amount of logs to trawl through when a production issue occurs, then you can probably ignore the warning and #pragma it away. However, there are also performance implications of using string interpolation regardless of intent of using full blown structured logging.

The heading Avoid string interpolation in logging explains:

String interpolation in logging is problematic for performance, as the string is evaluated even if the corresponding LogLevel isn't enabled.

This is because the string interpolated value is evaluated at the time of passing the string into the ILogger call, not after the log message is ready to be sent to a provider. For example if we look at interpolation:

var time = "3:00 PM";

// This interpolated string
_logger.LogInformation($"The time is currently: {time}");

// has the interpolation cost done to it before entering the LogInformation() method, meaning the call ends up being:
_logger.LogInformation($"The time is currently: 3:00 PM");

Contrast this with using a log message template:

var time = "3:00 PM";

// This log template is passed as is to the underlying call without upfront interpolation cost
_logger.LogInformation("The time is currently: {currentTime}", time);

You can see for yourself in the Logger class in Logger.cs where we can pick up a couple of key checks before a log message is written:

1. If there are any providers to log to. E.g. Console, EventSource, EventLog, etc
2. If the right level is enabled for this message for this provider

Only then is work put in to interpolate our string.

Let's look at performance metrics. The benchmarks are off the back of the default weather example when creating a new minimal API with some of the randomness and allocations removed. Work is still left in to ensure our benchmarks aren't jitted away. There will be two benchmarks: Interpolation, and Template. They both use LogInformation() for information level logging.

// Interpolation
_logger.LogInformation($"Returning weather forecast. Day 1 summary: {forecast[0].Summary}");

// Template
_logger.LogInformation("Returning weather forecast. Day 1 summary: {summary}", forecast[0].Summary);

Both will log the same string:

"Returning weather forecast. Day 1 summary: Sweltering"

No log message is written regardless of level.

With no providers to log to, the interpolation occuring creates more allocations than the template - increasing garbage collection pressure. The template allocations are due to calling into a function with a params parameter, leading to an array allocation (I believe).

The Logger object will attempt to log to the console, but due to the warning log level, none of the information logs will be written.

Same outcome as having no provider.

The Logger object will log the weather string to the console.

When writing a log message, slightly more allocation has come from the template version. However this is acceptable as most logging calls in a production environment are skipped over. Unless needed, it's a poor idea to have logs in production to be at a lower, more verbose level. Meaning there is an overall gain in memory savings, and an overall reduction in GC pressure when templating.

• Needed to remove the log levels from appsettings.json and appsettings.Development.json which override the logging levels
• The project is runnable and has two endpoints returning the same value:
  • https://localhost:7023/weatherforecast-improper-structuring
  • https://localhost:7023/weatherforecast-proper-structuring
• To run the benchmarks do dotnet run --configuration Release

• CA2254: Template should be a static expression
• Logging in C# and .NET
• Logging in .NET Core and ASP.NET Core
• Logging guidance for .NET library authors
• How to use structured logging by NLog
• ZLogger: A zero allocation text/structured logger (for interest)