From 7831ae08663c3b252052e4761a084756bd16ba9b Mon Sep 17 00:00:00 2001 From: Dongbo Wang Date: Mon, 21 Oct 2024 16:37:24 -0700 Subject: [PATCH 1/2] Add basic logging for error cases in the Azure agent --- .../agents/Microsoft.Azure.Agent/AzureAgent.cs | 18 +++++++++++++++++- .../AzureCopilotReceiver.cs | 8 +++++--- .../Microsoft.Azure.Agent/ChatSession.cs | 4 ++-- .../Microsoft.Azure.Agent/DataRetriever.cs | 6 +++++- .../Microsoft.Azure.Agent.csproj | 2 ++ 5 files changed, 31 insertions(+), 7 deletions(-) diff --git a/shell/agents/Microsoft.Azure.Agent/AzureAgent.cs b/shell/agents/Microsoft.Azure.Agent/AzureAgent.cs index 22ed2f34..e1049483 100644 --- a/shell/agents/Microsoft.Azure.Agent/AzureAgent.cs +++ b/shell/agents/Microsoft.Azure.Agent/AzureAgent.cs @@ -1,6 +1,8 @@ using System.Diagnostics; using System.Text; + using AIShell.Abstraction; +using Serilog; namespace Microsoft.Azure.Agent; @@ -16,6 +18,7 @@ public sealed class AzureAgent : ILLMAgent internal ArgumentPlaceholder ArgPlaceholder { set; get; } private const string SettingFileName = "az.agent.json"; + private const string LoggingFileName = "log..txt"; private const string InstructionPrompt = """ NOTE: follow the below instructions when generating responses that include Azure CLI commands with placeholders: 1. User's OS is `{0}`. Make sure the generated commands are suitable for the specified OS. @@ -33,6 +36,7 @@ 7. DO NOT include the placeholder summary when the commands contains no placehol """; private int _turnsLeft; + private readonly string _instructions; private readonly StringBuilder _buffer; private readonly HttpClient _httpClient; @@ -73,12 +77,23 @@ public void Dispose() ArgPlaceholder?.DataRetriever?.Dispose(); _chatSession.Dispose(); _httpClient.Dispose(); + + Log.CloseAndFlush(); } public void Initialize(AgentConfig config) { _turnsLeft = int.MaxValue; SettingFile = Path.Combine(config.ConfigurationRoot, SettingFileName); + + string logFile = Path.Combine(config.ConfigurationRoot, LoggingFileName); + Log.Logger = new LoggerConfiguration() + .WriteTo.Async(a => a.File( + path: logFile, + outputTemplate: "{Timestamp:HH:mm:ss} [{Level:u3}] {Message:lj}{NewLine}{Exception}", + rollingInterval: RollingInterval.Day)) + .CreateLogger(); + Log.Information("Azure agent initialized."); } public IEnumerable GetCommands() => [new ReplaceCommand(this)]; @@ -129,12 +144,12 @@ public async Task ChatAsync(string input, IShell shell) data = ParseCLIHandlerResponse(copilotResponse, shell); } - string answer = data is null ? copilotResponse.Text : GenerateAnswer(data); if (data?.PlaceholderSet is not null) { ArgPlaceholder = new ArgumentPlaceholder(input, data, _httpClient); } + string answer = data is null ? copilotResponse.Text : GenerateAnswer(data); host.RenderFullResponse(answer); } else @@ -293,6 +308,7 @@ private ResponseData ParseCLIHandlerResponse(CopilotResponse copilotResponse, IS { // The placeholder section is not in the format as we've instructed ... // TODO: send telemetry about this case. + Log.Error("Placeholder section not in expected format:\n{0}", text); } ReplaceKnownPlaceholders(data); diff --git a/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs b/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs index b2f958fa..ff5d5a98 100644 --- a/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs +++ b/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs @@ -3,6 +3,8 @@ using System.Runtime.ExceptionServices; using System.Text.Json; +using Serilog; + namespace Microsoft.Azure.Agent; internal class AzureCopilotReceiver : IDisposable @@ -57,14 +59,14 @@ private async Task ProcessActivities() } catch (OperationCanceledException) { - // TODO: log the cancellation of the message receiving thread. // Close the web socket before the thread is going away. closingMessage = "Client closing"; + Log.Error("[AzureCopilotReceiver] Receiver thread cancelled, which means the instance was disposed."); } if (closingMessage is not null) { - // TODO: log the closing request. + Log.Error("[AzureCopilotReceiver] Sending web socket closing request, message: '{}'", closingMessage); await _webSocket.CloseAsync(WebSocketCloseStatus.NormalClosure, closingMessage, CancellationToken.None); _activityQueue.CompleteAdding(); break; @@ -100,7 +102,7 @@ private async Task ProcessActivities() } } - // TODO: log the current state of the web socket. + Log.Error("[AzureCopilotReceiver] Web socket connection dropped. State: '{0}'", _webSocket.State); _activityQueue.Add(new CopilotActivity { Error = new ConnectionDroppedException($"The websocket got in '{_webSocket.State}' state. Connection dropped.") }); _activityQueue.CompleteAdding(); } diff --git a/shell/agents/Microsoft.Azure.Agent/ChatSession.cs b/shell/agents/Microsoft.Azure.Agent/ChatSession.cs index cad2484d..117c497e 100644 --- a/shell/agents/Microsoft.Azure.Agent/ChatSession.cs +++ b/shell/agents/Microsoft.Azure.Agent/ChatSession.cs @@ -3,6 +3,7 @@ using System.Text; using System.Text.Json; using System.Text.Json.Nodes; + using AIShell.Abstraction; namespace Microsoft.Azure.Agent; @@ -75,8 +76,7 @@ internal async Task RefreshAsync(IHost host, CancellationToken cancellationToken else { host.WriteErrorLine() - .WriteErrorLine($"Failed to start a conversation due to the following error: {e.Message}") - .WriteErrorLine(e.StackTrace) + .WriteErrorLine($"Failed to start a conversation due to the following error: {e.Message}\n{e.StackTrace}") .WriteErrorLine() .WriteErrorLine("Please try '/refresh' to start a new conversation.") .WriteErrorLine(); diff --git a/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs b/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs index 6ba09779..e265c9d8 100644 --- a/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs +++ b/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs @@ -4,7 +4,9 @@ using System.Text; using System.Text.Json; using System.Text.RegularExpressions; + using AIShell.Abstraction; +using Serilog; namespace Microsoft.Azure.Agent; @@ -573,11 +575,13 @@ private AzCLICommand QueryForMetadata(string azCommand) else { // TODO: telemetry. + Log.Error("[QueryForMetadata] Metadata service returns status code: {0}. Query command: {1}", response.StatusCode, azCommand); } } - catch (Exception) + catch (Exception e) { // TODO: telemetry. + Log.Error(e, "[QueryForMetadata] Exception while processing command: {0}", azCommand); } return command; diff --git a/shell/agents/Microsoft.Azure.Agent/Microsoft.Azure.Agent.csproj b/shell/agents/Microsoft.Azure.Agent/Microsoft.Azure.Agent.csproj index 8d556570..d484f156 100644 --- a/shell/agents/Microsoft.Azure.Agent/Microsoft.Azure.Agent.csproj +++ b/shell/agents/Microsoft.Azure.Agent/Microsoft.Azure.Agent.csproj @@ -18,6 +18,8 @@ + + From 20df101e95a716c95760677858cd9aa7da65fb06 Mon Sep 17 00:00:00 2001 From: Dongbo Wang Date: Mon, 21 Oct 2024 17:19:41 -0700 Subject: [PATCH 2/2] Minor updates --- shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs | 2 +- shell/agents/Microsoft.Azure.Agent/DataRetriever.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs b/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs index ff5d5a98..80f02669 100644 --- a/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs +++ b/shell/agents/Microsoft.Azure.Agent/AzureCopilotReceiver.cs @@ -66,7 +66,7 @@ private async Task ProcessActivities() if (closingMessage is not null) { - Log.Error("[AzureCopilotReceiver] Sending web socket closing request, message: '{}'", closingMessage); + Log.Error("[AzureCopilotReceiver] Sending web socket closing request, message: '{0}'", closingMessage); await _webSocket.CloseAsync(WebSocketCloseStatus.NormalClosure, closingMessage, CancellationToken.None); _activityQueue.CompleteAdding(); break; diff --git a/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs b/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs index e265c9d8..e4d8092c 100644 --- a/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs +++ b/shell/agents/Microsoft.Azure.Agent/DataRetriever.cs @@ -575,7 +575,7 @@ private AzCLICommand QueryForMetadata(string azCommand) else { // TODO: telemetry. - Log.Error("[QueryForMetadata] Metadata service returns status code: {0}. Query command: {1}", response.StatusCode, azCommand); + Log.Error("[QueryForMetadata] Received status code '{0}' for command '{1}'", response.StatusCode, azCommand); } } catch (Exception e)