Runtime: 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.

```C#
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();
});

        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 https://github.com/dotnet/runtime/blob/d2f7c8f52b7b21112a7765d311dc82a413e7116c/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs#L181

[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 https://github.com/dotnet/runtime/blob/e3ffd343ad5bd3a999cb9515f59e6e7a777b2c34/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LogValuesFormatter.cs#L117-L127. 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.

[vaz-rodrigo]

Isn't this the same thing as issue 36025?

Anyway, can I work on this?

[WernerMairl]

Hi
i have prepared a few tests and fix here:

https://github.com/WernerMairl/runtime/commit/feb8982c5081649d2b7e1788b6f4bcf5773ecf79

(ready for feedback/discussions specially about performance impact.....)

Assuming that this should go into master/6.0
But i was not able to compile with 6.0 (may be there is a bigger change in progress from 5.0 to 6.0)
So i did the dev work based on the 5.0 release branch, assuming that if we agree on the implementation i can create a PR for master/6.0 later on....

regards
Werner

[PathogenDavid]

@WernerMairl Did you investigate implementing an IFormatProvider instead? I think that'd avoid the redundant array allocation and still allow customizing the formatting behavior IEnumerable.

[WernerMairl]

@PathogenDavid can you explain how a IFormatProvider should avoid that?
I cannot follow....

Yes the array needs array allocation but not sure how much effort we should spend for optimizations without better measurements (benchmarks).....

[WernerMairl]

@vaz-rodrigo : i have seen your code after creating my one - exactly the same ;-)

I have 1 or 2 tests different and may be a simpler testing aproach...
so we can merge/decide after the "allocation" discussion....

[PathogenDavid]

@WernerMairl From what I can see, the crux of the issue is that LogValuesFormatter.Format(object[]) is pre-formatting IEnumerable in order to bypass their default format logic to provide something more useful in logs.

IFormatProvider is capable of providing an alternative formatter for string.Format to use directly instead of trying to do the alternate formatting ahead of time. (Simplified example here)

I don't really have a horse in this race, but my gut reaction is that doubling allocations in order to handle an uncommon case isn't ideal.

[KalleOlaviNiemitalo]

Implementing via ICustomFormatter might increase the number of string allocations by disabling the ISpanFormattable optimization.

[KalleOlaviNiemitalo]

If you worry about the array allocation, then perhaps LogValuesFormatter.Format(object[]) can do it lazily when it finds an array element that cannot be used as is, i.e. the value is either null or an IEnumerable other than string. However, it would be best to have some benchmarks before adding such complexity. I don't know what fraction of log calls in real programs have null references among the values. For IEnumerable values, I suspect the string.Join(", ", enumerable.Cast<object>().Select(o => o ?? NullValue)) expression in LogValuesFormatter.FormatArgument(object) causes so many allocations that the array does not matter. And if the log level is disabled, then the log entry won't be formatted anyway.