[Microsoft.Extensions.Logging] Bug: Logging arrays is broken and behaves unreliably

[czdietrich]

Description

Depending on which option is used for logging (Source Generators, LoggerMessage.Define, Logger.Log) the resulting format for arrays (or any other type of enumeration) is different and sometimes even unusable.

On the first glance the issue seems to be part of the LogValuesFormatter that tries to specially handle enumerations using TryFormatArgumentIfNullOrEnumerable.

The issue is probably caused here where TryFormatArgumentIfNullOrEnumerable is not invoked for every parameter in some combinations:

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

Lines 207 to 215 in f6dc71b

	{
	object? arg0String = null, arg1String = null, arg2String = null;
	return
	!TryFormatArgumentIfNullOrEnumerable(arg0, ref arg0String) &&
	!TryFormatArgumentIfNullOrEnumerable(arg1, ref arg1String) &&
	!TryFormatArgumentIfNullOrEnumerable(arg2, ref arg2String) ?
	string.Format(CultureInfo.InvariantCulture, _format, arg0, arg1, arg2) :
	string.Format(CultureInfo.InvariantCulture, _format, arg0String ?? arg0, arg1String ?? arg1, arg2String ?? arg2);
	}

Reproduction Steps

1. Create a new console application for net8.0
2. Add Microsoft.Extensions.Logging.Console NuGet in version 8.0.0
3. Paste the following code into Program.cs

using Microsoft.Extensions.Logging;

public static partial class Program
{
    private const string MessageTemplate = "Log {Number}: {Array1} and {Array2}";

    private static readonly string[] Array1 = ["a", "b", "c"];
    private static readonly string[] Array2 = ["d", "e", "f"];        

    [LoggerMessage( EventId = 0, Level = LogLevel.Information, Message = MessageTemplate )]
    private static partial void LogBad(this ILogger logger, int number, string[] array1, string[] array2);

    [LoggerMessage( EventId = 0, Level = LogLevel.Information, Message = MessageTemplate )]
    private static partial void LogGood(this ILogger logger, string[] array1, string[] array2, int number);
    
    public static void Main()
    {
        var logger = LoggerFactory
            .Create( x => x.AddConsole() )
            .CreateLogger( "Logger" );

        logger.LogBad( 10, Array1, Array2 );
        logger.LogGood( Array1, Array2, 20 );

        var badDefine = LoggerMessage.Define<int, string[], string[]>( LogLevel.Information, new EventId(), MessageTemplate );
        
        badDefine( logger, 30, Array1, Array2, null );
        
        logger.LogInformation( MessageTemplate, 40, Array1, Array2 );
    }
}

4. Run the application

Expected behavior

The resulting log should look something like this:

info: Logger[0]
      Log 10: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 40: [a, b, c] and [d, e, f]

Actual behavior

The resulting log entries look different. Some options struggle with formatting arrays.

info: Logger[0]
      Log 10: a, b, c and System.String[]
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and System.String[]
info: Logger[0]
      Log 40: a, b, c and d, e, f

Regression?

No response

Known Workarounds

The issue can be minimized if the enumerations (e.g. an array) are passed as first parameters of the logging invocation. Alternatively the developer can manually format the arrays and pass the value as a string parameter.

Configuration

SDK version: 8.0.300

Other information

No response

[dotnet-policy-service]

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

[julealgon]

@czdietrich

Known Workarounds

The issue can be minimized if the enumerations (e.g. an array) are passed as first parameters of the logging invocation. Alternatively the developer can manually format the arrays and pass the value as a string parameter.

You can also use the Microsoft.Extensions.Telemetry packages which better support collections:

• https://github.com/dotnet/extensions/tree/main/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions#enhanced-logging-capabilities

The package includes a custom logging generator that enhances the default .NET logging capabilities by replacing the default generator. This generator automatically logs the contents of collections

[czdietrich]

