Application Insights Logger Scope overwritting OriginalFormat property

[YanBrunet]

Context

Using .Net 8 Isolated process and the issue can also be reproduced in debug mode and outside of a function app as mentionned here : https://github.com/Azure/azure-functions-host/issues/9827#issuecomment-1907918105

Packages : Microsoft.Azure.Functions.Worker.ApplicationInsights ( 1.1.0 )

• Microsoft.ApplicationInsights.PerfCounterCollector ( 2.22.0 )
  • Microsoft.ApplicationInsights ( 2.22.0 )

Irrelevant packages excluded.

Problem description

When creating a scope using a formatted string, the arguments are added to the custom properties but the message overwrites the OriginalFormat of all subsequent messages logged within that scope.

The Scope property is not set with the provided value.

public class MyClass(ILogger<MyClass> Logger)
{
    [Function("TestLogs")]
    public IActionResult TestLogs(
[HttpTrigger(AuthorizationLevel.Function, "post", Route = "test-logs")]
        HttpRequest req,
CancellationToken token = default)
    {
        string processName = "MyProcessName";
        Guid id = Guid.NewGuid();

        KeyValuePair<string, object>[] scopeValues = [
            new ("Id", id ),
            new( "Process", processName),
        ];
        using (var scope = Logger.BeginScope(scopeValues))
        {
            Logger.LogInformation("My log {SomeValue}", "ScopeKeys only.");
        }

        using (var scope2 = Logger.BeginScope("Executing {Process} : {Id}", processName, id ))
        {
            Logger.LogInformation("My log {SomeValue}", "Scope with formatted text.");
        }

        using (var scope3 = Logger.BeginScope($"Executing {processName} : {id}"))
        {
            Logger.LogInformation("My log {SomeValue}", "Scope with text only.");
        }

        return new OkResult();
    }
}

The first log entry will work as expected, adding the keys to the custom properties.

{
  "data": {
    "baseType": "MessageData",
    "baseData": {
      "ver": 2,
      "message": "My log ScopeKeys only.",
      "severityLevel": "Information",
      "properties": {
        "Id": "65b6e9e1-ec41-4b27-bf5c-cd7dac8e95c7",
        "InvocationId": "372d62af-e449-4e48-bce3-35d0b8dfde7f",
        "AzureFunctions_FunctionName": "TestLogs",
        "DeveloperMode": "true",
        "Process": "MyProcessName",
        "AzureFunctions_InvocationId": "372d62af-e449-4e48-bce3-35d0b8dfde7f",
        "SomeValue": "ScopeKeys only.",
        "OriginalFormat": "My log {SomeValue}",
        "CategoryName": "MyClass"
      }
    }
  }
}

The second log entry will also add the keys to the custom properties, but the OriginalFormat property will be overwritten by the formatted string provided as the scope value.

The Scope property is not created.

{
  "data": {
    "baseType": "MessageData",
    "baseData": {
      "ver": 2,
      "message": "My log Scope with formatted text.",
      "severityLevel": "Information",
      "properties": {
        "Id": "65b6e9e1-ec41-4b27-bf5c-cd7dac8e95c7",
        "InvocationId": "372d62af-e449-4e48-bce3-35d0b8dfde7f",
        "AzureFunctions_FunctionName": "TestLogs",
        "DeveloperMode": "true",
        "Process": "MyProcessName",
        "AzureFunctions_InvocationId": "372d62af-e449-4e48-bce3-35d0b8dfde7f",
        "SomeValue": "Scope with formatted text.",
        "OriginalFormat": "Executing {Process} : {Id}",
        "CategoryName": "MyClass"
      }
    }
  }
}

The last one shows the result of creating a scope using text only instead of structured. OriginalFormat contains the string provided within the LogInformation as expected. The Scope property is created as expected.

The values are not added to the custom properties.

{
  "data": {
    "baseType": "MessageData",
    "baseData": {
      "ver": 2,
      "message": "My log Scope with text only.",
      "severityLevel": "Information",
      "properties": {
        "InvocationId": "0dabaee1-647e-4392-91ad-258848afced2",
        "AzureFunctions_FunctionName": "TestLogs",
        "DeveloperMode": "true",
        "Scope": "=> Executing MyProcessName : 5f7e1011-027b-40b7-a050-a1f50e406d69",
        "AzureFunctions_InvocationId": "0dabaee1-647e-4392-91ad-258848afced2",
        "SomeValue": "Scope with text only.",
        "OriginalFormat": "My log {SomeValue}",
        "CategoryName": "MyClass"
      }
    }
  }
}

