.NET: execute_tool double escapes gen_ai.tool.call.result

[zakimaksyutov]

Description

execute_tool span double escapes tool output in gen_ai.tool.call.result. Note, gen_ai.tool.call.arguments doesn't have this issue.

{
    "gen_ai.operation.name": "execute_tool",
    "gen_ai.tool.type": "function",
    "gen_ai.tool.call.id": "call_qhSRsKd0mVfzp1QsZUHhxTGo",
    "gen_ai.tool.name": "ExecuteCommand",
    "gen_ai.tool.description": "Execute a command (cmd.exe) in Windows terminal.",
    "gen_ai.tool.call.arguments": "{\r\n  \"command\": \"dir\",\r\n  \"arguments\": \"/b *CmdAgent*\"\r\n}",
    "gen_ai.tool.call.result": "\"OUTPUT:\\r\\nCmdAgent.deps.json\\r\\nCmdAgent.dll\\r\\nCmdAgent.exe\\r\\nCmdAgent.pdb\\r\\nCmdAgent.runtimeconfig.json\\r\\n\\r\\nEXIT CODE: 0\""
}

Example

Agent interaction:

You> list files which have CmdAgent in its name in current folder
About to execute command:
> dir /b *CmdAgent*
Do you want to proceed? (y/yes): y
Executing command...
----------------------
CmdAgent.deps.json
CmdAgent.dll
CmdAgent.exe
CmdAgent.pdb
CmdAgent.runtimeconfig.json
----------------------
Files with "CmdAgent" in their name in the current folder:
- CmdAgent.deps.json
- CmdAgent.dll
- CmdAgent.exe
- CmdAgent.pdb
- CmdAgent.runtimeconfig.json
You>

This resulted in the following trace.

(1) has gen_ai.tool.call.arguments from description above.

(2) has the following content in gen_ai.input.messages:

[
  {
    "role": "user",
    "parts": [
      {
        "type": "text",
        "content": "list files which have CmdAgent in its name in current folder"
      }
    ]
  },
  {
    "role": "assistant",
    "parts": [
      {
        "type": "tool_call",
        "id": "call_qhSRsKd0mVfzp1QsZUHhxTGo",
        "name": "ExecuteCommand",
        "arguments": {
          "command": "dir",
          "arguments": "/b *CmdAgent*"
        }
      }
    ]
  },
  {
    "role": "tool",
    "parts": [
      {
        "type": "tool_call_response",
        "id": "call_qhSRsKd0mVfzp1QsZUHhxTGo",
        "response": "OUTPUT:\r\nCmdAgent.deps.json\r\nCmdAgent.dll\r\nCmdAgent.exe\r\nCmdAgent.pdb\r\nCmdAgent.runtimeconfig.json\r\n\r\nEXIT CODE: 0"
      }
    ]
  }
]

This shows that tool returned non-escaped string. And it logged correctly in LLM span but not in execute_tool span.

Expectation

gen_ai.tool.call.result should have

"gen_ai.tool.call.result": "OUTPUT:\r\nCmdAgent.deps.json\r\nCmdAgent.dll\r\nCmdAgent.exe\r\nCmdAgent.pdb\r\nCmdAgent.runtimeconfig.json\r\n\r\nEXIT CODE: 0"

instead of

"gen_ai.tool.call.result": "\"OUTPUT:\\r\\nCmdAgent.deps.json\\r\\nCmdAgent.dll\\r\\nCmdAgent.exe\\r\\nCmdAgent.pdb\\r\\nCmdAgent.runtimeconfig.json\\r\\n\\r\\nEXIT CODE: 0\""

[stephentoub]

Could you share a minimal repro?

[zakimaksyutov]

Program.cs:

using System.ClientModel;
using System.ComponentModel;
using System.Diagnostics;
using System.Text;

using Azure.AI.OpenAI;
using Azure.Monitor.OpenTelemetry.Exporter;

