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

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[bot]]

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.