63

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

I have a question about this line that uses composite formatting:

_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 parameter?

What's the point when you can send everything in a string message?

I assume there is a reason for this but I haven't found an explanation anywhere. I am wondering which method I should be using to log properly in .NET Core.

Improve this question
13
  • Logging pre-dates string interpolation. Commented Sep 6, 2018 at 9:10
  • 1
    Who nose? Probably because they want to provide support for people not on C# 6? And because existing logging frameworks have that params object[] overload? Commented Sep 6, 2018 at 9:10
  • 1
    String interpolation does work, as long as there's an ID property or variable in context. Of course, that means that you lose all information about context, properties, variables etc and have only that one string that needs parsing to find out what it contains. Commented Sep 6, 2018 at 9:12
  • 1
    You asked two question (or three). 1) Why not log only strings? Because the parameters matter, because the string is actually just a description and the real actionable information is part of the category, event, severity, correlation parameters. Logging frameworks can use that information to select targets, message strings etc. Semantic logging also uses them Commented Sep 6, 2018 at 9:14
  • 1
    Here's a solution to use string interpolation with Serilog and not to lose structured logging benefits. Commented May 15, 2020 at 10:19

4 Answers 4

Reset to default
52

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 separately 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 separately 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 load.' and ms > 50 GROUP BY PageName

Improve this answer
Sign up to request clarification or add additional context in comments.

4 Comments

Great example, makes you think about how logs are queries in third party services like New Relic, CloudWatch etc.
"if you use string interpolation you are just logging a single string"...not actually true. string interpolation creates a formattablestring which could be used to support structured logging.
True, but does ILogger<T> use a FormattableString? I wasn't sure if the question was why didn't MS use FormattableString or why do you send it in a String.Format style and answered it as the latter.
@Darragh If it used a FormattableString, the value names would be {0}, {1}... etc which is not very usable when writing queries to the logs.
45

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.

Improve this answer

14 Comments

@DalmTo the Serilog article points to another problem. FormattableString doesn't capture the property names . You can only get arguments by position. This means that adding FormattableString to the generic Logging abstraction would cause problems when used with any library that cares about properties
@FrankM SQL Injection is an example from another service that does use interlopation and ended up causing trouble: EF Core.
@PanagiotisKanavos Serilogs author did not write anything about performance - pro or con. The other part I do now understand, the names of the parameters are replacing the string.Format's {0} {1}... for semantic evaluation of the given values. Thanks for explaining.
Here's a solution to use string interpolation with Serilog and not to lose structured logging benefits. stackoverflow.com/questions/61816775/…
I've just published a library (with extensions to Serilog, NLog, and Microsoft ILogger) which allows writing log messages using interpolated strings and yet defining the property names through anonymous objects. Would love to hear some feedback: github.com/Drizin/InterpolatedLogging
|
18

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.

Improve this answer

5 Comments

A far more important reason is that it's a bad idea. EF Core uses string interpolation for parameterized queries. The result: a lot of unintended SQL injection problems. Imagine extracting the the interpolation to a separate line. Instead of a parameterized query you get an injected string
The interpolated string isn't constructed from FormattableString until the conversion to string happens, if ever. So there's no performance penalty. Also, the first point explains why they didn't provide the feature initially. It doesn't explain why they still don't provide an overload taking a FormattableString.
That's correct. I've developed this library which converts FormattableString into message-template (it allows us to give meaninful-names to the interpolated variables), and according to my benchmarking tests the cost of creating FormattableString is irrelevant, and the cost of converting a FormattableString into a string is almost the same of building the strings in other ways. To sum, FormattableString is not as ugly as some people think. Take a look at benchmarks here: github.com/Drizin/InterpolatedLogging
To illustrate expensive parameter calculation, did you mean LogDebug("{obj} NOT FOUND", GetById(ID)) ?
Consideration about performance benefits for disabled log levels(e.g. Debug) is insignificant. Method arguments are always evaluated before the method is called, regardless of whether the method ends up doing anything internally .For possible options about introducing lazy evaluation see discussion github.com/serilog/serilog/issues/1458. But it’s not related to structural logging vs interpolation.
0

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.

Improve this answer

1 Comment

string.format creates a string, string interpolation creates a formattablestring which has a negligible cost

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.