Why Logging doesn't use string interpolation

Question

I have been following Logging in ASP.NET Core Which is working just fine.

I have a question about this line

_logger.LogWarning(LoggingEvents.GetItemNotFound, "GetById({ID}) NOT FOUND", id);

I am wondering why they are not using $ - string interpolation?

_logger.LogWarning(LoggingEvents.GetItemNotFound, $"GetById({ID}) NOT FOUND");

Why would the LogWarning extension have a params object[] args paramater?

Whats the point when you can just send everything in string message.

I assume there is a reason for this but i haven't been able to find an explanation anywhere. I am wondering which method i should be using in order to log properly in .net core.

Answer 1

I suspect the question can be rephrased to :

Why didn't they provide overloads that accept a FormattableString to pass message templates and parameters using string interpolation syntax, like EF Core does for parameterized queries?

I'd say they got it right. At this point in time using FormattableString offers minimal benefits but creates a lot of confusion.

I just found that Serilog's author explains why this isn't such a good idea even though a semantic logging library looks like a natural fit for this scenario

Semantic Logging

One can argue that FormattableString would be a great addition to semantic logging libraries like Serilog. In this case an interpolated string does lose important information.

The call

Log.Information("Logged in {UserId}", loggedInUserId);

Won't just log a string based on the template, it will keep the names and values of the parameters and provide them to filters and targets. Wouldn't it be great to get the same result with :

Log.Information($"Logged in {loggedInUserId}");

Serilog's author doesn't think so and explains that :

1. A good variable name is not necessarily a good property name
2. Holes don’t always have obvious names, eg Log.Information($"Enabling categories {new[]{1, 2, 3}}");

and concludes that

String interpolation is a great feature, one I’ve looked forward to in C# for a long time. The idea of providing direct support for Serilog is a very interesting one and worth exploring, but I’m increasingly convinced it’s unnecessary.

Interpolation is nice when it keeps code DRY, cutting out the redundant clutter of {0} and {1} and preventing parameter mismatches.

In the case of Serilog, I think it’s incorrect to consider the property names like {UserId} as redundant; in a well-implemented logging strategy they’re an incredibly important part of the picture that deserve their own consideration. You wouldn’t let variable names determine the table and column names in a relational database – it’s exactly the same trade-off being considered here.

Original explanation

That's one of the most controversial features of EF Core actually, and can easily result in the very SQL injection and conversion problems one wants to avoid by using parameters.

This call :

string city = "London";
var londonCustomers = context.Customers
    .FromSql($"SELECT * FROM Customers WHERE City = {city}");

calls FromSql(FormattableString) and will create a parameterized query :

SELECT * FROM Customers WHERE City = @p0

And pass London as a parameter value.

On the other hand this :

string city = "London";
var query=$"SELECT * FROM Customers WHERE City = {city}";
var londonCustomers = context.Customers.FromSql(query);

calls FromSql(string) and will generate :

SELECT * FROM Customers WHERE City = London

Which is invalid. It's far too common to fall in this trap even when you do know about the risk.

It doesn't help at all when you already have predefined queries or messages. This usage is far more common in logging, where you (should) use specific message templates defined in well known locations, instead of sprinkling similar looking strings in every log location.

One could argue that this addition made EF Core 2.0 somewhat safer because people had already started using string interpolation in EF Core 1.0, resulting in invalid queries. Adding the FormattableString overload the EF Core team was able to mitigate that scenario while making it easier to accidentally cause a different problem.

At this point in time the logging designers decided to avoid this confusion. Logging a raw string doesn't have such catastrophic consequences.

Answer 2

I know this is 4 years old but I don't feel any of the answers provided are really correct.

The reason is structured logging, if you use string interpolation you are just logging a single string, with structured logging you log the variables seperatly so you can access them more easily.

Imagine you have a website and you want to alert or provide a report on how long a page takes to load. You log it like this logger.LogDebug($"{PageName} took {ms}ms to load."); All your log can contain is "Index took 53ms to load."

If you log it like this instead logger.LogDebug("{PageName} took {ms}ms to laod.", PageName, sw.ElapsedMilliseconds); Then depending on your logging provider you can access all the properties seperatly and group by the PageName easily and filter all load times over 50ms. Without having to revert to Regular Expressions. E.g. SELECT PageName, Count(*) FROM Logs WHERE LogText = '{PageName} took {ms}ms to laod.' and ms > 50 GROUP BY PageName

Answer 3

At least two reasons.

First, logging pre-dates string interpolation, and Microsoft have not yet invented a time machine. String interpolation was only introduced in C# 6 in July 2015, but the logging methods follow the same pattern used in Microsoft.Build.Utilities since dotnet framework 2.0.

Second, Performance. If string interpolation is used and a string is passed as a parameter, then the interpolation is done before the call to Log. However not every call to Log results in something being logged - it depends on the configuration.

If you log something at DEBUG level and your current configuration is for INFORMATION level, the it is a waste of time to do string interpolation, you can just say "Thanks, but no thanks", and return immediately after doing nothing with the arguments.

Expanding on Second, Performance Internally, the most logger look basically like this:

void LogDebug(string Message, params object[] args){
    if(this.DebugEnabled){
        Log.Write(string.Format(Message,args)); 
    }
}

// 1 with parameters
LogDebug("GetById({ID}) NOT FOUND", id);
// 2 interpolated
LogDebug($"GetById({id}) NOT FOUND");

So if Debug is not enabled, one less interpolation operation is done.

Answer 4

The reason in my opinion is that .NET is using multiple levels of logging.

Trace = 0, Debug = 1, Information = 2, Warning = 3, Error = 4, Critical = 5 and None = 6.

There are differences between below codes although they look similar.

Structural logging

Logger.LogInformation("Hello {Name}", myName);

and

String Interpolation

Logger.LogInformation($"Hello {myName}");

String interpolation under the hood is identical to the use of string.Format(). Which means string.Format will always be executed disregarding the log level and pass the formatted string to the logger.

On the other hand, when structural logging is used, the string will only be formatted as per the log level is met.