LoggerMessage.Define doesn't support repeating the same named parameter in the message template

[davidfowl]

Description

LoggerMessage.Define blows up if the number of parameters doesn't match the specified template parameters even if the parameters used in the template are the same.

LoggerMessage.Define<string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

This throws, and it should work.

Regression?

No

Other information

Unhandled exception. System.ArgumentException: The format string 'Hello {Name}. How are you {Name}' does not have the expected number of named parameters. Expected 1 parameter(s) but found 2 parameter(s).
   at Microsoft.Extensions.Logging.LoggerMessage.CreateLogValuesFormatter(String formatString, Int32 expectedNamedParameterCount)
   at Microsoft.Extensions.Logging.LoggerMessage.Define[T1](LogLevel logLevel, EventId eventId, String formatString, Boolean skipEnabledCheck)
   at Microsoft.Extensions.Logging.LoggerMessage.Define[T1](LogLevel logLevel, EventId eventId, String formatString)
   at <Program>$.<Main>$(String[] args) in C:\Users\david\source\repos\WebApplication455\WebApplication455\Program.cs:line 10

[ghost]

Tagging subscribers to this area: @maryamariyan
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

LoggerMessage.Define blows up if the number of parameters doesn't match the specified template parameters even if the parameters used in the template are the same.

LoggerMessage.Define<string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

This throws, and it should work.

Regression?

No

Other information

Unhandled exception. System.ArgumentException: The format string 'Hello {Name}. How are you {Name}' does not have the expected number of named parameters. Expected 1 parameter(s) but found 2 parameter(s).
   at Microsoft.Extensions.Logging.LoggerMessage.CreateLogValuesFormatter(String formatString, Int32 expectedNamedParameterCount)
   at Microsoft.Extensions.Logging.LoggerMessage.Define[T1](LogLevel logLevel, EventId eventId, String formatString, Boolean skipEnabledCheck)
   at Microsoft.Extensions.Logging.LoggerMessage.Define[T1](LogLevel logLevel, EventId eventId, String formatString)
   at <Program>$.<Main>$(String[] args) in C:\Users\david\source\repos\WebApplication455\WebApplication455\Program.cs:line 10

Author:	davidfowl
Assignees:	-
Labels:	area-Extensions-Logging, untriaged
Milestone:	-

[davidfowl]

This also affects direct calls to LogX methods:

var loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
var logger = loggerFactory.CreateLogger("Foo");
logger.LogInformation("Hello {Name}. How are you {Name}", "David");

Blows up with:

Unhandled exception. System.AggregateException: An error occurred while writing to logger(s). (Index (zero based) must be greater than or equal to zero and less than the size of the argument list.)
 ---> System.FormatException: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.
   at System.Text.ValueStringBuilder.AppendFormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.FormatHelper(IFormatProvider provider, String format, ParamsArray args)
   at System.String.Format(IFormatProvider provider, String format, Object[] args)
   at Microsoft.Extensions.Logging.LogValuesFormatter.Format(Object[] values)
   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|12_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.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, EventId eventId, Exception exception, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.LogInformation(ILogger logger, String message, Object[] args)
   at <Program>$.<Main>$(String[] args) in C:\Users\david\source\repos\WebApplication455\WebApplication455\Program.cs:line 12

[davidfowl]

Thinking about why this isn't supported today, there could be some difficulty aligning template holes and specified arguments:

logger.LogInformation("Hello {Name}. Are you {Age} years old? How are you {Name}", "David", 100);
logger.LogInformation("Are you {Age} years old? How are you {Name}. Hello {Name}", 100, "David");

The first template would translate to:

string.Format("Hello {0}. Are you {1} years old? How are you {0}", "David", 100);

The second would be:

string.Format("Are you {0} years old? How are you {1}. Hello {1}", 100, "David");

Essentially, holes get a number based on the first time they occur in the template.

[gfoidl]

Both (LoggerMessage.Define and the LogXyz-extension method) go down to

