ILogger throws System.FormatException in .net8 but the same code works in .net7

[datoml]

Description

After upgrading our codebase to .NET8, we noticed a lot of System.FormatExceptions coming from the ILogger interface when we try to log some messages.
This only happens with some types of messages. After a closer look, messages created during runtime like these cause the problem.
"Hello, {name}}!", "Serilog"
It seems that something has changed within the message parser when log messages are provided with arguments.
In .NET7 it worked.

Below is a minimal example that works in .NET7 but crashes in .NET8.

Reproduction Steps

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Serilog;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateLogger();

var serviceCollection = new ServiceCollection();
serviceCollection.AddLogging(builder =>
{
    builder.ClearProviders();
    builder.AddSerilog(dispose: true);
});

var serviceProvider = serviceCollection.BuildServiceProvider();
var logger = serviceProvider.GetRequiredService<ILogger<Program>>();

logger.LogInformation("Hello, World!");
logger.LogInformation("Hello, {Name}!", "Serilog");
// Crashes in .NET8 but works with .NET7
logger.LogInformation("Hello, {Name}}!", "Serilog");

Console.ReadLine();

Expected behavior

[07:27:26 INF] Hello, World!
[07:27:26 INF] Hello, Serilog!
[07:27:26 INF] Hello, {Name}}!

Actual behavior

[07:21:01 INF] Hello, World!
[07:21:02 INF] Hello, Serilog!

..\bin\Debug\net8.0\ILoggerCrashExample.exe (process 25560) exited with code -1.

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

No response

[ghost]

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

After upgrading our codebase to .NET8, we noticed a lot of System.FormatExceptions coming from the ILogger interface when we try to log some messages.
This only happens with some types of messages. After a closer look, messages created during runtime like these cause the problem.
"Hello, {name}}!", "Serilog"
It seems that something has changed within the message parser when log messages are provided with arguments.
In .NET7 it worked.

Below is a minimal example that works in .NET7 but crashes in .NET8.

Reproduction Steps

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Serilog;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateLogger();

var serviceCollection = new ServiceCollection();
serviceCollection.AddLogging(builder =>
{
    builder.ClearProviders();
    builder.AddSerilog(dispose: true);
});

var serviceProvider = serviceCollection.BuildServiceProvider();
var logger = serviceProvider.GetRequiredService<ILogger<Program>>();

logger.LogInformation("Hello, World!");
logger.LogInformation("Hello, {Name}!", "Serilog");
// Crashes in .NET8 but works with .NET7
logger.LogInformation("Hello, {Name}}!", "Serilog");

Console.ReadLine();

Expected behavior

[07:27:26 INF] Hello, World!
[07:27:26 INF] Hello, Serilog!
[07:27:26 INF] Hello, {Name}}!

Actual behavior

[07:21:01 INF] Hello, World!
[07:21:02 INF] Hello, Serilog!

..\bin\Debug\net8.0\ILoggerCrashExample.exe (process 25560) exited with code -1.

Regression?

No response

Known Workarounds

No response

Configuration

No response

Other information

No response

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

[poizan42]

Isn't the old behaviour incorrect? To get the resulting string "Hello, {Name}}!" you should use the format string "Hello, {{Name}}}}!".

The string "Hello, {Name}}!}" should be parsed as "Hello, {0}" with argument 0 having name "Name}!", so the string "Hello, {Name}}!" is that but missing the termination of the placeholder name.

[stephentoub]

Isn't the old behaviour incorrect?

Yes. And CA2017 flags that, as a warning by default:

The difference here between .NET 7 and .NET 8 is when the parsing happens. The logging infrastructure maintains a cache of information about the format strings. In .NET 7, the format string itself was just stored in that cache, and the error would then only be detected when the string formatting actually happened. In .NET 8, CompositeFormat is used to parse the string when it's created, caching more information about it in order to speed up subsequent parsing. You can see that if you change the repro to just:

using Microsoft.Extensions.Logging;

ILogger logger = LoggerFactory.Create(b => b.AddConsole()).CreateLogger("repro");

logger.LogInformation("Hello, {Name}}!", "Serilog");

With the 7.0 version of the logging package, you get this call stack from the resulting exception:

Unhandled exception. System.AggregateException: An error occurred while writing to logger(s). (Input string was not in a correct format. Failure to parse near offset 8. Expected an ASCII digit.)
 ---> System.FormatException: Input string was not in a correct format. Failure to parse near offset 8. Expected an ASCII digit.
   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.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)

and with the 8.0 version of the package you get this call stack:

Unhandled exception. System.FormatException: Input string was not in a correct format. Failure to parse near offset 8. Expected an ASCII digit.
   at System.Text.CompositeFormat.Parse(String format)
   at Microsoft.Extensions.Logging.LogValuesFormatter..ctor(String format)
   at Microsoft.Extensions.Logging.FormattedLogValues.<>c.<.ctor>b__9_0(String f)
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   at Microsoft.Extensions.Logging.FormattedLogValues..ctor(String format, Object[] values)
   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)

This does mean, however, that if with the .NET 7 you never actually do the formatting because e.g. the logging level is set higher than the erroneous logged item's level:

using Microsoft.Extensions.Logging;

ILogger logger = LoggerFactory.Create(b => b.AddConsole().SetMinimumLevel(LogLevel.Warning)).CreateLogger("repro");

logger.LogInformation("Hello, {Name}}!", "Serilog");

the bug in the format string will go unnoticed.

[datoml]

So what would be a good approach here to avoid the problem?
The example is only extremely simplified because the problem came from a ToString method of an object.

Edit:
Also Serilog alone is able to parse it

[stephentoub]

Also Serilog alone is able to parse it

Then it's choosing to be more lenient on something that is erroneous.

So what would be a good approach here to avoid the problem? The example is only extremely simplified because the problem came from a ToString method of an object.

Why is the format string being dynamically generated? Best practice is to not do that: have a fixed set of placeholders in a well-defined format string, and put any dynamic content into the placeholders as arguments.

[datoml]

Why is the format string being dynamically generated? Best practice is to not do that: have a fixed set of placeholders in a well-defined format string, and put any dynamic content into the placeholders as arguments.

The problem was that the object was only more or less JSON stringified and sent to the logging library.
And the method automatically adds the line number and member name as arguments.
This then caused it to appear.

[tarekgh]

This looks you need to some validation before sending the string to the logger library. Not doing that can end with undesired or surprised behavior. Even with Serilog, it is kind of hiding the problem. Also, if you have control on the object get serialized, maybe good to fix that there.

[ghost]

This issue has been marked needs-author-action and may be missing some important information.

[datoml]

This looks you need to some validation before sending the string to the logger library. Not doing that can end with undesired or surprised behavior. Even with Serilog, it is kind of hiding the problem. Also, if you have control on the object get serialized, maybe good to fix that there.

I have already adjusted the serialization of the object so that this no longer happens.
So the fact that it worked with .NET7 was just a coincidence and only a matter of time before it would come to light.
With .NET8 it has now shown itself directly.

So the solution would be that when I log an object in serialized form, it first goes through a validation before it is logged.

[tarekgh]

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