Added message logging capabilities (#20)

This PR includes message logging capabilities to HassClient.

The default behavior now is:
- When LogLevel.Trace then all messages are logged except event. This is so we do not flood the log
- Events can be turned on by setting the environment var HASSCLIENT_MSGLOGLEVEL=All
- All message logs can be turned off by setting the environment var HASSCLIENT_MSGLOGLEVEL=None

console/HassClient.Performance.Tests/Program.cs

@@ -61,8 +61,10 @@ private static async Task ConnectToHomeAssistant(string ip, short port, bool eve
             {
                 builder
                     .ClearProviders()
-                    .AddFilter("HassClient.HassClient", LogLevel.Trace)
-                    .AddConsole();
+                    // .AddFilter("HassClient.HassClient", LogLevel.Trace)
+                    .AddConsole()
+                    .AddDebug()
+                    .SetMinimumLevel(LogLevel.Trace);
             });
 
             client = new HassClient(factory);
@@ -92,7 +94,8 @@ private static async Task ConnectToHomeAssistant(string ip, short port, bool eve
                 await client.SubscribeToEvents();
             }
 
-            // var test = await client.CallService("light", "toggle", new { entity_id = "light.tomas_rum" });
+            await client.CallService("light", "toggle", new { entity_id = "light.tomas_rum" });
+            await client.CallService("light", "no_exist", new { entity_id = "light.tomas_rum_not_exist" });
             //var tt = await client.SetState("sensor.csharp", "cool", new {daemon = true});
 
             //var result = await client.SendEvent("test_event", new { data="hello" });

src/HassClient/Client/HassClient.cs

@@ -12,7 +12,6 @@
 using System.Threading.Channels;
 using System.Threading.Tasks;
 using System.Web;
-using System.Xml.XPath;
 using Microsoft.Extensions.Logging;
 
 [assembly: InternalsVisibleTo("HassClientIntegrationTests")]
@@ -193,6 +192,14 @@ public class HassClient : IHassClient, IDisposable
         /// </summary>
         private readonly ILogger _logger;
 
+        /// <summary>
+        ///     Set loglevel om messages when tracing is enabled
+        ///     - Default, logs but state chages
+        ///     - None, do not log messages
+        ///     - All, logs all but security challanges
+        /// </summary>
+        private readonly string _messageLogLevel;
+
         /// <summary>
         ///     Channel used as a async thread safe way to wite messages to the websocket
         /// </summary>
@@ -266,6 +273,7 @@ internal HassClient(ILoggerFactory? logFactory, IClientWebSocketFactory? wsFacto
 
             _wsFactory = wsFactory;
             _logger = logFactory.CreateLogger<HassClient>();
+            _messageLogLevel = Environment.GetEnvironmentVariable("HASSCLIENT_MSGLOGLEVEL") ?? "Default";
         }
 
         /// <summary>
@@ -718,6 +726,20 @@ await _ws.CloseOutputAsync(WebSocketCloseStatus.NormalClosure, "Remote closed",
                             throw new WebSocketException("Socket closed");
                         }
 
+                        // Log incoming messages for correct loglevel and tracing is enabled
+                        if (_messageLogLevel != "None" && _logger.IsEnabled(LogLevel.Trace) && result.Count > 0)
+                        {
+                            var strMessageReceived = UTF8Encoding.UTF8.GetString(memory.Slice(0, result.Count).ToArray());
+                            if (_messageLogLevel == "All")
+                                _logger.LogTrace("ReadClientSocket, message: {strMessageReceived}", strMessageReceived);
+                            else if (_messageLogLevel == "Default")
+                            {
+                                // Log all but events
+                                if (strMessageReceived.Contains("\"type\": \"event\"") == false)
+                                    _logger.LogTrace("ReadClientSocket, message: {strMessageReceived}", strMessageReceived);
+                            }
+
+                        }
                         // Advance writer to the read ne of bytes
                         pipe.Writer.Advance(result.Count);
 
@@ -760,6 +782,7 @@ async Task WriteMessagesToChannel()
                     // ReSharper disable once AccessToDisposedClosure
                     HassMessage m = await JsonSerializer.DeserializeAsync<HassMessage>(pipe.Reader.AsStream(),
                         cancellationToken: cancelTokenSource.Token);
+
                     await pipe.Reader.CompleteAsync();
                     switch (m.Type)
                     {
@@ -830,11 +853,6 @@ internal virtual async ValueTask<HassMessage> SendCommandAndWaitForResponse(Comm
                     HassMessage result = await _messageChannel.Reader.ReadAsync(sendCommandTokenSource.Token);
                     if (result.Id == message.Id)
                     {
-                        if (result.Type != "result" || result.Success != true)
-                        {
-                            _logger.LogError($"Unexpected response from command ({result.Type}, {result.Success})");
-                        }
-
                         return result;
                     }
 
@@ -1076,6 +1094,18 @@ private async Task WriteMessagePump()
                         _defaultSerializerOptions);
 
                     await _ws.SendAsync(result, WebSocketMessageType.Text, true, CancelSource.Token);
+
+                    if (_logger.IsEnabled(LogLevel.Trace))
+                    {
+                        if (nextMessage is HassAuthMessage == false)
+                        {
+                            // We log everything but AuthMessage due to security reasons
+                            _logger.LogTrace("SendAsync, message: {result}", UTF8Encoding.UTF8.GetString(result));
+                        }
+                        {
+                            _logger.LogTrace("Sending auth message, not shown for security reasons");
+                        }
+                    }
                 }
                 catch (OperationCanceledException)
                 {