WithHttpCommand_EnablesCommandOnceResourceIsRunning flaky

[danmoseley]

https://dev.azure.com/dnceng-public/public/_build/results?buildId=981881&view=ms.vss-test-web.build-test-results-tab&runId=26187914&resultId=100396&paneView=debug

Relevant log part below. 2 min wait failed here

aspire/tests/Aspire.Hosting.Tests/WithHttpCommandTests.cs

Line 370 in 4eda598

await watchTcs.Task.DefaultTimeout(TestConstants.LongTimeoutTimeSpan);

Note the resource successfully transitioned to Running (per log, and wait on line above) but command remained disabled (per log below) so exactly 2 mins later it timed out.

@mitchdenny can you figure out the issue by code inspection how it could go to running but not enable the command in this case?

  Failed Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning [2 m 2 s]
  Error Message:
   System.TimeoutException : The operation at /_/tests/Aspire.Hosting.Tests/WithHttpCommandTests.cs:370 timed out after reaching the limit of 120000ms.
  Stack Trace:
     at Microsoft.AspNetCore.InternalTesting.AsyncTestHelpers.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/tests/Shared/AsyncTestHelpers.cs:line 149
   at Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning() in /_/tests/Aspire.Hosting.Tests/WithHttpCommandTests.cs:line 370
--- End of stack trace from previous location ---

Standard output messages

