Formatting a log message: repeating the same positional parameter leads to exception

[hpetith]

Description of the bug

When issuing a log message trough ILogger, where the format string repeats a positional parameter, an exception is raised by a formatting layer of the logging extensions:

        logger.LogWarning("{0}{0}{1}", "Foo", "Bar");

To Reproduce

Please refer to the attached VS 2019 solution.
LoggingFormatError.zip

Expected behavior

The above programs logs "FooFooBar" to the console.

Screenshots resp. exception stack trace

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.FormattedLogValues.ToString()
   at Microsoft.Extensions.Logging.LoggerExtensions.MessageFormatter(FormattedLogValues state, Exception error)
   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.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.LogWarning(ILogger logger, String message, Object[] args)
   at LoggingFormatError.Program.Main(String[] args) in C:\projects\LoggingFormatError\Program.cs:line 12

C:\projects\LoggingFormatError\bin\Debug\net5.0\LoggingFormatError.exe (process 12888) exited with code -532462766.

Additional context

The behavior is the same on .NET 4.7.2, .NET Core 3.1 and .NET 5.0. The attached solution is built on .NET 5.0

[ghost]

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

Issue Details

---

Description of the bug

When issuing a log message trough ILogger, where the format string repeats a positional parameter, an exception is raised by a formatting layer of the logging extensions:

        logger.LogWarning("{0}{0}{1}", "Foo", "Bar");

To Reproduce

Please refer to the attached VS 2019 solution.
LoggingFormatError.zip

Expected behavior

The above programs logs "FooFooBar" to the console.

Screenshots resp. exception stack trace

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.FormattedLogValues.ToString()
at Microsoft.Extensions.Logging.LoggerExtensions.MessageFormatter(FormattedLogValues state, Exception error)
at Microsoft.Extensions.Logging.Console.ConsoleLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func3 formatter) at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|12_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func3 formatter, List1& exceptions, TState& state) --- End of inner exception stack trace --- at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List1 exceptions)
at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func3 formatter) at Microsoft.Extensions.Logging.Logger1.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.LogWarning(ILogger logger, String message, Object[] args)
at LoggingFormatError.Program.Main(String[] args) in C:\projects\LoggingFormatError\Program.cs:line 12

C:\projects\LoggingFormatError\bin\Debug\net5.0\LoggingFormatError.exe (process 12888) exited with code -532462766.

Additional context

The behavior is the same on .NET 4.7.2, .NET Core 3.1 and .NET 5.0. The attached solution is built on .NET 5.0

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

[KalleOlaviNiemitalo]

AFAIK, Microsoft.Extensions.Logging is not designed to support positional parameters at all. See Log message template. The analysers in #36064 would give warning MEL0001 for this code.

[hpetith]

You are right. When I reported the exception that started the thread, I was under the belief that the string fed with numbers as placeholders behaves like "traditional format string". It is not, as you write: it is a message template made to support structured logging. It is a pity that the "official" ILogger documentation (e.g. https://docs.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.loggerextensions.logerror?view=dotnet-plat-ext-5.0#Microsoft_Extensions_Logging_LoggerExtensions_LogError_Microsoft_Extensions_Logging_ILogger_Microsoft_Extensions_Logging_EventId_System_Exception_System_String_System_Object___ ) is not very explicit about this: it does not explain what "message template format" is in contrast to a format string.

Since my usage is wrong, and since the recommended log analyzer gives a warning for the wrong usage, we can close the issue.

[KalleOlaviNiemitalo]

A few hyperlinks from the reference documentation to the conceptual documentation would make the correct usage easier to understand. I don't think there is an open issue for adding any, although dotnet/dotnet-api-docs#5039 looks like it would cover adding such a link in the Microsoft.Extensions.Logging Namespace topic, and #48951 might make such links easier to add in method parameter documentation.