runtime/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs

Line 26 in b05a892

public LogValuesFormatter(string format)

, thus the have the same error-behavior.

Recently I wondered about the same 😉, but then I thought it's better to be explicit: it's another hole in the format string, so there must be another argument provided. Even if it's the same one. And how likely is it actually to have the same parameter name multiple times?

Further: LoggerMessage.Define delegates are quite often wrapped by an extension method. So that method could handle the multiple parameters. Picking from your first example:

private static readonly Action<ILogger, string, Exception?> s_greet = LoggerMessage.Define<string, string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

public static void Greet(this ILogger logger, string name) => s_greet(logger, name, name, null);

I'm not sure what's the correct behavior though.

---

A really quick fix would be to use a Dictionary<string, int> in the LogValuesFormatter to track the named parameters.
For LoggerMessage.Define this seems OK, but for the LogXyz-extension that's an allocation for each call, so a no-go.
Besides that we have a rather small count of parameters (for LoggerMessage currently 6), so maybe the Dictionary is overkill, as a simple linear scan will work too.

This would work according to

Essentially, holes get a number based on the first time they occur in the template.

[davidfowl]

, thus the have the same error-behavior.

I'm aware 😉

The only thing that gives me pause is the fact that this hasn't been reported before. I wonder if what we have is simpler now and might result in more ambiguity.

[gfoidl]

I'm aware 😉

It was more for the record, than for you 😃

hasn't been reported before

Maybe because it is an artificial problem, not a real world one? (As it was in my case by testing the new overloads with skipEnabledCheck)

[davidfowl]

Possibly, but it's come up again because of the source generator generating LoggerMessage.Define calls. Will it show up more then?

public static class Log
{
    [LoggerMessage(Message = "Hello {Name}. Are you {Age} years old? How are you {Name}")]
    public void SayHello(string name, int age);
}

[gfoidl]

This is still a artificial example. Have you seen something in the wild?
Note: I'm not against changing the current behavior.

For semantic logging the count of provided parameters must match the count of placeholders.
Will a change here to allow multiple placeholders match the same argument open a can of worms?
Logging libraries like App Insights collector, Serilog, etc. would need to be adapted.

For the example from the source generator IMO the produced code should double the name argument.
For this to work the template needs to be parsed, and as I understand the proposal (didn't follow in depth) does something like this already for the fallback when there are > 6 placeholders.

[KalleOlaviNiemitalo]

A similar case logger.LogWarning("{0}{0}{1}", "Foo", "Bar"); came up in #50036. If duplicate names were allowed, then that would also be allowed. (0 and 1 would still be names rather than positional numbers.)

[maryamariyan]

So in example,

LoggerMessage.Define<string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

The runtime exception shown in this issue description is happening because the Define API expected one string argument but we see two named placeholders ({Name}) in the message template.

The runtime exception above can be safely prevented, with the logging analyzer shipped in 6.0 SDK. This analyzer verifies the number of named placeholders in the message template match the number of arguments N for Define<T1..,TN>.

To get unblocked with this issue, I think today if someone wanted to repeat the same argument they would also have to add more arguments to the Define argument. So for:

LoggerMessage.Define<string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

the code could update to:

LoggerMessage.Define<string, string>(LogLevel.Information, new(0, "LogSomething"), "Hello {Name}. How are you {Name}");

---

This would need to move to 7.0.

Fixing this issue involves updating the newly shipped logging analyzer so that it would not complain about mismatched number of arguments with count of named placeholders, when the same number of argument gets repeated.

[oocx]

To give an example from "something in the wild" - this is what I just tried and then stumbled upon this problem:

_logger.LogInformation("Neuer Saldo für Kasse {kasseId} nach Einzahlung von {betrag} {währung}: 0 {währung}", kasseId, betrag.Wert, betrag.Währung);

(which translates to "New balance for {registerId} after deposit of {sum} {currency}: {total} {currency}")