How does MS default ILogger (Microsoft.Extensions.Logging.Logger) interpret args?

906 views Asked by At

It is a bit confusing to me how args is interpreted by the lib.

According to the official site (https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-6.0&viewFallbackFrom=aspnetcore-2.2#log-message-template),

It is "The order of the parameters, not their placeholder names, determines which parameters are used to provide placeholder values in log messages."

So, in the following 3 cases, I understand that they all provide the same log message

string message1 = "Messsage1";
string message2 = "Messsage2";
string message3 = "Messsage3";
logger.LogInformation("Testing args: {0}, {1}, {2}", message1, message2, message3);
// Message 1 -> 2 -> 3
logger.LogInformation("Testing args: {Message1}, {Message2}, {Message3}", message1, message2, message3);
// Message 2 -> 1 -> 3
logger.LogInformation("Testing args: {Message2}, {Message1}, {Message3}", message1, message2, message3);

All produce the same log message "Testing args: Messsage1, Messsage2, Messsage3".

Till now, it is still ok.

But when I try something like below,

// 1st case: Nothing shown
logger.LogInformation("Testing args: {Message1}, {Message2}, {Message3}, {Message2}", message1, message2, message3);
// 2nd case: Prints "Messsage1, Messsage1, Messsage3, Messsage1"
logger.LogInformation("Testing args: {Message1}, {Message2}, {Message3}, {Message2}", message1, message2, message3, message1);

The 1st and 2nd cases seems to contradict with each other.

1st case tells me that the placeholder name {MessageX} does not matter, the parameters are just assigned to the placeholders in the order of the parameters. So, in the 1st case, it prints nothing because there are 4 placeholders but only 3 parameters and the functions does not know how to print the log message.

But 2nd case tells me that the placeholder name does matter because the 4th parameter message1 replaces the original value message2 assigned to the placeholder {Message2}. If it is using a name-value pair for a placeholdername-parametervalue pair, why in 1st case, it cannot print "Testing args: Messsage1, Messsage2, Messsage3, Messsage2"?

1

There are 1 answers

4
Slack Groverglow On

The LogInformation method requires that that number of placeholders = number of parameters. It will throw if not and it will trigger CA2017 at compilation. The reason you are seeing nothing is because the call fails. As such, case 1 does not give meaningful insight into how the function should work.

With that out of the way, I think you're wondering for case 2 Why do I need to put message1 as a parameter twice like so

logger.LogInformation("Testing args: {Message1}, {Message2}, {Message3}, {Message2}", message1, message2, message3, message1);

The explanation here is that the string with placeholders being passed is not a string interpolation but instead the placeholders are used by the logger in order to store the message such that it is taking advantage of structured logging. This is a fancy way of allow you to later query logs based on these placeholders. Ultimately this means that the strings inside your placeholder have no relation to your parameters and are only useful later when you want to query logs.