Malformed message template string should throw warning or compiler error as a preference over runtime exceptions

[Kritner]

          I am closing the issue but feel free to respond if you still have any questions.

Originally posted by @tarekgh in https://github.com/dotnet/runtime/issues/97852#issuecomment-1924743297

---

Couldn't respond since locked, but we ran into this and is exceedingly frustrating. Will add additional information momentarily

---

Issue:

malformed message template strings for at a minimum logged messages should be throwing compiler errors IMO, rather than the current runtime errors seen with .net8.

Repro: https://github.com/Kritner/MessageTemplateNet8

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

HostApplicationBuilder builder = Host.CreateApplicationBuilder(args);
builder.Services.AddLogging(loggingBuilder => loggingBuilder.AddConsole());

var host = builder.Build();

var logger = host.Services.GetRequiredService<ILogger<Program>>();

logger.LogInformation("Hello world");

var i = 5;
logger.LogInformation("My value {i}}", i);

~This same code does not encounter a run time error in .net7. When updating to .net8 in a large code base,~ there is no indication that the badly message template will fail at run time, but it can and does (see above screenshot).

I feel like this needs to be a compiler error, lest you run into the same run time errors I've encountered.

[tarekgh]

In C#, only the interpolated strings in the form of $"..." is get validated. In general "My value {i}} is a valid C# string but its usage in logging messages will be invalid which is detected at runtime. Maybe having C# analyzer can help in such scenario but considering the high priority work we are doing this will be addressed in the future. Meanwhile, if you interested, you can write your analyzer and use it in your codebase. https://learn.microsoft.com/en-us/visualstudio/code-quality/roslyn-analyzers-overview?view=vs-2022.

[buyaa-n]

I feel like this needs to be a compiler error, lest you run into the same run time errors I've encountered.

It seems this scenario is already covered with https://learn.microsoft.com/en-us/dotnet/fundamentals/code-analysis/quality-rules/ca2017 @Kritner could you enable that analyzer in your repo (it is enabled and warns by default, but the rule might disabled for your project) and check the diagnostics?

[Kritner]

I feel like this needs to be a compiler error, lest you run into the same run time errors I've encountered.

It seems this scenario is already covered with https://learn.microsoft.com/en-us/dotnet/fundamentals/code-analysis/quality-rules/ca2017 @Kritner could you enable that analyzer in your repo (it is enabled and warns by default, but the rule might disabled for your project) and check the diagnostics?

Yeah so it's weird... we're not NoWarning against this particular "CA2017", but we don't get the string template being flagged as a CA2017... I can easily make the CA2017 appear (and get a compiler error yay) if I change...

logger.LogInformation("My value {i}}", i);

to

logger.LogInformation("My value {i}", i, i+1);

[buyaa-n]

Yeah, looks it is not covered with CA2017 when it should

[Kritner]

I added a potential fix in https://github.com/dotnet/roslyn-analyzers/pull/7286, but i'm not sure that the current CA2017 wording really fits with the new trigger for failure.

When you have unmatched/unclosed brackets that doesn't quite jive with the above error message. Does that warrant updating the message, or it being its own new CA____?

[buyaa-n]

When you have unmatched/unclosed brackets that doesn't quite jive with the above error message. Does that warrant updating the message, or it being its own new CA____?

You can have a same rule id with different message, look https://github.com/dotnet/roslyn-analyzers/blob/main/src/NetAnalyzers/Core/Microsoft.NetCore.Analyzers/Runtime/AttributeStringLiteralsShouldParseCorrectly.cs#L43 for example, it has 2 diagnostics with different message but same id

[Kritner]

I've not worked w/ localization before, what's the expectation around providing strings for other languages? just... don't and they'll get filled in over time in additional PRs or something else?

[buyaa-n]

You just need to add the new message to the https://github.com/dotnet/roslyn-analyzers/blob/main/src/NetAnalyzers/Core/Microsoft.NetCore.Analyzers/MicrosoftNetCoreAnalyzersResources.resx in English, then build, the build will generate resources for other languages which will be translated later with other professionals, you don't need to worry about that

[stephentoub]

This same code does not encounter a run time error in .net7.

FWIW, it does for me. On .NET 7:

info: Program[0]
      Hello world
Unhandled exception. System.AggregateException: An error occurred while writing to logger(s). (Input string was not in a correct format.)
 ---> System.FormatException: Input string was not in a correct format.
   at System.Text.ValueStringBuilder.ThrowFormatInvalidString()
   at System.Text.ValueStringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ReadOnlySpan`1 args)
   at System.String.FormatHelper(IFormatProvider provider, String format, ReadOnlySpan`1 args)
   at System.String.Format(IFormatProvider provider, String format, Object[] args)
   at Microsoft.Extensions.Logging.LogValuesFormatter.Format(Object[] values)
   at Microsoft.Extensions.Logging.FormattedLogValues.ToString()
   at Microsoft.Extensions.Logging.LoggerExtensions.MessageFormatter(FormattedLogValues state, Exception error)
   at Microsoft.Extensions.Logging.Console.SimpleConsoleFormatter.Write[TState](LogEntry`1& logEntry, IExternalScopeProvider scopeProvider, TextWriter textWriter)
   at Microsoft.Extensions.Logging.Console.ConsoleLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|13_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger`1.Microsoft.Extensions.Logging.ILogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, EventId eventId, Exception exception, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.LogInformation(ILogger logger, String message, Object[] args)
   at Program.<Main>$(String[] args)

[Kritner]

This same code does not encounter a run time error in .net7.

FWIW, it does for me. On .NET 7:

yeah i'm not sure what exactly happened here - i can confirm i see the behavior on .net7 as well now. Could this have been a change to one of the minor/patch revs of logging or something else?

Cuz it's the weirdest thing, this is seemingly a pretty hot path of code for us, but we didn't start seeing exceptions here until the .net8 update. But yeah, rolling back to .net7 now and still seeing the issue

EDIT:

in our codebase where we actually encountered the issue we're using serilog, i'm wondering if we also updated that package version in our update to .net8, and maybe it was masking the issue? It's certainly bothering me now that we didn't see it before updating to .net8, but then going back to .net7 didn't fix it 😓

either way though, i don't think the idea of a new analyzer looking for these issues is a bad thing yeah?