ILogger mutates the array of objects to format

[BrightSoul]

Hello there, I'm using ASP.NET Core 3.1. Basically the problem is the one described in the title. Here's how to reproduce.

Create a new ASP.NET Core application with dotnet new web
Change the Configure method of the Startup class like this.

public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILogger<Startup> logger)
{
    app.UseRouting();

    app.UseEndpoints(endpoints =>
    {
        endpoints.MapGet("/", async context =>
        {
            //Here's the relevant part of the repro
            var values = new object[] { null };
            logger.LogInformation("These are the values", values);

            //Is the first value still null?
            bool stillNull = values[0] == null;

            //It's not! This displays: "Still null: False, Value is: (null)"
            await context.Response.WriteAsync($"Still null: {stillNull}. Value is: {values[0]}");
        });
    });
}

As you can see, the original null value gets replaced with the string (null). It's a very subtle behavior by the ILogger service and I think this is not right. The original array should be left untouched.

Of course, the workaround is to make it log a copy of the array.

logger.LogInformation("These are the values", values.ToArray());

That yields: "Still null: True. Value is:"

I'm not sure if this is the intended behavior. The LogInformation method description doesn't say anything about mutating the provided array.

Thanks,
Moreno

[javiercn]

@BrightSoul thanks for contacting us.

We'll look into this issue and get back to you.

@Pilchie now that extensions have moved to runtime, do we have a tag/place to put these types of issues? Is platform a good label for it? Just want to make sure that the right folks look at it.

[davidfowl]

I'll move it

[davidfowl]

Minimal repro, I haven't dug in as yet.

using System;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

namespace ConsoleApp15
{
    class Program
    {
        static void Main(string[] args)
        {
            using var loggerFactory = LoggerFactory.Create(logging =>
            {
                logging.Services.AddSingleton<ILoggerProvider, MyLoggerProvider>();
            });

            var logger = loggerFactory.CreateLogger<Program>();

            //Here's the relevant part of the repro
            var values = new object[] { null };
            logger.LogInformation("These are the values", values);

            //Is the first value still null?
            bool stillNull = values[0] == null;

            Console.WriteLine(stillNull);

            Console.Read();
        }
    }

    public class MyLoggerProvider : ILoggerProvider
    {
        public ILogger CreateLogger(string categoryName)
        {
            return new MyLogger();
        }

        public void Dispose()
        {

        }

        private class MyLogger : ILogger
        {
            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }

            public bool IsEnabled(LogLevel logLevel)
            {
                return true;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            {
                formatter(state, exception);
            }
        }
    }
}

[davidfowl]

Here's the code

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

Line 181 in d2f7c8f

return NullValue;

[davidfowl]

OK I took a quick look and this is a bug that's been there forever. My guess is it doesn't show up because what you're showing isn't typical usage.

The bug is here

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

Lines 117 to 127 in e3ffd34

	public string Format(object[] values)
	{
	if (values != null)
	{
	for (int i = 0; i < values.Length; i++)
	{
	values[i] = FormatArgument(values[i]);
	}
	}
	return string.Format(CultureInfo.InvariantCulture, _format, values ?? EmptyArray);

. When the logger provider tries to turn the object into a string, it get mutated here.

It should just copy the array before modifying it. We should be aware of the performance implications here though since this is a pretty hot and main code path.

[BrightSoul]

My guess is it doesn't show up because what you're showing isn't typical usage.

It came up after logging a formattableString.GetArguments() which contained a null value. That argument was changed and a subsequent query to the database produced an unexpected result. See for instance the FromSqlInterpolated extension method of DbSet<T> which works with FormattableString objects.
Anyway, thanks for looking into it!

[Frassle]

We hit this using FormattedLogValues class directly, we just copy the array before passing it in. Took a while to track down it was formatting code that was causing changes in our arrays.

[davidfowl]

We hit this using FormattedLogValues class directly, we just copy the array before passing it in. Took a while to track down it was formatting code that was causing changes in our arrays.

Are you on < 3.1 bits? FormattedLogValues is internal now.

[Frassle]

Are you on < 3.1 bits? FormattedLogValues is internal now.

I'll check when I'm in work Friday

[Frassle]

We're using Microsoft.Extensions.Logging.Abstractions 2.2.0.