Better timeout management and error handling of results (#672)

* Added better handling of timeouts and background error logging

* Doc better why we just log warning on timeout

* Added test and fix comment

* Remove from DI

* Remove the interface

* Fix tests

* Fix tests

src/Client/NetDaemon.HassClient.Tests/HelperTest/ResultMessageHandlerTests.cs

@@ -0,0 +1,85 @@
+namespace NetDaemon.HassClient.Tests.HelperTest;
+
+public class ResultMessageHandlerTests
+{
+    private readonly Mock<ILogger<ResultMessageHandler>> _loggerMock = new();
+    private readonly ResultMessageHandler _resultMessageHandler;
+
+    public ResultMessageHandlerTests()
+    {
+        _resultMessageHandler = new ResultMessageHandler(_loggerMock.Object);
+    }
+
+    [Fact]
+    public async Task TestTaskCompleteWithoutLog()
+    {
+        var task = SomeSuccessfulResult();
+        _resultMessageHandler.HandleResult(task, new CommandMessage {Type = "test"});
+        await _resultMessageHandler.DisposeAsync().ConfigureAwait(false);
+        task.IsCompletedSuccessfully.Should().BeTrue();
+        _loggerMock.Verify(
+            x => x.Log(
+                It.IsAny<LogLevel>(),
+                It.IsAny<EventId>(),
+                It.Is<It.IsAnyType>((_, __) => true),
+                It.IsAny<Exception>(),
+                It.Is<Func<It.IsAnyType, Exception, string>>((_, _) => true)!), Times.Never());
+    }
+
+
+    [Fact]
+    public async Task TestTaskCompleteWithErrorResultShouldLogWarning()
+    {
+        var task = SomeUnSuccessfulResult();
+        _resultMessageHandler.HandleResult(task, new CommandMessage {Type = "test"});
+        await _resultMessageHandler.DisposeAsync().ConfigureAwait(false);
+        task.IsCompletedSuccessfully.Should().BeTrue();
+        _loggerMock.VerifyWarningWasCalled("Failed command (test) error: (null).  Sent command is CommandMessage { Type = test, Id = 0 }");
+    }
+
+    [Fact]
+    public async Task TestTaskCompleteWithExceptionShouldLogError()
+    {
+        var task = SomeUnSuccessfulResultThrowsException();
+        _resultMessageHandler.HandleResult(task, new CommandMessage {Type = "test"});
+        await _resultMessageHandler.DisposeAsync().ConfigureAwait(false);
+        task.IsCompletedSuccessfully.Should().BeFalse();
+        task.IsFaulted.Should().BeTrue();
+        _loggerMock.VerifyErrorWasCalled("Exception waiting for result message  Sent command is CommandMessage { Type = test, Id = 0 }");
+    }
+
+    [Fact]
+    public async Task TestTaskCompleteWithTimeoutShouldLogWarning()
+    {
+        _resultMessageHandler.WaitForResultTimeout = 1;
+
+        var task = SomeSuccessfulResult();
+        _resultMessageHandler.HandleResult(task, new CommandMessage {Type = "test"});
+        await _resultMessageHandler.DisposeAsync().ConfigureAwait(false);
+        task.IsCompletedSuccessfully.Should().BeTrue();
+        _loggerMock.VerifyWarningWasCalled("Command (test) did not get response in timely fashion.  Sent command is CommandMessage { Type = test, Id = 0 }");
+    }
+
+
+
+    private async Task<HassMessage> SomeSuccessfulResult()
+    {
+        // Simulate som time
+        await Task.Delay(100);
+        return new HassMessage {Success = true};
+    }
+
+    private async Task<HassMessage> SomeUnSuccessfulResult()
+    {
+        // Simulate som time
+        await Task.Delay(100);
+        return new HassMessage {Success = false};
+    }
+
+    private async Task<HassMessage> SomeUnSuccessfulResultThrowsException()
+    {
+        // Simulate som time
+        await Task.Delay(100);
+        throw new InvalidOperationException("Ohh noooo!");
+    }
+}

src/Client/NetDaemon.HassClient.Tests/Helpers/LoggerMockExtensions.cs

@@ -0,0 +1,32 @@
+namespace NetDaemon.HassClient.Tests.Helpers;
+
+public static class LoggerMockExtensions
+{
+    public static Mock<ILogger<T>> VerifyWarningWasCalled<T>(this Mock<ILogger<T>> logger, string expectedMessage)
+    {
+        Func<object, Type, bool> state = (v, t) => String.Compare(v.ToString()!, expectedMessage, StringComparison.Ordinal) == 0;
+
+        logger.Verify(
+            x => x.Log(
+                It.Is<LogLevel>(l => l == LogLevel.Warning),
+                It.IsAny<EventId>(),
+                It.Is<It.IsAnyType>((v, t) => state(v, t)),
+                It.IsAny<Exception>(),
+                It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)!));
+        return logger;
+    }
+
+    public static Mock<ILogger<T>> VerifyErrorWasCalled<T>(this Mock<ILogger<T>> logger, string expectedMessage)
+    {
+        Func<object, Type, bool> state = (v, t) => String.Compare(v.ToString()!, expectedMessage, StringComparison.Ordinal) == 0;
+
+        logger.Verify(
+            x => x.Log(
+                It.Is<LogLevel>(l => l == LogLevel.Error),
+                It.IsAny<EventId>(),
+                It.Is<It.IsAnyType>((v, t) => state(v, t)),
+                It.IsAny<Exception>(),
+                It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)!));
+        return logger;
+    }
+}

