Failing test WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost

[radical]

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=771389
Build error leg or test failing: Aspire.Hosting.Containers.Tests.WithDockerfileTests.Aspire.Hosting.Containers.Tests.WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost
Pull request: #5243

Error Message

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

{
  "ErrorMessage": "Aspire.Hosting.Containers.Tests.WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost [FAIL]",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

cc @mitchdenny @eerhardt @sebastienros

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=771389
Error message validated: [Aspire.Hosting.Containers.Tests.WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost [FAIL]]
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 8/9/2024 8:31:17 PM UTC

Report

Build	Definition	Test	Pull Request
935717	dotnet/aspire	Aspire.Hosting.Containers.Tests.WorkItemExecution	#7335
916583	dotnet/aspire	Aspire.Hosting.Containers.Tests.WorkItemExecution	#5878

Summary

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

[radical]

The output from the app:

[2024-08-09T19:27:52] Aspire.Hosting.DistributedApplication Information: Aspire version: 8.1.1-ci
[2024-08-09T19:27:52] Aspire.Hosting.DistributedApplication Information: Distributed application starting.
[2024-08-09T19:27:52] Aspire.Hosting.DistributedApplication Information: Application host directory is: /mnt/vss/_work/1/s/tests/Aspire.Hosting.Tests
[2024-08-09T19:27:52] Aspire.Hosting.Dcp.DcpHostService Information: Starting DCP with arguments: start-apiserver --monitor 2335 --detach --kubeconfig "/datadisks/disk1/work/C84B0A39/t/aspire.uyBVUT/kubeconfig"
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.start-apiserver.api-server Information: Starting API server...
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.start-apiserver.api-server Information: API server started	{"Address": "127.0.0.1", "Port": 42539}
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.start-apiserver.dcp-host Information: Starting DCP controller host
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.start-apiserver.dcp-host Information: Started all services	{"count": 1}
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.dcpctrl.IdeExecutableRunner Information: Executables cannot be started via IDE: missing required environment variable 'DEBUG_SESSION_PORT'
[2024-08-09T19:27:54] Aspire.Hosting.Dcp.dcpctrl Information: starting controller manager
[2024-08-09T19:27:54] Aspire.Hosting.DistributedApplication Information: Distributed application started. Press Ctrl+C to shut down.
[2024-08-09T19:28:03] Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler Information: service /testcontainer-7ea59c5 is now in state Ready	{"ServiceName": {"name":"testcontainer-7ea59c5"}, "Reconciliation": 4}
[2024-08-09T19:28:03] System.Net.Http.HttpClient.Default.LogicalHandler Information: Start processing HTTP request GET http://localhost:41427/aspire.html
[2024-08-09T19:28:03] System.Net.Http.HttpClient.Default.ClientHandler Information: Sending HTTP request GET http://localhost:41427/aspire.html
[2024-08-09T19:28:03] System.Net.Http.HttpClient.Default.ClientHandler Information: Received HTTP response headers after 2.38ms - 200
[2024-08-09T19:28:03] Polly Information: Execution attempt. Source: '-standard//Standard-Retry', Operation Key: '', Result: '200', Handled: 'False', Attempt: '0', Execution Time: 4.1763ms
[2024-08-09T19:28:03] System.Net.Http.HttpClient.Default.LogicalHandler Information: End processing HTTP request after 6.8643ms - 200

The test is looking for this string:

aspire/tests/Aspire.Hosting.Containers.Tests/WithDockerfileTests.cs

Lines 81 to 83 in 972f9a9

	// Just looking for a common message in Docker build output.
	Assert.Contains(logs, log => log.Message.Contains("load build definition from Dockerfile"));

But I don't see any messages about the image being built in the logs.

When I run the test locally:

info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      2:
info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      3: 2024-08-09T20:28:53.413Z #1 [internal] load build definition from Dockerfile
info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      4: 2024-08-09T20:28:53.413Z #1 transferring dockerfile: 562B done
info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      5: 2024-08-09T20:28:53.413Z #1 DONE 0.0s
info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      6:
info: Aspire.Hosting.Tests.Resources.testcontainer[0]
      7: 2024-08-09T20:28:53.413Z #2 [internal] load metadata for mcr.microsoft.com/cbl-mariner/base/nginx:1.22
...

Another thing I observed was that the name of the image being created stays the same across multiple runs like testcontainer-image-1ca45e42d1f2a1d1ae8aca2063aa3724906f4788. Though in local runs, the build does seem to run every time.

1. Is this a case of the logs not showing up, or a build not happening at all? Why did it happen on this unrelated PR though?

[mitchdenny]

I am wondering wither the Docker engine is crashing.