Better handling of faulty unloading of appa (#961)

* handle unloading of faulty apps better and prohibit apps instancing if previous unloading fails

* refactor

* test for slow dispose

Author: helto4real

src/AppModel/NetDaemon.AppModel.Tests/AppModelTests.cs

@@ -37,14 +37,37 @@ public async Task TestGetApplicationsLocal()
         var loadApps = await TestHelpers.GetLocalApplicationsFromYamlConfigPath("Fixtures/Local").ConfigureAwait(false);
 
         // CHECK
-        loadApps.Should().HaveCount(6);
+        loadApps.Should().HaveCount(7);
 
         // check the application instance is init ok
         var application = (Application) loadApps.First(n => n.Id == "LocalApps.MyAppLocalApp");
         var instance = (MyAppLocalApp?) application.ApplicationContext?.Instance;
         instance!.Settings.AString.Should().Be("Hello world!");
     }
 
+    [Fact]
+    public async Task TestSlowDisposableAppShouldLogWarning()
+    {
+        // ARRANGE
+        var loggerMock = new Mock<ILogger<Application>>();
+
+        // ACT
+        var loadApps = await TestHelpers.GetLocalApplicationsFromYamlConfigPath("Fixtures/Local", loggerMock.Object).ConfigureAwait(false);
+
+        // CHECK
+        // check the application instance is init ok
+        var application = (Application) loadApps.First(n => n.Id == "LocalApps.SlowDisposableApp");
+        await application.DisposeAsync().ConfigureAwait(false);
+
+        loggerMock.Verify(
+            x => x.Log(
+                LogLevel.Error,
+                It.IsAny<EventId>(),
+                It.Is<It.IsAnyType>((_, __) => true),
+                It.IsAny<Exception>(),
+                It.Is<Func<It.IsAnyType, Exception?, string>>((_, _) => true)), Times.Once);
+    }
+
     [Fact]
     public async Task TestGetApplicationsLocalWithDisabled()
     {

src/AppModel/NetDaemon.AppModel.Tests/Fixtures/Local/AppThatTakesASlowTimeToDispose.cs

@@ -0,0 +1,17 @@
+
+namespace LocalApps;
+
+
+[NetDaemonApp]
+public class SlowDisposableApp : IDisposable
+{
+    public SlowDisposableApp()
+    {
+    }
+
+    public void Dispose()
+    {
+        Thread.Sleep(3500);
+    }
+}
+

src/AppModel/NetDaemon.AppModel.Tests/Helpers/TestHelpers.cs

@@ -1,10 +1,13 @@
 using System.Reflection;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
+using NetDaemon.AppModel.Internal;
 
 namespace NetDaemon.AppModel.Tests.Helpers;
 
 public static class TestHelpers
 {
+
     internal static async Task<IReadOnlyCollection<IApplication>> GetLocalApplicationsFromYamlConfigPath(string path)
     {
         var builder = Host.CreateDefaultBuilder()
@@ -25,6 +28,27 @@ internal static async Task<IReadOnlyCollection<IApplication>> GetLocalApplicatio
         return appModelContext.Applications;
     }
 
+    internal static async Task<IReadOnlyCollection<IApplication>> GetLocalApplicationsFromYamlConfigPath(string path, ILogger<Application> logger)
+    {
+        var builder = Host.CreateDefaultBuilder()
+            .ConfigureServices((_, services) =>
+            {
+                // get apps from test project
+                services.AddAppsFromAssembly(Assembly.GetExecutingAssembly());
+                services.AddTransient<ILogger<Application>>(_ => logger);
+            })
+            .ConfigureAppConfiguration((_, config) =>
+            {
+                config.AddYamlAppConfig(
+                    Path.Combine(AppContext.BaseDirectory,
+                        path));
+            })
+            .Build();
+        var appModel = builder.Services.GetService<IAppModel>();
+        var appModelContext = await appModel!.LoadNewApplicationContext(CancellationToken.None).ConfigureAwait(false);
+        return appModelContext.Applications;
+    }
+
     internal static async Task<IReadOnlyCollection<IApplication>> GetDynamicApplicationsFromYamlConfigPath(string path)
     {
         var builder = Host.CreateDefaultBuilder()
@@ -46,4 +70,4 @@ internal static async Task<IReadOnlyCollection<IApplication>> GetDynamicApplicat
         var appModelContext = await appModel!.LoadNewApplicationContext(CancellationToken.None).ConfigureAwait(false);
         return appModelContext.Applications;
     }
-}
+}

src/AppModel/NetDaemon.AppModel/Internal/AppModelContext.cs

@@ -26,7 +26,7 @@ public async Task InitializeAsync(CancellationToken cancellationToken)
     {
         var factories = _appFactoryProviders.SelectMany(provider => provider.GetAppFactories()).ToList();
 
-        var filteredFactories =  _focusFilter.FilterFocusApps(factories);
+        var filteredFactories = _focusFilter.FilterFocusApps(factories);
 
         foreach (var factory in filteredFactories)
         {
@@ -44,10 +44,10 @@ public async ValueTask DisposeAsync()
         if (_isDisposed) return;
         _isDisposed = true;
 
-        foreach (var appInstance in _applications)
-        {
-            await appInstance.DisposeAsync().ConfigureAwait(false);
-        }
+        // Get all tasks for disposing the apps with a timeout
+        var disposeTasks = _applications.Select(app => app.DisposeAsync().AsTask()).ToList();
+
+        await Task.WhenAll(disposeTasks).ConfigureAwait(false);
 
         _applications.Clear();
     }

src/AppModel/NetDaemon.AppModel/Internal/Application.cs

@@ -58,20 +58,43 @@ public async Task SetStateAsync(ApplicationState state)
         }
     }
 