src/Client/NetDaemon.HassClient.Tests/HomeAssistantClientTest/HomeAssistantClientTests.cs

@@ -67,7 +67,8 @@ public void TestInstanceNewConnectionOnClosedWebsocketThrowsExceptionShouldThrow
             _ = new HomeAssistantConnection(
                 loggerMock.Object,
                 _pipeline.Object,
-                new Mock<IHomeAssistantApiManager>().Object));
+                new Mock<IHomeAssistantApiManager>().Object)
+                );
     }
 
     /// <summary>
@@ -122,4 +123,4 @@ private HomeAssistantClient GetDefaultConnectOkHomeAssistantClient()
         );
         return GetDefaultHomeAssistantClient();
     }
-}
+}

src/Client/NetDaemon.HassClient.Tests/Integration/IntegrationTestBase.cs

@@ -22,7 +22,6 @@ internal async Task<TestContext> GetConnectedClientContext(HomeAssistantSettings
         var loggerClient = new Mock<ILogger<HomeAssistantClient>>();
         var loggerTransport = new Mock<ILogger<IWebSocketClientTransportPipeline>>();
         var loggerConnection = new Mock<ILogger<IHomeAssistantConnection>>();
-
         var settings = haSettings ?? new HomeAssistantSettings
         {
             Host = "127.0.0.1",
@@ -64,4 +63,4 @@ internal async Task<TestContext> GetConnectedClientContext(HomeAssistantSettings
             HomeAssistantConnection = connection
         };
     }
-}
+}

src/Client/NetDaemon.HassClient.Tests/Integration/WebsocketIntegrationTests.cs

@@ -146,7 +146,7 @@ public async Task TestGetAreasShouldHaveCorrectCounts()
     public async Task TestErrorReturnShouldThrowException()
     {
         await using var ctx = await GetConnectedClientContext().ConfigureAwait(false);
-        await Assert.ThrowsAsync<ApplicationException>(async () => await ctx.HomeAssistantConnection
+        await Assert.ThrowsAsync<InvalidOperationException>(async () => await ctx.HomeAssistantConnection
             .SendCommandAndReturnResponseAsync<SimpleCommand, object?>(
                 new SimpleCommand("fake_return_error"),
                 TokenSource.Token
@@ -252,4 +252,4 @@ private record AttributeTest
     {
         [JsonPropertyName("battery_level")] public int BatteryLevel { get; init; }
     }
-}
+}

src/Client/NetDaemon.HassClient.Tests/NetDaemon.HassClient.Tests.csproj

@@ -28,6 +28,6 @@
         </PackageReference>
     </ItemGroup>
     <ItemGroup>
-        <ProjectReference Include="..\NetDaemon.HassClient\NetDaemon.Client.csproj"/>
+        <ProjectReference Include="..\NetDaemon.HassClient\NetDaemon.Client.csproj" />
     </ItemGroup>
 </Project>

src/Client/NetDaemon.HassClient/Common/Extensions/ServiceCollectionExtension.cs

@@ -62,4 +62,4 @@ private static HttpMessageHandler ConfigureHttpMessageHandler(IServiceProvider p
         var handler = provider.GetService<HttpMessageHandler>();
         return handler ?? HttpHelper.CreateHttpMessageHandler(provider);
     }
-}
+}

