What's the best way to have a proper log for chained prompts?

[MithrilMan]

I'm using kernel.InvokePromptAsync , my logs are verbose, i can see token usage and function returns but nothing about the prompt text that's spending the tokens.

My OpenAIPromptExecutionSettings ToolCallBehavior set to ToolCallBehavior.AutoInvokeKernelFunctions
During the execution of my prompt test, I see that 2 different functions (my plugins) are called, but I don't see why (I can't see the inner reasoning)

I tried to implement a IAutoFunctionInvocationFilter but can't find the details I need, there is context.ChatHistory but it doesn't contains the intermediary step I was looking for, is it because automatic functions are solved on the openai server and it just return the next thing to call? So the spent token are the sum of the openai server required to give back the next function to call?

If so, are we forced to "walk blinded" attempting various function description until we see it behave like we expect?

[stephentoub]

The prompts are logged at LogLevel.Trace, as they can contain sensitive information. What level are you logging at?

[MithrilMan]

Hi @stephentoub I'm already logging at Trace level, tomorrow I'm out of office but I'll post back some snippets to explain better my current implementation.

[MithrilMan]

@stephentoub

let me post some code:

A plugin example:

using System.ComponentModel;
using MediatR;
using Microsoft.SemanticKernel;
using WAY4WEB.Shared.Features.Common.AI;

namespace WAY4WEB.Server.Features.Common.AI.Plugins;

public class VehiclePlugin(ILogger<VehicleDistanceCalculator> logger, IMediator mediator)
{
   [KernelFunction]
   [Description("Gets the information for the given vehicle. If you have a DomainEntityId in the form of waydomain-id (e.g. areademo-1231) you can call this function to have more details about the vehicle)")]
   public async Task<ExtendedVehicle?> GetVehicleInformation(
      [FromKernelServices] AIRequestContextManager requestContextManager,
      string vehicleName = null,
      string vehicleId = null)
   {
      logger.LogInformation("Getting information for the vehicle: {VehicleName}", vehicleName);

      var vehicles = (await mediator.Send(new GetVehiclesQuery()).ConfigureAwait(false))
         .Select(v => new
         {
            Name = v.Name,
            Plate = v.Plate,
            Vehicle = v
         });

      var vehicle = vehicles.FirstOrDefault(v =>
         v.Vehicle.Id == vehicleId
         || v.Name.Equals(vehicleName, StringComparison.InvariantCultureIgnoreCase)
         || v.Plate.Equals(vehicleName, StringComparison.InvariantCultureIgnoreCase)
         );

      if (vehicle is null) return null;

      var extendedVehicleInfo = await mediator.Send(new GetExtendedVehicleQuery(vehicle.Vehicle.Id)).ConfigureAwait(false);

      return extendedVehicleInfo;
   }
}

How I register in DI

private static IServiceCollection RegisterSemanticKernel(this IServiceCollection services, IConfiguration configuration)
   {
      const string TEXT_MODEL = "gpt-3.5-turbo-0125";

      services.AddScoped<AIRequestContextManager>();

      services.AddSingleton<IAutoFunctionInvocationFilter, LogAutoFunctionInvocation>();
      //services.AddSingleton<IFunctionInvocationFilter, LogFunctionInvocation>();
      services.AddSingleton<IPromptRenderFilter, LogPromptRender>();

      services.AddKeyedSingleton<IChatCompletionService>(PerformAIActionCommandHandler.SERVICE_ID, (sp, serviceKey)
         => new OpenAIChatCompletionService(
            TEXT_MODEL,
            configuration["OpenAI:ApiKey"],
            loggerFactory: sp.GetRequiredService<ILoggerFactory>()
            ));

      services.AddKeyedTransient<Kernel>(PerformAIActionCommandHandler.SERVICE_ID, (sp, serviceKey) =>
      {
         KernelPluginCollection plugins = new KernelPluginCollection().LoadWayPlugins(sp);

         // load standard plugins
         kernelPlugins.AddFromType<MathPlugin>(serviceProvider: serviceProvider);
         kernelPlugins.AddFromType<TimePlugin>(serviceProvider: serviceProvider);
         kernelPlugins.AddFromType<WaitPlugin>(serviceProvider: serviceProvider);

         // Load custom plugins
         kernelPlugins.AddFromType<GeoLocationPlugin>(serviceProvider: serviceProvider);
         kernelPlugins.AddFromType<VehicleDistanceCalculator>(serviceProvider: serviceProvider);
         kernelPlugins.AddFromType<VehiclePlugin>(serviceProvider: serviceProvider);
         return kernel;
      });


      AppContext.SetSwitch("Microsoft.SemanticKernel.Experimental.EnableModelDiagnosticsWithSensitiveData", true);

      return services;
   }

An attempt to get info with an IAutoFunctionInvocationFilter

private sealed class LogAutoFunctionInvocation(ILogger<LogAutoFunctionInvocation> logger)
      : IAutoFunctionInvocationFilter
   {
      public async Task OnAutoFunctionInvocationAsync(AutoFunctionInvocationContext context, Func<AutoFunctionInvocationContext, Task> next)
      {
         // Example: get function information
         var functionName = context.Function.Name;

         //write the chat history
         logger.LogDebug("Chat history: {ChatHistory}", context.ChatHistory.Select(x => x.ToString()));

         await next(context).ConfigureAwait(false);

         logger.LogDebug("AutoFunction {FunctionName} has been rendered with result {Result}", functionName, context.Result);
      }
   }

I tried to log with `{@ChatHistory}' (we are using Serilog + Seq) but if i recall it gave us json deserialization errors (will try again tomorrow)

TLTR:
logging properly the insight of what's happening is far from straightforward, I think that the sent prompt/history should be easily loggable, maybe with a proper configuration settings like how EntityFrameworkCore do ( EnableSensitiveDataLogging )

What's currently the suggested approach to log prompts properly, inject a custom httpclient and log its request/response data ?

[dmytrostruk]

I tried to log with `{@ChatHistory}' (we are using Serilog + Seq) but if i recall it gave us json deserialization errors (will try again tomorrow)

I tried to log ChatHistory based on your example using console and it works as expected. You can also do just logger.LogDebug("Chat history: {ChatHistory}", context.ChatHistory);, since ChatHistory is serializable.