using Microsoft.Agents.AI;
using Microsoft.Extensions.AI;
using Microsoft.Extensions.Logging;

using OpenTelemetry;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

namespace MicrosoftAgentFrameworkToolDoubleEscapeRepro;

internal class Program
{
    private const string ServiceName = "ToolDoubleEscapedRepro";
    private const string OTelSourceName = "ToolDoubleEscapedRepro.Agent";

    private const string AppInsightsConnectionString =
        "<redacted>";
    private const string AzureOpenAIEndpoint = "<redacted>";
    private const string AzureOpenAIApiKey = "<redacted>";

    private static readonly ActivitySource MainActivitySource = new(name: OTelSourceName);

    public static ILogger<Program> logger = default!;
    private static TracerProvider tracerProvider = default!;
    private static ILoggerFactory loggerFactory = default!;

    private static async Task Main(string[] _)
    {
        ConfigureOpenTelemetry();

        using Activity? conversation = MainActivitySource.StartActivity("root.span", kind: ActivityKind.Server);
        string conversationId = Guid.NewGuid().ToString("n");
        conversation?.SetTag("ai.conversation.id", value: conversationId);

        AIAgent agent = CreateAgent();
        AgentThread thread = agent.GetNewThread();
        AgentRunResponse reply = await agent.RunAsync(message: "Run the ExecuteTool!", thread: thread);
        Console.WriteLine(value: reply);

        loggerFactory.Dispose();
        tracerProvider.Dispose();
    }

    [Description("Execute a command in preparation to user response.")]
    public static Task<string> ExecuteCommand()
    {
        StringBuilder builder = new();
        builder.AppendLine("First line.");
        builder.AppendLine("Second line.");
        return Task.FromResult(builder.ToString());
    }

    private static AIAgent CreateAgent()
    {
        Uri endpoint = new(AzureOpenAIEndpoint);

        ApiKeyCredential credential = new(AzureOpenAIApiKey);

        IChatClient instrumentedChatClient = new AzureOpenAIClient(endpoint: endpoint, credential)
            .GetChatClient("gpt-4.1")
            .AsIChatClient()
            .AsBuilder()
            .UseFunctionInvocation()
            .UseOpenTelemetry(loggerFactory: loggerFactory, sourceName: OTelSourceName, otel =>
            {
                otel.EnableSensitiveData = true;
            })
            .Build();

        AIFunction aiFunction = AIFunctionFactory.Create(ExecuteCommand);

        return new ChatClientAgent(
                chatClient: instrumentedChatClient,
                name: OTelSourceName,
                instructions: "You must call ExecuteCommand first!",
                tools: new List<AITool>([aiFunction]))
            .AsBuilder()
            .UseOpenTelemetry(sourceName: OTelSourceName, cfg => cfg.EnableSensitiveData = true)
            .Build();
    }

    private static void ConfigureOpenTelemetry()
    {
        ResourceBuilder resource = ResourceBuilder.CreateDefault().AddService(serviceName: ServiceName);
        tracerProvider =
            Sdk.CreateTracerProviderBuilder()
                .SetResourceBuilder(resourceBuilder: resource)
                .AddSource(OTelSourceName)
                .AddSource("Microsoft.Agents.AI")
                .AddSource("Microsoft.Extensions.AI")
                .AddSource("*")
                .AddHttpClientInstrumentation()
                .AddAzureMonitorTraceExporter(o =>
                {
                    o.ConnectionString = AppInsightsConnectionString;
                })
                .Build();
        loggerFactory = LoggerFactory.Create(builder =>
        {
            builder.ClearProviders();
            builder.AddOpenTelemetry(options =>
            {
                options.SetResourceBuilder(resourceBuilder: resource);
                options.IncludeFormattedMessage = true;
                options.ParseStateValues = true;
                options.AddAzureMonitorLogExporter(o =>
                {
                    o.ConnectionString = AppInsightsConnectionString;
                }); // uses env var connection string
            });
        });
        logger = loggerFactory.CreateLogger<Program>();
    }
}