Details

  Standard Output Messages:
 | [2025-03-15T23:36:08] Aspire.Hosting.DistributedApplication Information: Aspire version: 9.2.0-ci
 | [2025-03-15T23:36:08] Aspire.Hosting.DistributedApplication Information: Distributed application starting.
 | [2025-03-15T23:36:08] Aspire.Hosting.DistributedApplication Information: Application host directory is: /mnt/vss/_work/1/s/tests/Aspire.Hosting.Tests
 | [2025-03-15T23:36:08] Aspire.Hosting.Cli.CliBackchannel Debug: Aspire CLI backchannel socket path was not specified.
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.DcpHost Information: Starting DCP with arguments: start-apiserver --monitor 68446 --detach --kubeconfig "/tmp/aspire.8UTwEK/kubeconfig"
 | [2025-03-15T23:36:08] Aspire.Hosting.ApplicationModel.ResourceNotificationService Trace: Version: 1
 |                                                                                          Resource service/service update published:
 |                                                                                          ResourceType = CustomResource,
 |                                                                                          CreationTimeStamp = (null),
 |                                                                                          State = { Text = (null), Style = (null) },
 |                                                                                          HeathStatus = (null),
 |                                                                                          ResourceReady = False,
 |                                                                                          ExitCode = (null),
 |                                                                                          Urls = {  },
 |                                                                                          EnvironmentVariables = {
 |                                                                                          },
 |                                                                                          Properties = {
 |                                                                                          },
 |                                                                                          HealthReports = {
 |                                                                                          },
 |                                                                                          Commands = {
 |                                                                                            Do The Thing (mycommand) = Disabled
 |                                                                                          }
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.DcpExecutor Debug: Watching over DCP Endpoint resources.
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.DcpExecutor Debug: Watching over DCP Service resources.
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.DcpExecutor Debug: Watching over DCP Container resources.
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.DcpExecutor Debug: Watching over DCP Executable resources.
 | [2025-03-15T23:36:08] Aspire.Hosting.Dcp.dcp.start-apiserver.api-server Information: Starting API server...
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.KubernetesService Debug: Successfully read Kubernetes configuration from '/tmp/aspire.8UTwEK/kubeconfig' after 401 milliseconds.
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcp.start-apiserver.api-server Information: API server started	{"Address": "127.0.0.1", "Port": 46341}
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host Information: Starting DCP controller host
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host Information: Started all services	{"count": 1}
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcpctrl.ContainerOrchestrator Information: runtime status	{"ContainerRuntime": "", "runtime": "podman", "status": {"Installed":false,"Running":false,"Error":"exec: \"podman\": executable file not found in $PATH\nfailed to start podman command 'Info'"}}
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcpctrl.ContainerOrchestrator Information: runtime status	{"ContainerRuntime": "", "runtime": "docker", "status": {"Installed":true,"Running":true,"Error":""}}
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcpctrl.IdeExecutableRunner Information: Executables cannot be started via IDE: missing required environment variable 'DEBUG_SESSION_PORT'
 | [2025-03-15T23:36:09] Aspire.Hosting.Dcp.dcpctrl Information: starting controller manager
 | [2025-03-15T23:36:09] Aspire.Hosting.Devcontainers.Codespaces.CodespacesResourceUrlRewriterService Trace: Not running in Codespaces, skipping URL rewriting.
 | [2025-03-15T23:36:09] Aspire.Hosting.DistributedApplication Information: Distributed application started. Press Ctrl+C to shut down.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Resource service/service changed state: Starting
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Trace: Version: 2
 |                                                                                          Resource service/service update published:
 |                                                                                          ResourceType = CustomResource,
 |                                                                                          CreationTimeStamp = (null),
 |                                                                                          State = { Text = Starting, Style = (null) },
 |                                                                                          HeathStatus = (null),
 |                                                                                          ResourceReady = False,
 |                                                                                          ExitCode = (null),
 |                                                                                          Urls = {  },
 |                                                                                          EnvironmentVariables = {
 |                                                                                          },
 |                                                                                          Properties = {
 |                                                                                          },
 |                                                                                          HealthReports = {
 |                                                                                          },
 |                                                                                          Commands = {
 |                                                                                            Do The Thing (mycommand) = Disabled
 |                                                                                          }
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Waiting for resource 'service' to enter one of the target state: Starting
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Finished waiting for resource 'service'. Resource state is 'Starting'.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Resource service/service changed state: Starting -> Running
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Starting health monitoring for resource 'service'.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Trace: Version: 3
 |                                                                                          Resource service/service update published:
 |                                                                                          ResourceType = CustomResource,
 |                                                                                          CreationTimeStamp = (null),
 |                                                                                          State = { Text = Running, Style = (null) },
 |                                                                                          HeathStatus = Healthy,
 |                                                                                          ResourceReady = False,
 |                                                                                          ExitCode = (null),
 |                                                                                          Urls = {  },
 |                                                                                          EnvironmentVariables = {
 |                                                                                          },
 |                                                                                          Properties = {
 |                                                                                          },
 |                                                                                          HealthReports = {
 |                                                                                          },
 |                                                                                          Commands = {
 |                                                                                            Do The Thing (mycommand) = Disabled
 |                                                                                          }
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Resource 'service' has no health checks to monitor.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Waiting for resource 'service' to enter one of the target state: Running
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Resource 'service' is ready.
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Publishing ResourceReadyEvent for 'service'.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Debug: Finished waiting for resource 'service'. Resource state is 'Running'.
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Waiting for ResourceReadyEvent for 'service'.
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: ResourceReadyEvent for 'service' completed.
 | [2025-03-15T23:36:09] Aspire.Hosting.Health.ResourceHealthCheckService Debug: Publishing the result of ResourceReadyEvent for 'service'.
 | [2025-03-15T23:36:09] Aspire.Hosting.ApplicationModel.ResourceNotificationService Trace: Version: 4
 |                                                                                          Resource service/service update published:
 |                                                                                          ResourceType = CustomResource,
 |                                                                                          CreationTimeStamp = (null),
 |                                                                                          State = { Text = Running, Style = (null) },
 |                                                                                          HeathStatus = Healthy,
 |                                                                                          ResourceReady = True,
 |                                                                                          ExitCode = (null),
 |                                                                                          Urls = {  },
 |                                                                                          EnvironmentVariables = {
 |                                                                                          },
 |                                                                                          Properties = {
 |                                                                                          },
 |                                                                                          HealthReports = {
 |                                                                                          },
 |                                                                                          Commands = {
 |                                                                                            Do The Thing (mycommand) = Disabled
 |                                                                                          }
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Cancellation received while watching Executable resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Stopped watching Executable resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Cancellation received while watching Container resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Stopped watching Container resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Cancellation received while watching Service resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Stopped watching Service resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Cancellation received while watching Endpoint resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.DcpExecutor Debug: Stopped watching Endpoint resources.
 | [2025-03-15T23:38:09] Aspire.Hosting.Dcp.dcp.start-apiserver.api-server.adminHttpHandler Information: API server changed status	{"OldStatus": "Running", "NewStatus": "CleaningResources"}
 | [2025-03-15T23:38:10] Aspire.Hosting.Dcp.dcp.start-apiserver.api-server.adminHttpHandler Information: API server changed status	{"OldStatus": "CleanupComplete", "NewStatus": "Stopping"}
 | [2025-03-15T23:38:10] Aspire.Hosting.Dcp.dcp.start-apiserver Information: Shutting down...
 | [2025-03-15T23:38:10] Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host Information: Service DCP controller host terminated gracefully
 | [2025-03-15T23:38:10] Aspire.Hosting.Dcp.dcp.start-apiserver Information: Shutdown complete.