You can also use the Microsoft.Extensions.Telemetry packages which better support collections:

Thank you for the suggestion. This NuGet package has indeed an effect on the logging methods created by the source generator. The ones without source generator nevertheless behave differently.

info: Logger[0]
      Log 10: ["a","b","c"] and ["d","e","f"]
info: Logger[0]
      Log 20: ["a","b","c"] and ["d","e","f"]
info: Logger[0]
      Log 30: a, b, c and System.String[]
info: Logger[0]
      Log 40: a, b, c and d, e, f

[tarekgh]

Closing this as Microsoft.Extensions.Telemetry source generation supports advanced logging for cases like this. We may consider addressing this in the runtime source generation in the future if we encounter any issues that prevent the use of Microsoft.Extensions.Telemetry.

[czdietrich]

Closing this as Microsoft.Extensions.Telemetry source generation supports advanced logging for cases like this. We may consider addressing this in the runtime source generation in the future if we encounter any issues that prevent the use of Microsoft.Extensions.Telemetry.

I have to disagree.

This is obviously a bug and not by design. Using LoggerMessage.Define which is recommended for high performance logging prints a, b, c for the first passed array and System.String[] for the second array.

This must be classified as a bug, not something that could be improved some day in the future.

[tarekgh]

Fair enough. I reactivated the issue.

[KalleOlaviNiemitalo]

This is a regression.

To make the repro compatible with .NET SDK 6, I changed the initialization syntax to:

    private static readonly string[] Array1 = {"a", "b", "c"};
    private static readonly string[] Array2 = {"d", "e", "f"};

In each test case below, the Microsoft.Extensions.Logging.Console package was the same version as Microsoft.Extensions.Logging.Abstractions.

Microsoft.Extensions.Logging.Abstractions 6.0.0 on .NET SDK 6.0.424 targeting net6.0

info: Logger[0]
      Log 10: a, b, c and d, e, f
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and d, e, f
info: Logger[0]
      Log 40: a, b, c and d, e, f

This correctly formatted each array as a comma-delimited list.

However, some arrays have brackets around them and others don't. That is because the generated LogGood method uses __LoggerMessageGenerator.Enumerate, which adds brackets, but the others use LogValuesFormatter, which doesn't.

Microsoft.Extensions.Logging.Abstractions 7.0.0 on .NET SDK 6.0.424 targeting net6.0

info: Logger[0]
      Log 10: a, b, c and d, e, f
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and d, e, f
info: Logger[0]
      Log 40: a, b, c and d, e, f

The output is the same as with version 6.0.0 of the packages.

Microsoft.Extensions.Logging.Abstractions 8.0.0 on .NET SDK 6.0.424 targeting net6.0

info: Logger[0]
      Log 10: a, b, c and d, e, f
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and d, e, f
info: Logger[0]
      Log 40: a, b, c and d, e, f

This is still the same.

Microsoft.Extensions.Logging.Abstractions 7.0.0 on .NET SDK 8.0.303 targeting net8.0

info: Logger[0]
      Log 10: a, b, c and d, e, f
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and d, e, f
info: Logger[0]
      Log 40: a, b, c and d, e, f

This is still the same.

Microsoft.Extensions.Logging.Abstractions 8.0.0 on .NET SDK 8.0.303 targeting net8.0

info: Logger[0]
      Log 10: a, b, c and System.String[]
info: Logger[0]
      Log 20: [a, b, c] and [d, e, f]
info: Logger[0]
      Log 30: a, b, c and System.String[]
info: Logger[0]
      Log 40: a, b, c and d, e, f

This shows the regression.
I think it was caused by #80753.

Fixing it might be as simple as replacing && with & in the NET8_0_OR_GREATER variants of the Format<TArg0, TArg1>(TArg0 arg0, TArg1 arg1) and Format<TArg0, TArg1, TArg2>(TArg0 arg0, TArg1 arg1, TArg2 arg2) methods.