9

I'm using Serilog 2.10.0 for logging in an ASP.NET Core Application on .NET 5. I'm running into a problem when trying to log an event where there is only one parameter and this parameter is an array. The following is some example code and the log output with a JSON file sink:

var myArray = new string[] { "foo", "bar" };
logger.LogInformation("Log stuff: {@MyArray}", myArray);

{"@t":"2021-02-22T14:09:46.8673482Z","@mt":"Log stuff: {@MyArray}","MyArray":"foo","SourceContext":"MyNamespace.MyClass"}

The logger is an ILogger injected via dependency injection. The logged event only contains the first element of my string array. If I add another parameter the string array is correctly logged. I tried this with and without the @ and also with a different sink.

This is a modified example with an additional parameter, and this works as I would expect:

var myArray = new string[] { "foo", "bar" };
logger.LogInformation("Log stuff: {baz} {@MyArray}", "baz", myArray);

{"@t":"2021-02-22T14:19:21.3580354Z","@mt":"Log stuff: {baz} {@MyArray}","baz":"baz","MyArray":["foo","bar"],"SourceContext":"MyNamespace.MyClass"}

I suspect I'm misunderstanding something here about how the variadic function determines the mapping between parameters and variables in the template string. But I couldn't figure out a way to get this to work properly without adding irrelevant additional parameters.

How do I get Serilog to properly handle a log message with a single array as a parameter?

Ruben Bartelink
  • 59,778
  • 26
  • 187
  • 249
Fabian
  • 439
  • 3
  • 9
  • Not sure if the same problem exists with `Serilog.Log.Information` ? If you were working direct againt that, I suspect it would be flagged by https://github.com/Suchiman/SerilogAnalyzer – Ruben Bartelink Feb 22 '21 at 18:03
  • @RubenBartelink: I believe best practive now is to inject `ILogger`, but I've also experienced projects with dependency to Serilog all over the code. BR – Roar S. Feb 22 '21 at 18:11
  • 2
    Serilog's logger tries to avoid this - https://github.com/serilog/serilog/blob/dev/src/Serilog/Core/Logger.cs#L366 - but the situation can't be detected when events are passed through from MEL. – Nicholas Blumhardt Feb 23 '21 at 02:57

3 Answers3

16

I was able to reproduce your issue. Issue was flagged by Resharper as shown in the screenshot below.

enter image description here

If we enter the source for LoggerExtensions#LogInformation, it has the following signature:

public static void LogInformation(this ILogger logger, string message, params object[] args)

The last parameter is params object[] args, and when passing in a single array, this method believes the array is a list of parameters and casts the array to object[], while your intention was to pass in the array as a parameter. This is confirmed by changing the template like this:

_logger.LogInformation("Log stuff: {FirstElement} {SecondElement}", myArray);

which will output Log stuff: foo bar. The above code has the same logic and behaviour as this:

_logger.LogInformation("Log stuff: {FirstElement} {SecondElement}", "foo", "bar");

Changing the array to e.g. a list or, as @IharYakimush suggests, simply cast array to object, does the trick because the collection will now be treated as a parameter, not a list of parameters.

_logger.LogInformation("Log stuff: {MyArray}", (object)myArray);
Roar S.
  • 8,103
  • 1
  • 15
  • 37
2

The destructuring operator @ that you are using is probably the cause of the issue. According to Serilog docs, https://github.com/serilog/serilog/wiki/Structured-Data#collections, this should work out of the box:

var fruit = new[] { "Apple", "Pear", "Orange" };
Log.Information("In my bowl I have {Fruit}", fruit);

This would produce following JSON:

{ "Fruit": ["Apple", "Pear", "Orange"] }

So, no casting to object is necessary!

lef
  • 43
  • 4
  • Live testing with code shows that this advice is incorrect, the @ operator is not the source of the problem. The collections code example in the documentation does not work as expected. Using an (object) cast as described in the accepted answer resolved the problem. The wiki documentation linked to above has not been edited since May 2017, it has probably drifted out of sync with current behavior with structured logging of collection data. – camelCase Sep 01 '23 at 11:01
1

Perhaps you could change you log statement to something like

logger.LogInformation("Log stuff: {baz} {myArrayString}", "baz",  String.Join(", ", myArray));
GlennSills
  • 3,977
  • 26
  • 28