+    /// <summary>
+    ///    Unloads the application and log any errors.If application unload takes longer than 3 seconds it will log a warning and return.
+    /// </summary>
+    private async Task UnloadContextAsync()
+    {
+        if (ApplicationContext is not null)
+        {
+            try
+            {
+               await ApplicationContext.DisposeAsync().AsTask().WaitAsync(TimeSpan.FromSeconds(3)).ConfigureAwait(false);
+            }
+            catch (Exception e)
+            {
+                if (e is TimeoutException)
+                    _logger.LogError("Unloading the app '{App}' takes longer than expected, please check for blocking code", Id);
+                else
+                    _logger.LogError(e, "Unloading the app '{App}' failed", Id);
+
+                ApplicationContext = null;
+                return;
+            }
+        }
+
+        ApplicationContext = null;
+        _logger.LogDebug("Successfully unloaded app {Id}", Id);
+    }
+
     public async ValueTask DisposeAsync()
     {
-        if (ApplicationContext is not null) await ApplicationContext.DisposeAsync().ConfigureAwait(false);
+        await UnloadContextAsync().ConfigureAwait(false);
     }
 
     private async Task UnloadApplication(ApplicationState state)
     {
-        if (ApplicationContext is not null)
-        {
-            await ApplicationContext.DisposeAsync().ConfigureAwait(false);
-            ApplicationContext = null;
-            _logger.LogInformation("Successfully unloaded app {Id}", Id);
-            await SaveStateIfStateManagerExistAsync(state).ConfigureAwait(false);
-        }
+        await UnloadContextAsync().ConfigureAwait(false);
+
+        await SaveStateIfStateManagerExistAsync(state).ConfigureAwait(false);
     }
 
     private async Task LoadApplication(ApplicationState state)

src/Runtime/NetDaemon.Runtime/Internal/NetDaemonRuntime.cs

@@ -85,6 +85,14 @@ private async Task OnHomeAssistantClientConnected(
         CancellationToken cancelToken)
     {
         _logger.LogInformation("Successfully connected to Home Assistant");
+
+        if (_applicationModelContext is not null)
+        {
+            // Something wrong with unloading and disposing apps on restart of HA, we need to prevent apps loading multiple times
+            _logger.LogWarning("Applications were not successfully disposed during restart, skippin loading apps again");
+            return;
+        }
+
         IsConnected = true;
 
         await _cacheManager.InitializeAsync(cancelToken).ConfigureAwait(false);
@@ -108,13 +116,13 @@ private async Task LoadNewAppContextAsync(IHomeAssistantConnection haConnection,
                     Path.GetFullPath(_locationSettings.Value.ApplicationConfigurationFolder));
             else
                 _logger.LogDebug("Loading applications with no configuration folder");
-            
+
             _applicationModelContext = await appModel.LoadNewApplicationContext(CancellationToken.None).ConfigureAwait(false);
 
             // Handle state change for apps if registered
             var appStateHandler = _serviceProvider.GetService<IHandleHomeAssistantAppStateUpdates>();
             if (appStateHandler == null) return;
-            
+
             await appStateHandler.InitializeAsync(haConnection, _applicationModelContext);
         }
         catch (Exception e)
@@ -144,7 +152,14 @@ private async Task OnHomeAssistantClientDisconnected(DisconnectReason reason)
                 reasonString, TimeoutInSeconds);
         }
 
-        await DisposeApplicationsAsync().ConfigureAwait(false);
+        try
+        {
+            await DisposeApplicationsAsync().ConfigureAwait(false);
+        }
+        catch (Exception e)
+        {
+            _logger.LogError(e, "Error disposing applications");
+        }
         IsConnected = false;
     }
 
@@ -153,7 +168,7 @@ private async Task DisposeApplicationsAsync()
         if (_applicationModelContext is not null)
         {
             await _applicationModelContext.DisposeAsync();
-            
+
             _applicationModelContext = null;
         }
     }
@@ -163,7 +178,7 @@ public async ValueTask DisposeAsync()
     {
         if (_isDisposed) return;
         _isDisposed = true;
-        
+
         await DisposeApplicationsAsync().ConfigureAwait(false);
         _runnerCancelationSource?.Cancel();
         try
@@ -172,4 +187,4 @@ public async ValueTask DisposeAsync()
         }
         catch (OperationCanceledException) { }
     }
-}
+}

src/debug/DebugHost/apps/HelloApp/HelloApp.cs

@@ -23,9 +23,10 @@ public HelloApp(IHaContext ha, ILogger<HelloApp> logger)
         // ha?.CallService("notify", "persistent_notification", data: new { message = "Notify me", title = "Hello world!" });
     }
 
-    public ValueTask DisposeAsync()
+    public async ValueTask DisposeAsync()
     {
+        await Task.Delay(5000);
         _logger.LogInformation("disposed app");
-        return ValueTask.CompletedTask;
+        //return ValueTask.CompletedTask;
     }
-}
+}