dotnet / aspire

Tools, templates, and packages to accelerate building observable, production-ready apps
https://learn.microsoft.com/dotnet/aspire
MIT License
3.94k stars 482 forks source link

`Container is being deleted` errors when shutting down test host. #6786

Open afscrome opened 3 days ago

afscrome commented 3 days ago

Is there an existing issue for this?

Describe the bug

At the end of a test run using the test host builder, I often (but not always) see some unhelpful log errors as the final entries in the test logs. These logs can end up being a bit of a red herring as the first things people do when troubleshooting a failed test is to look at the last errors in the logs, which these show up as.

fail: Aspire.Hosting.Dcp.start-apiserver.api-server.logstorage[0]
      failed to initialize log stream   {"Kind": "usvc-dev.developer.microsoft.com/v1, Kind=Container", "Name": "REDACTED-aetszphy-7cf5787f", "UID": "f0af3741-8f28-4ca4-83d4-f4a6716f052c", "Source": "stdout", "Follow": true, "error": "Container is being deleted"}

fail: Aspire.Hosting.Dcp.start-apiserver.api-server.logstorage[0]
      failed to initialize log stream   {"Kind": "usvc-dev.developer.microsoft.com/v1, Kind=Container", "Name": "REDACTED-aetszphy-7cf5787f", "UID": "f0af3741-8f28-4ca4-83d4-f4a6716f052c", "Source": "stderr", "Follow": true, "error": "Container is being deleted"}

fail: Aspire.Hosting.Dcp.start-apiserver.api-server.logstorage[0]
      failed to initialize log stream   {"Kind": "usvc-dev.developer.microsoft.com/v1, Kind=Container", "Name": "REDACTED-wtbvyptf-7cf5787f", "UID": "d4b2e7b2-9372-4748-b48a-0c69eaf2b773", "Source": "stdout", "Follow": true, "error": "Container is being deleted"}

fail: Aspire.Hosting.Dcp.start-apiserver.api-server.logstorage[0]
      failed to initialize log stream   {"Kind": "usvc-dev.developer.microsoft.com/v1, Kind=Container", "Name": "REDACTED-wtbvyptf-7cf5787f", "UID": "d4b2e7b2-9372-4748-b48a-0c69eaf2b773", "Source": "stderr", "Follow": true, "error": "Container is being deleted"}

Expected Behavior

Container is being deleted seems like expected (and desirable!) behaviour when shutting down the app host, so I wouldn't expect such errors to be logged.

Steps To Reproduce

Don't have great repo steps as it doesn't always happen, but I'm using nunit as test framework, with the following wrapping code. I've seen it across a variety of tests, so I think it's a general race condition during TestHost disposal rather than related to the contents of any specific test.

   [SetUp]
   public async Task SetUp()
   {
      // Arrange
      var appHost = await DistributedApplicationTestingBuilder.CreateAsync<Projects.Trayport_Aspire_AppHost>();
      appHost.Services.AddLogging(x => x
            .AddNUnit()
            .AddFilter("Default", LogLevel.Information)
            .AddFilter("Microsoft.AspNetCore", LogLevel.Warning)
            .AddFilter("Aspire.Hosting.Dcp", LogLevel.Warning)
      );

      _app = await appHost.BuildAsync();
      _resourceNotificationService = _app.Services.GetRequiredService<ResourceNotificationService>();

      // Start Async includes pulling docker images, so on a fresh machine (i.e. build agent)
      // this does need a bit of time
      using var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromMinutes(5));
      await _app.StartAsync(cancellationTokenSource.Token);
   }

   [TearDown]
   public async Task TearDown()
   {
      if (_app != null)
      {
         await _app.StopAsync();
         await _app.DisposeAsync();
      }
   }

Exceptions (if any)

No response

.NET Version info

.NET SDK: Version: 9.0.100 Commit: 59db016f11 Workload version: 9.0.100-manifests.c6f19616 MSBuild version: 17.12.7+5b8665660

Runtime Environment: OS Name: Windows OS Version: 10.0.22621 OS Platform: Windows RID: win-x64 Base Path: C:\Program Files\dotnet\sdk\9.0.100\

.NET workloads installed: [aspire] Installation Source: VS 17.12.35514.174 Manifest Version: 8.2.2/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.aspire\8.2.2\WorkloadManifest.json Install Type: Msi

Configured to use loose manifests when installing new manifests.

Host: Version: 9.0.0 Architecture: x64 Commit: 9d5a6a9aa4

.NET SDKs installed: 6.0.428 [C:\Program Files\dotnet\sdk] 8.0.404 [C:\Program Files\dotnet\sdk] 9.0.100 [C:\Program Files\dotnet\sdk]

.NET runtimes installed: Microsoft.AspNetCore.App 6.0.36 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.7 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 8.0.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 9.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 6.0.36 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 8.0.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 9.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 6.0.36 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 8.0.11 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 9.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found: x86 [C:\Program Files (x86)\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables: Not set

global.json file: Not found

Learn more: https://aka.ms/dotnet/info

Download .NET: https://aka.ms/dotnet/download

Anything else?

Image

dbreshears commented 3 days ago

Thanks @afscrome, should be a simple fix for us not log this if shutting down