Build Information

Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=981881
Build error leg or test failing: Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning
Pull request: N/A

Error Message

Fill the error message using step by step known issues guidance.

{
  "ErrorMessage": " at Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": true
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=981881
Error message validated: [System.TimeoutException : The operation at]
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 3/20/2025 12:28:18 AM UTC

Report

Build	Definition	Test	Pull Request
1030307	dotnet/aspire	Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning
1030294	dotnet/aspire	Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning
1030289	dotnet/aspire	Aspire.Hosting.Tests.WithHttpCommandTests.WithHttpCommand_EnablesCommandOnceResourceIsRunning

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	3

Report

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	0

Report for Quarantined runs

Recent runs:

OS	Last 100 runs
linux (43/43)	❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌
macos (2/2)	❌, ❌
windows (40/40)	❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌

-- Updated on 8/6/2025 1:59:38 PM UTC

Report for PRs and Rolling builds

Last 10 failures:

Run date	Test Name

Summary of the failures

Last 24 hrs	Last 7 days	Last 30 days
0	0	0

-- Updated on 8/6/2025 1:59:38 PM UTC

Report

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	0

Report for Quarantined runs

Recent runs:

OS	Last 100 runs
linux (43/43)	❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌
macos (2/2)	❌, ❌
windows (40/40)	❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌, ❌

-- Updated on 8/6/2025 1:59:38 PM UTC

Report for PRs and Rolling builds

Last 10 failures:

Run date	Test Name

Summary of the failures

Last 24 hrs	Last 7 days	Last 30 days
0	0	0

-- Updated on 8/6/2025 1:59:38 PM UTC

[radical]

This is failing often on PRs too.

[danmoseley]

timeout in Aspire.Hosting.Tests.DistributedApplicationTests.StartResourceForcesStart didn't match as it was
System.TimeoutException : The operation at /_/tests/Aspire.Hosting.Tests/DistributedApplicationTests.cs:141 timed out after reaching the limit of 120000ms.
but associating it here

wait is on a resource stopping.

aspire/tests/Aspire.Hosting.Tests/DistributedApplicationTests.cs

Lines 139 to 141 in 21bda16

	logger.LogInformation("Stop resource.");
	await orchestrator.StopResourceAsync(resourceEvent.ResourceId, CancellationToken.None).DefaultTimeout(TestConstants.LongTimeoutTimeSpan);
	await rns.WaitForResourceAsync(dependentResourceName, e => e.Snapshot.State?.Text == KnownResourceStates.Finished).DefaultTimeout(TestConstants.LongTimeoutTimeSpan);

[danmoseley]

| [2025-03-27T21:01:45] Aspire.Hosting.Health.ResourceHealthCheckService Trace: Health report status for 'force-resource-start-servicea' is Unhealthy.

I think it depends on serviceb which remained in state Unknown rather than going presumably Stopping->Stopped.

@karolz-ms can you suggest whether this might be orchestrator or more likely app host? Most of the logging here is orchestrator and I can't tell whether this is "no evidence of orchestrator problem, likely resource problem" or not.

https://dev.azure.com/dnceng-public/public/_build/results?buildId=996345&view=ms.vss-test-web.build-test-results-tab&runId=26589558&resultId=100476&paneView=attachments

[danmoseley]

Maybe we need more logging someplace to solve this kind of issue

[karolz-ms]

We might need to switch to a "make change, then verify" approach for resource stopping, similar to what I implemented for resource deletion and the other flaky test(s) via #8238. @danmoseley LMK if you guys need my help with that.