I would expect the OriginalFormat to have the same value in all cases: My log {SomeValue}

I would also expect the structured text scope to create a Scope property containing the formatted text and adding the args to the custom properties.

Expected result when using the instruction : Logger.BeginScope("Executing {Process} : {Id}", processName, id )

{
  "data": {
    "baseType": "MessageData",
    "baseData": {
      "ver": 2,
      "message": "My log Scope with formatted text.",
      "severityLevel": "Information",
      "properties": {
        "Id": "65b6e9e1-ec41-4b27-bf5c-cd7dac8e95c7",
        "InvocationId": "372d62af-e449-4e48-bce3-35d0b8dfde7f",
        "AzureFunctions_FunctionName": "TestLogs",
        "DeveloperMode": "true",
        "Process": "MyProcessName",
        "AzureFunctions_FunctionName": "TestLogs",
        "DeveloperMode": "true",
        "Scope": "=> Executing MyProcessName : 5f7e1011-027b-40b7-a050-a1f50e406d69",
        "AzureFunctions_InvocationId": "0dabaee1-647e-4392-91ad-258848afced2",
        "SomeValue": "Scope with formatted text.",
        "OriginalFormat": "My log {SomeValue}",
        "CategoryName": "MyClass"
      }
    }
  }
}

[cijothomas]

using (var scope2 = Logger.BeginScope("Executing {Process} : {Id}", processName, id ))

^ do not use this for Scopes. Instead pass in KVP yourself like below:

        KeyValuePair<string, object>[] scopeValues = [
            new ("Id", id ),
            new( "Process", processName),
        ];
        using (var scope = Logger.BeginScope(scopeValues))
        {

There are no fixes planned for scopes in this repo - please follow the above suggestion. (Even when you move to openTelemetry, still the above recommendation should be followed.)

[YanBrunet]

Thank you for taking the time to answer. Although, I wasn't satisfied because I see this issue as a breach of the Liskov Substitution Principle.

Hence, I jumped in the code to find where the issue was originating from.

BeginScope(ILogger, String, Object[]) is an extension from the runtime, and therefore, outside of the scope of this repos.

The main concern that prompted me to open this issue, is the fact that the value {OriginalMessage} is overwritten by whatever is contained in the scope.

I could track down the issue to : source code

The scope values are only added after the state value passed in the Log<TState>() method. In this case, since the scope used a FormattedLogValues, it also includes a key {OriginalFormat}, which overwrites the one previously created.

To solve the main issue, editing the condition at line 202 of the file as such :

if (item.Key == "{OriginalFormat}")
{
    if (!dict.ContainsKey("OriginalFormat")) 
        dict["OriginalFormat"] = Convert.ToString(item.Value, CultureInfo.InvariantCulture);
}

To solve the secondary issue, but this could have unforseen consequences, knowing that there is an OriginalFormat key, it could be assumed that the activeScope uses some kind of formater and just add it to the builder.

if (item.Key == "{OriginalFormat}")
{
    if (!dict.ContainsKey("OriginalFormat")) 
        dict["OriginalFormat"] = Convert.ToString(item.Value, CultureInfo.InvariantCulture);

    builder.Append(" => ").Append(activeScope);
}

[cijothomas]

which overwrites the one previously created.

That is true. There kvpairs in the TraceTelemetry cannot accept duplicates. So if there are more than one OriginalFormat key, only one can remain. This would be the case when you has nested scopes as well.

This issue (https://github.com/microsoft/ApplicationInsights-dotnet/issues/2241) shows other possible cases where the information is lost, along with some ideas to fix. But like I said, there won't be any such fixes in this repos, due to the long term strategy of only using OpenTelemetry exclusively.

And I don't see OTel solving it either, it'll remain user responsibility to not use loggermessage templates in scope, but use only list/ienumeralbe/dic in scopes, or potentially move away from scopes to some other enrichment mechanism.