csproj:

<Project Sdk="Microsoft.NET.Sdk">

    <PropertyGroup>
        <OutputType>Exe</OutputType>
        <TargetFramework>net8.0</TargetFramework>
        <ImplicitUsings>enable</ImplicitUsings>
        <Nullable>enable</Nullable>
    </PropertyGroup>

    <ItemGroup>
        <PackageReference Include="Azure.AI.OpenAI" Version="2.5.0-beta.1" />
        <PackageReference Include="Azure.Monitor.OpenTelemetry.Exporter" Version="1.4.0" />
        <PackageReference Include="Microsoft.Agents.AI.OpenAI" Version="1.0.0-preview.251105.1" />
        <PackageReference Include="OpenTelemetry.Extensions.Hosting" Version="1.13.1" />
        <PackageReference Include="OpenTelemetry.Instrumentation.Http" Version="1.13.0" />
    </ItemGroup>

</Project>

Agent interaction:

ExecuteCommand completed successfully:
First line.
Second line.

What would you like to do next?

[stephentoub]

The code for tracing the results is just JSON serializing them, so the string being returned from the tool is just being JSON serialized in order to be logged (as would any other returned content). Thus what you see in the Tool output is a JSON string. Why is that a problem?

[zakimaksyutov]

Here is the trace from above repro:

In Fiddler I see that for LLM span (#2) SDK emitted the following gen_ai.input.messages:

"gen_ai.input.messages": "[\r\n {\r\n \u0022role\u0022: \u0022user\u0022,\r\n \u0022parts\u0022: [\r\n {\r\n \u0022type\u0022: \u0022text\u0022,\r\n \u0022content\u0022: \u0022Run the ExecuteTool!\u0022\r\n }\r\n ]\r\n },\r\n {\r\n \u0022role\u0022: \u0022assistant\u0022,\r\n \u0022parts\u0022: [\r\n {\r\n \u0022type\u0022: \u0022tool_call\u0022,\r\n \u0022id\u0022: \u0022call_sQBahQDMCvIllYM2faHKBZNw\u0022,\r\n \u0022name\u0022: \u0022ExecuteCommand\u0022,\r\n \u0022arguments\u0022: {}\r\n }\r\n ]\r\n },\r\n {\r\n \u0022role\u0022: \u0022tool\u0022,\r\n \u0022parts\u0022: [\r\n {\r\n \u0022type\u0022: \u0022tool_call_response\u0022,\r\n \u0022id\u0022: \u0022call_sQBahQDMCvIllYM2faHKBZNw\u0022,\r\n \u0022response\u0022: \u0022First line.\\r\\nSecond line.\\r\\n\u0022\r\n }\r\n ]\r\n }\r\n]"

When I unescape I get this:

"gen_ai.input.messages": "[
  {
    "role": "user",
    "parts": [
      {
        "type": "text",
        "content": "Run the ExecuteTool!"
      }
    ]
  },
  {
    "role": "assistant",
    "parts": [
      {
        "type": "tool_call",
        "id": "call_sQBahQDMCvIllYM2faHKBZNw",
        "name": "ExecuteCommand",
        "arguments": {}
      }
    ]
  },
  {
    "role": "tool",
    "parts": [
      {
        "type": "tool_call_response",
        "id": "call_sQBahQDMCvIllYM2faHKBZNw",
        "response": "First line.\r\nSecond line.\r\n"
      }
    ]
  }
]"

And response part is escaped once - which is expected. When I unescape then get expected (what the tool produced):

First line.
Second line.

Now, Fiddler captured the following for Tool span (#1):

"gen_ai.tool.call.result": "\u0022First line.\\r\\nSecond line.\\r\\n\u0022"

So, the value of tool result becomes

"First line.\r\nSecond line.\r\n"

So, when one deserializes tool result - it is not the tool result, but still serialized tool result.

PS: Maybe I'm missing something with all these deserializations...