Semantic Kernel: Using Logging to Examine Planners and Support Debugging
Note: This post covers Semantic Kernel, which I’ve since moved on from. My new work is built on Microsoft Agent Framework. If you’re starting fresh, I’d recommend the Microsoft Agent Framework: The Complete Series instead, or see the section What Does It Mean For Your Current Semantic Kernel project in this blog.
Adding logging to an application is crucial for monitoring and debugging. In addition to tracking issues and performing diagnostics, within the context of Semantic Kernel, logging can help provide insights into the planner’s decision-making process.
This can let you know how the AI model and planner arrived at a particular decision-making outcome or which processes were executed to handle a user prompt.
This can give you an extra level of transparency, thereby ensuring the reliability and performance of your Semantic Kernel and AI model integration.
In this blog post, we will see how to add logging to a Semantic Kernel and OpenAI integration.
We will also see:
- what logging verbosity is available
- examples of logging outputs
- the planner component of Semantic Kernel in action
Example code and console outputs are included. A video demo is also available.
~
Booking Plugin
To recap, we are working with a customer service agent that can handle bookings and complaints. Before continuing, if will help useful if you read some of those earlier blogs first.
To recap, the BookingPlugin is designed to manage appointment bookings, cancellations, and to provide information about available booking dates.
An overview of the functionality:
- Available Dates: Maintains a list of dates available for booking, initially set to the next nine days.
- Booked Dates: Keeps track of dates that have been booked.
- Get Next Available Date: Provides the next available booking date starting from a specified date.
- Book Appointment: Allows users to book an appointment for a specified date if it is available. The date is then moved from the available list to the booked list, and a confirmation message is returned.
- Cancel Appointment: Allows users to cancel a previously booked appointment. The date is moved from the booked list back to the available list, and a confirmation message is returned.
The plugin consists of the following code:
public sealed class BookingPlugin
{
// a list of available dates the user can book
private List<DateTime> _available = new List<DateTime>
{
// add dates for the next 9 days, ignore the time part
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 1,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 2,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 3,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 4,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 5,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 6,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 7,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 8,0,0,0),
new DateTime(DateTime.Now.Year, DateTime.Now.Month, DateTime.Now.Day + 9,0,0,0),
};
// a list of booked dates
private List<DateTime> _booked = new List<DateTime>();
[KernelFunction, Description("Determines the next available date for a booking")]
public DateTime GetNextAvailableDate([Description("The date to start searching from")] DateTime startDate)
{
// get the next available date
return _available.FirstOrDefault(d => d > startDate);
}
[KernelFunction, Description("Allows the user to make a booking.")]
public string BookAppointment([Description("The date of the appointment")] DateTime date)
{
// check if the date is available, ignore the time part
date = date.Date;
if (_available.Contains(date))
{
// remove the date from the available list
_available.Remove(date);
// add the date to the booked list
_booked.Add(date);
// return a confirmation message
return $"Appointment booked for {date.ToShortDateString()}";
}
else
{
// return an error message
return "The selected date is not available";
}
}
[KernelFunction, Description("Cancels a booking.")]
public string CancelAppointment([Description("The date of the appointment to cancel")] DateTime date)
{
// check if the date is booked
if (_booked.Contains(date))
{
// remove the date from the booked list
_booked.Remove(date);
// add the date back to the available list
_available.Add(date);
// return a confirmation message
return $"Appointment on {date.ToShortDateString()} cancelled";
}
else
{
// return an error message
return "The selected date is not booked";
}
}
}
The variable _available is used to stored available dates for booking.
~
Setting Up Logging
To add logging, you need to add the following code:
// add logging builder.Services.AddLogging(configure => configure.AddConsole()); builder.Services.AddLogging(configure => configure.SetMinimumLevel(LogLevel.Information));
The enum LogLevel lets you select from the following values:
- Information
- Debug
- Warning
- Error
- Trace
Further details of each setting and examples follow in a subsequent section.
~
Agent Code
Here, we can see where logging is configured and setup for the customer service agent:
static async Task Main(string[] args)
{
Console.WriteLine("Launching Semantic Kernel Sandpit");
var builder = Kernel.CreateBuilder()
.AddOpenAIChatCompletion(modelId, apiKey);
builder.Plugins.AddFromType<BookingPlugin>();
// add logging
builder.Services.AddLogging(configure => configure.AddConsole());
builder.Services.AddLogging(configure => configure.SetMinimumLevel(LogLevel.Information));
Kernel kernel = builder.Build();
// Enable planning / automatic function calling
OpenAIPromptExecutionSettings openAIPromptExecutionSettings = new()
{
ToolCallBehavior = ToolCallBehavior.AutoInvokeKernelFunctions,
};
// Create chat history and system prompt
var history = new ChatHistory("You are professional customer service agent.");
// Get chat completion service
var chatCompletionService = kernel.GetRequiredService<IChatCompletionService>();
// Start the conversation
Console.Write("User > ");
string? userInput;
while ((userInput = Console.ReadLine()) != null)
{
// Add user input
history.AddUserMessage(userInput);
// Get the response from the AI
var result = await chatCompletionService.GetChatMessageContentAsync(history,executionSettings: openAIPromptExecutionSettings, kernel: kernel);
// Print the results
Console.WriteLine("Assistant > " + result);
// Add the message from the agent to the chat history
history.AddAssistantMessage(result.Content ?? string.Empty);
// Get user input again
Console.Write("User > ");
}
}
~
Examples and Output
Examples for each of the enum logging options now follow. For context, the human is supplying the prompt i would like to make a booking in each.
They are looking to make a booking for next monday.
Any system logging messages are output in the console.
Information
This is the default setting. It provides information about general flow of the application.
Information level logging can contains following :
- AI model / endpoint used to create a plan
- Plan creation status (Success/Failed)
- Plan creation execution time (in seconds)
- Created plan without function arguments
- AI model used to execute a function
- Function execution status (Success/Failed)
- Function execution time (in seconds)
Launching Semantic Kernel Sandpit User > i would like to make a booking info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 222. Completion tokens: 20. Total tokens: 242. Assistant > Sure, I can assist with that. Can you please supply a preferred date for the booking? User > next monday info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 251. Completion tokens: 26. Total tokens: 277. info: GetNextAvailableDate[0] Function GetNextAvailableDate invoking. info: GetNextAvailableDate[0] Function GetNextAvailableDate succeeded. info: GetNextAvailableDate[0] Function completed. Duration: 0.003814s info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 304. Completion tokens: 38. Total tokens: 342. Assistant > I am sorry but the date you have chosen is already fully booked. The next available date is on 15th July 2024. Would you like to book on this date? User > yes please info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 351. Completion tokens: 30. Total tokens: 381. info: BookAppointment[0] Function BookAppointment invoking. info: BookAppointment[0] Function BookAppointment succeeded. info: BookAppointment[0] Function completed. Duration: 0.006477s info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 402. Completion tokens: 32. Total tokens: 434. Assistant > Great, your appointment has been booked for the 15th of July, 2024. If you need any further assistance, feel free to ask. User >
~
Debug
Debug level logging contains more detailed messages. No sensitive data is emitted. Suitable for production environments.
Launching Semantic Kernel Sandpit User > i would like to make a booking info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 142. Completion tokens: 26. Total tokens: 168. dbug: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Tool requests: 1 info: GetNextAvailableDate[0] Function GetNextAvailableDate invoking. info: GetNextAvailableDate[0] Function GetNextAvailableDate succeeded. info: GetNextAvailableDate[0] Function completed. Duration: 0.0041668s info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 195. Completion tokens: 27. Total tokens: 222. Assistant > The next available date for a booking is on July 15, 2024. Would you like to proceed with this date? User > next monday info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 231. Completion tokens: 26. Total tokens: 257. dbug: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Tool requests: 1 info: GetNextAvailableDate[0] Function GetNextAvailableDate invoking. info: GetNextAvailableDate[0] Function GetNextAvailableDate succeeded. info: GetNextAvailableDate[0] Function completed. Duration: 0.000388s info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 284. Completion tokens: 33. Total tokens: 317. Assistant > I'm sorry for the confusion. The next available date after next Monday is on July 17, 2024. Would you like to book this date? User > yes info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 325. Completion tokens: 30. Total tokens: 355. dbug: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Tool requests: 1 info: BookAppointment[0] Function BookAppointment invoking. info: BookAppointment[0] Function BookAppointment succeeded. info: BookAppointment[0] Function completed. Duration: 0.0087355s info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0] Prompt tokens: 376. Completion tokens: 29. Total tokens: 405. Assistant > Great! Your appointment has been booked for July 17, 2024. If you need any more assistance, feel free to ask.
~
Warning
This can include information about unusual events that don’t cause the application to fail.
Launching Semantic Kernel Sandpit User > i would like to make a booking Assistant > Sure, I can help you with that. Could you please specify the date you'd like to make a booking for? User > next monday Assistant > I'm sorry for the inconvenience, it appears that the next available booking date is not until July 15, 2024. Would you like to book an appointment for this date? User > yes Assistant > Great, your booking has been confirmed for July 15, 2024. If you need to change or cancel your booking, please feel free to contact us. User >
~
Error
This is useful for logging exception details. Notice how that whilst there is an exception, the agent is able to recover. The kernel and LLM has provided guidance and asked the human to confirm if the identified data is suitable.
You can also see where the planner failed (GetNextAvailableDate).
You could use this insight to further refine the logic in the Native Function.
Launching Semantic Kernel Sandpit User > i would like to make a booking Assistant > Sure, I can assist you with that. May I know from which date you want to start looking for available slots? User > next monday fail: GetNextAvailableDate[0] Function failed. Error: next Monday is not a valid value for DateTime. (Parameter 'startDate') Actual value was next Monday. System.ArgumentOutOfRangeException: next Monday is not a valid value for DateTime. (Parameter 'startDate') Actual value was next Monday. at Microsoft.SemanticKernel.KernelFunctionFromMethod.<>c__DisplayClass13_0.<GetParameterMarshalerDelegate>g__Process|10(Object value, <>c__DisplayClass13_1&) at Microsoft.SemanticKernel.KernelFunctionFromMethod.<>c__DisplayClass13_0.<GetParameterMarshalerDelegate>g__parameterFunc|9(KernelFunction _, Kernel kernel, KernelArguments arguments, CancellationToken __) at Microsoft.SemanticKernel.KernelFunctionFromMethod.<>c__DisplayClass11_0.<GetMethodDetails>g__Function|0(Kernel kernel, KernelFunction function, KernelArguments arguments, CancellationToken cancellationToken) at Microsoft.SemanticKernel.KernelFunctionFromMethod.InvokeCoreAsync(Kernel kernel, KernelArguments arguments, CancellationToken cancellationToken) at Microsoft.SemanticKernel.KernelFunction.<>c__DisplayClass21_0.<<InvokeAsync>b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.SemanticKernel.Kernel.InvokeFilterOrFunctionAsync(NonNullCollection`1 functionFilters, Func`2 functionCallback, FunctionInvocationContext context, Int32 index) at Microsoft.SemanticKernel.Kernel.OnFunctionInvocationAsync(KernelFunction function, KernelArguments arguments, FunctionResult functionResult, Func`2 functionCallback, CancellationToken cancellationToken) at Microsoft.SemanticKernel.KernelFunction.InvokeAsync(Kernel kernel, KernelArguments arguments, CancellationToken cancellationToken) Assistant > I apologize for the misunderstanding. Could you kindly specify the date for next Monday? For example, if today is the 1st of the month, and next Monday falls on the 7th, then you would specify "7th of the month". Thank you. User > 7th of Month Assistant > The next available booking slot is on July 15th, 2023. Would you like to book this date? User >
~
Trace
This contains many insights. It can contain sensitive data. Do not use this in production.
This setting is helpful for monitoring how your Semantic Kernel integration is behaving when coding or testing.
You can see how the planner decides which native functions to invoke to satisfy a user request, prompt variables and arguments etc.
The chat history is also included. Highly useful. You can persist these insights to see how or if your agent drifts from a topic. Use this data to help you implement new native functions, processes, and adjust your agentic AI solution.
Launching Semantic Kernel Sandpit
trce: _5_SemanticKernel.Logging.Plugins.Bookings.BookingPlugin[0]
Created KernelFunction 'GetNextAvailableDate' for 'GetNextAvailableDate'
trce: _5_SemanticKernel.Logging.Plugins.Bookings.BookingPlugin[0]
Created KernelFunction 'BookAppointment' for 'BookAppointment'
trce: _5_SemanticKernel.Logging.Plugins.Bookings.BookingPlugin[0]
Created KernelFunction 'CancelAppointment' for 'CancelAppointment'
trce: _5_SemanticKernel.Logging.Plugins.Bookings.BookingPlugin[0]
Created plugin BookingPlugin with 3 [KernelFunction] methods out of 9 methods found.
User > i would like to make a booking
trce: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
ChatHistory: [{"Role":{"Label":"system"},"Items":[{"$type":"TextContent","Text":"You are professional customer service agent."}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"i would like to make a booking"}]}], Settings: {"temperature":1,"top_p":1,"presence_penalty":0,"frequency_penalty":0,"max_tokens":null,"stop_sequences":null,"results_per_prompt":1,"seed":null,"response_format":null,"chat_system_prompt":null,"token_selection_biases":null,"ToolCallBehavior":{"ToolCallResultSerializerOptions":null},"User":null,"logprobs":null,"top_logprobs":null,"service_id":null,"model_id":null}
info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Prompt tokens: 142. Completion tokens: 26. Total tokens: 168.
Assistant > Absolutely, I can assist with that. Could you please provide me with a date you would like to make the booking for?
User > next monday
trce: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
ChatHistory: [{"Role":{"Label":"system"},"Items":[{"$type":"TextContent","Text":"You are professional customer service agent."}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"i would like to make a booking"}]},{"Role":{"Label":"assistant"},"Items":[{"$type":"TextContent","Text":"Absolutely, I can assist with that. Could you please provide me with a date you would like to make the booking for?"}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"next monday"}]}], Settings: {"temperature":1,"top_p":1,"presence_penalty":0,"frequency_penalty":0,"max_tokens":null,"stop_sequences":null,"results_per_prompt":1,"seed":null,"response_format":null,"chat_system_prompt":null,"token_selection_biases":null,"ToolCallBehavior":{"ToolCallResultSerializerOptions":null},"User":null,"logprobs":null,"top_logprobs":null,"service_id":null,"model_id":null}
info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Prompt tokens: 177. Completion tokens: 26. Total tokens: 203.
dbug: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Tool requests: 1
trce: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Function call requests: BookingPlugin-GetNextAvailableDate({
"startDate": "2022-02-07"
})
info: GetNextAvailableDate[0]
Function GetNextAvailableDate invoking.
trce: GetNextAvailableDate[0]
Function arguments: {"startDate":"2022-02-07"}
info: GetNextAvailableDate[0]
Function GetNextAvailableDate succeeded.
trce: GetNextAvailableDate[0]
Function result: "2024-07-15T00:00:00"
info: GetNextAvailableDate[0]
Function completed. Duration: 0.0073157s
info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Prompt tokens: 230. Completion tokens: 36. Total tokens: 266.
Assistant > I apologize for the inconvenience, but it seems the next available date is actually Monday, July 15th, 2024. Would you like to book for this date?
User > yes
trce: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
ChatHistory: [{"Role":{"Label":"system"},"Items":[{"$type":"TextContent","Text":"You are professional customer service agent."}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"i would like to make a booking"}]},{"Role":{"Label":"assistant"},"Items":[{"$type":"TextContent","Text":"Absolutely, I can assist with that. Could you please provide me with a date you would like to make the booking for?"}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"next monday"}]},{"Role":{"Label":"assistant"},"Items":[{"$type":"FunctionCallContent","Id":"call_tMFixWwGOwgf89hMnZ2oxlq2","PluginName":"BookingPlugin","FunctionName":"GetNextAvailableDate","Arguments":{"startDate":"2022-02-07"}}],"ModelId":"gpt-4","Metadata":{"Id":"chatcmpl-9kyUkOojUW2oxTvYNyOLipx20aBVv","Created":"2024-07-14T18:44:18+00:00","PromptFilterResults":[],"SystemFingerprint":null,"Usage":{"CompletionTokens":26,"PromptTokens":177,"TotalTokens":203},"ContentFilterResults":null,"FinishReason":"tool_calls","FinishDetails":null,"LogProbabilityInfo":null,"Index":0,"Enhancements":null,"ChatResponseMessage.FunctionToolCalls":[{"Name":"BookingPlugin-GetNextAvailableDate","Arguments":"{\n \u0022startDate\u0022: \u00222022-02-07\u0022\n}","Id":"call_tMFixWwGOwgf89hMnZ2oxlq2"}]}},{"Role":{"Label":"tool"},"Items":[{"$type":"TextContent","Text":"\u00222024-07-15T00:00:00\u0022","Metadata":{"ChatCompletionsToolCall.Id":"call_tMFixWwGOwgf89hMnZ2oxlq2"}},{"$type":"FunctionResultContent","CallId":"call_tMFixWwGOwgf89hMnZ2oxlq2","PluginName":"BookingPlugin","FunctionName":"GetNextAvailableDate","Result":"\u00222024-07-15T00:00:00\u0022"}],"Metadata":{"ChatCompletionsToolCall.Id":"call_tMFixWwGOwgf89hMnZ2oxlq2"}},{"Role":{"Label":"assistant"},"Items":[{"$type":"TextContent","Text":"I apologize for the inconvenience, but it seems the next available date is actually Monday, July 15th, 2024. Would you like to book for this date?"}]},{"Role":{"Label":"user"},"Items":[{"$type":"TextContent","Text":"yes"}]}], Settings: {"temperature":1,"top_p":1,"presence_penalty":0,"frequency_penalty":0,"max_tokens":null,"stop_sequences":null,"results_per_prompt":1,"seed":null,"response_format":null,"chat_system_prompt":null,"token_selection_biases":null,"ToolCallBehavior":{"ToolCallResultSerializerOptions":null},"User":null,"logprobs":null,"top_logprobs":null,"service_id":null,"model_id":null}
info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Prompt tokens: 274. Completion tokens: 30. Total tokens: 304.
dbug: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Tool requests: 1
trce: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Function call requests: BookingPlugin-BookAppointment({
"date": "2024-07-15T00:00:00"
})
info: BookAppointment[0]
Function BookAppointment invoking.
trce: BookAppointment[0]
Function arguments: {"date":"2024-07-15T00:00:00"}
info: BookAppointment[0]
Function BookAppointment succeeded.
trce: BookAppointment[0]
Function result: Appointment booked for 15/07/2024
info: BookAppointment[0]
Function completed. Duration: 0.00851s
info: Microsoft.SemanticKernel.Connectors.OpenAI.OpenAIChatCompletionService[0]
Prompt tokens: 325. Completion tokens: 34. Total tokens: 359.
Assistant > Great, your appointment has been booked for Monday, July 15th, 2024. Let me know if there's anything else I can assist you with.
User >
~
Video Demo
In this demo, you will see logging in action. You will see different types of information being surface. You will also see how to use logging to debug.
~
Summary
In this post we’ve seen how to implement logging with Semantic Kernel. We’ve seen what gets output to the console using the various levels that are available.
Use these feature to help you diagnose issues with Planners, evaluate Native Function performance or to debug your LLM and Semantic Kernel integration.
~
Further Reading
You can learn more about Semantic Kernel, Planners, and Function Calling here:
- Semantic Kernel – Semantic Kernel documentation
- Plugins and Native Functions – Provide native code to your agents
- Planners – What are Planners in Semantic Kernel
- Function Calling – Function calling – OpenAI API
- Tool Call Behaviour – ToolCallBehavior.AutoInvokeKernelFunctions
- Telemetry – Telemetry
Enjoy what you’ve read, have questions about this content, or would like to see another topic? Drop me a note below.
You can schedule a call using my Calendly link to discuss consulting and development services.
Hey Jamie, great content. Just a quick tip for those wishing to follow along.
You may need to add the following dependencies; Microsoft.Extensions.Logging, Microsoft.Extensions.Logging.Debug, and Microsoft.Extensions.Logging.Console.