src/Client/NetDaemon.HassClient/Common/HomeAssistant/Extensions/IHomeAssistantConnectionExtensions.cs

@@ -103,7 +103,7 @@ public static async Task CallServiceAsync(
     )
     {
         await connection
-            .SendCommandAndReturnResponseAsync<CallServiceCommand, object?>
+            .SendCommandAsync
             (
                 new CallServiceCommand
                 {
@@ -147,4 +147,4 @@ await connection
 
         return true;
     }
-}
+}

src/Client/NetDaemon.HassClient/Common/HomeAssistantClientConnector.cs

@@ -35,6 +35,7 @@ public static async Task<IHomeAssistantConnection> ConnectClientAsync(string hos
         var loggerFactory = LoggerFactory.Create(b => b.AddConsole());
         var loggerConnect = loggerFactory.CreateLogger<IHomeAssistantConnection>();
         var loggerClient = loggerFactory.CreateLogger<IHomeAssistantClient>();
+        var loggerResultMessageHandler = loggerFactory.CreateLogger<ResultMessageHandler>();
         var settings = new HomeAssistantSettings
         {
             Host = host,
@@ -51,4 +52,4 @@ public static async Task<IHomeAssistantConnection> ConnectClientAsync(string hos
 
         return await client.ConnectAsync(host, port, ssl, token, websocketPath, cancelToken).ConfigureAwait(false);
     }
-}
+}

src/Client/NetDaemon.HassClient/Internal/Helpers/ResultMessageHandler.cs

@@ -0,0 +1,74 @@
+using System.Collections.Concurrent;
+
+namespace NetDaemon.Client.Internal.Helpers;
+
+internal class ResultMessageHandler : IAsyncDisposable
+{
+    internal int WaitForResultTimeout = 20000;
+    private readonly CancellationTokenSource _tokenSource = new();
+    private readonly ConcurrentDictionary<Task<HassMessage>, object?> _backgroundTasks = new();
+    private readonly ILogger _logger;
+
+    public ResultMessageHandler(ILogger logger)
+    {
+        _logger = logger;
+    }
+
+    public void HandleResult(Task<HassMessage> returnMessageTask, CommandMessage originalCommand)
+    {
+        TrackBackgroundTask(returnMessageTask, originalCommand);
+    }
+
+    private void TrackBackgroundTask(Task<HassMessage> task, CommandMessage command)
+    {
+        _backgroundTasks.TryAdd(task, null);
+
+        [SuppressMessage("", "CA1031")]
+        async Task Wrap()
+        {
+            try
+            {
+                var awaitedTask = await Task.WhenAny(task, Task.Delay(WaitForResultTimeout, _tokenSource.Token)).ConfigureAwait(false);
+
+                if (awaitedTask != task)
+                {
+                    // We have a timeout
+                    _logger.LogWarning(
+                        "Command ({CommandType}) did not get response in timely fashion.  Sent command is {CommandMessage}",
+                        command.Type, command);
+                }
+                // We wait for the task even if there was a timeout so we make sure
+                // we catch the original error
+                var result = await task.ConfigureAwait(false);
+                if (!result.Success ?? false)
+                {
+                    _logger.LogWarning(
+                        "Failed command ({CommandType}) error: {ErrorResult}.  Sent command is {CommandMessage}",
+                        command.Type, result.Error, command);
+                }
+            }
+            catch (Exception e)
+            {
+                _logger.LogError(e, "Exception waiting for result message  Sent command is {CommandMessage}", command);
+            }
+            finally
+            {
+                _backgroundTasks.TryRemove(task, out var _);
+            }
+        }
+
+        // We do not handle task here cause exceptions
+        // are handled in the Wrap local functions and
+        // all tasks should be cancelable
+        _ = Wrap();
+    }
+
+    public async ValueTask DisposeAsync()
+    {
+        // Wait for the tasks to complete max 5 seconds
+        if (!_backgroundTasks.IsEmpty)
+        {
+            await Task.WhenAny( Task.WhenAll(_backgroundTasks.Keys), Task.Delay(TimeSpan.FromSeconds(5))).ConfigureAwait(false);
+        }
+    }
+}