Add basic logging for error cases in the Azure agent (#250)

- Use `Serilog` as it supports file logging. I considered `Microsoft.Extension.Logging` which has built-in logging provider for Event Source, but decided to not use it because it's easier to share a file log for diagnosis purposes.
- The logging is configured to be rolling over by day, and it uses async writing to the log file.
- The logging enabled so far is error only, but we can add more information/debug loggings for better view of the code operation.
- We will need to allow a user to disable logging in the agent's configuration file. **This is not done in this PR.**

Author: daxian-dbw

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<CommandBase> GetCommands() => [new ReplaceCommand(this)];
@@ -129,12 +144,12 @@ public async Task<bool> 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);

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: '{0}'", 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();
     }

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();

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] Received status code '{0}' for command '{1}'", response.StatusCode, azCommand);
             }
         }
-        catch (Exception)
+        catch (Exception e)
         {
             // TODO: telemetry.
+            Log.Error(e, "[QueryForMetadata] Exception while processing command: {0}", azCommand);
         }
 
         return command;

shell/agents/Microsoft.Azure.Agent/Microsoft.Azure.Agent.csproj

@@ -18,6 +18,8 @@
   <ItemGroup>
     <PackageReference Include="Azure.Identity" Version="1.11.4" />
     <PackageReference Include="Microsoft.ApplicationInsights.WorkerService" Version="2.22.0" />
+    <PackageReference Include="Serilog.Sinks.File" Version="6.0.0" />
+    <PackageReference Include="Serilog.Sinks.Async" Version="2.0.0" />
   </ItemGroup>
 
   <ItemGroup>