Build resource logging into Aspire.Hosting

[davidfowl]

Description

• ResourceLoggerForwarderService needs to be added before the DcpHostedService is added so that it can subscribe to the resource notification service and capture logs for all resources (before waiting for services to complete).
• Added EnableResourceLogging to DistributedApplicationOptions
• Removed all of the code duplication and instead set the flag in places where it was being used.

Fixes #6791

PS: I found this while debugging #5821

Checklist

• Is this feature complete?
  • Yes. Ready to ship.
  • No. Follow-up changes expected.
• Are you including unit tests for the changes and scenario tests if relevant?
  • Yes
  • No
• Did you add public API?
  • Yes
    • If yes, did you have an API Review for it?
      • Yes
      • No
    • Did you add <remarks /> and <code /> elements on your triple slash comments?
      • Yes
      • No
  • No
• Does the change make any security assumptions or guarantees?
  • Yes
    • If yes, have you done a threat model and had a security review?
      • Yes
      • No
  • No
• Does the change require an update in our Aspire docs?
  • Yes
    • Link to aspire-docs issue:
  • No

[radical]

What extra logs would this capture that were being missed earlier?

[davidfowl]

What extra logs would this capture that were being missed earlier?

The tests using WaitFor sometimes hang and get collect no output because the ApplicationExecutor.StartAsync won't return until all of the services have been spun up completely. I think we'll need to change this behavior in general, but this also makes pushing logs through the ILogger a first class feature.

[mitchdenny]

LGTM

[eerhardt]

LGTM. Might want to consider writing a test that ensures it works correctly.

[radical]

Failure looks relevant:

  Failed Aspire.Hosting.Containers.Tests.WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost [7 s]
  Error Message:
   Assert.Contains() Failure: Filter not matched in collection
Collection: [[51:03.553,  info] Aspire version: 9.0.0-ci, [51:03.554,  info] Distributed application starting., [51:03.555,  info] Application host directory is: /mnt/vss/_work/1/s/tests/Aspire.Hosting.Tests, [51:03.704,  info] Starting DCP with arguments: start-apiserver --monitor 110882 --detach --kubeconfig "/datadisks/disk1/work/AA820940/t/aspire.MrTnGb/kubeconfig", [51:05.318,  info] Starting API server..., ···]
  Stack Trace:
     at Aspire.Hosting.Containers.Tests.WithDockerfileTests.ContainerBuildLogsAreStreamedToAppHost() in /_/tests/Aspire.Hosting.Containers.Tests/WithDockerfileTests.cs:line 81
--- End of stack trace from previous location ---
  Standard Output Messages:
 | [2024-09-24T06:51:03] Aspire.Hosting.DistributedApplication Information: Aspire version: 9.0.0-ci
 | [2024-09-24T06:51:03] Aspire.Hosting.DistributedApplication Information: Distributed application starting.
 | [2024-09-24T06:51:03] Aspire.Hosting.DistributedApplication Information: Application host directory is: /mnt/vss/_work/1/s/tests/Aspire.Hosting.Tests
 | [2024-09-24T06:51:03] Aspire.Hosting.Dcp.DcpHostService Information: Starting DCP with arguments: start-apiserver --monitor 110882 --detach --kubeconfig "/datadisks/disk1/work/AA820940/t/aspire.MrTnGb/kubeconfig"
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.start-apiserver.api-server Information: Starting API server...
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.start-apiserver.api-server Information: API server started	{"Address": "127.0.0.1", "Port": 46779}
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.start-apiserver.dcp-host Information: Starting DCP controller host
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.start-apiserver.dcp-host Information: Started all services	{"count": 1}
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.dcpctrl.IdeExecutableRunner Information: Executables cannot be started via IDE: missing required environment variable 'DEBUG_SESSION_PORT'
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.dcpctrl Information: starting controller manager
 | [2024-09-24T06:51:05] Aspire.Hosting.DistributedApplication Information: Distributed application started. Press Ctrl+C to shut down.
 | [2024-09-24T06:51:05] Aspire.Hosting.Dcp.dcpctrl.NetworkReconciler Information: network created	{"NetworkName": {"name":"default-aspire-network"}, "Reconciliation": 2, "Network": "default-aspire-network-glccs3r380"}
 | [2024-09-24T06:51:10] Aspire.Hosting.Dcp.dcpctrl.ContainerReconciler Information: Added new ContainerNetworkConnection	{"Container": {"name":"testcontainer-qrhwsqdg-6411e65b"}, "Reconciliation": 7, "Container": "9f00ff396b1fb4b3402fadd236aad486b1e8d2c2e3806a73115b7710918babf1", "ContainerNetworkConnection": "/testcontainer-qrhwsqdg-6411e65b-default-aspire-network-t3uk366i14"}
 | [2024-09-24T06:51:10] Aspire.Hosting.Dcp.dcpctrl.NetworkReconciler Information: connected a container to the network	{"NetworkName": {"name":"default-aspire-network"}, "Reconciliation": 4, "Container": "9f00ff396b1fb4b3402fadd236aad486b1e8d2c2e3806a73115b7710918babf1", "Network": "default-aspire-network-glccs3r380"}
 | [2024-09-24T06:51:11] System.Net.Http.HttpClient.Default.LogicalHandler Information: Start processing HTTP request GET http://localhost:46295/aspire.html
 | [2024-09-24T06:51:11] System.Net.Http.HttpClient.Default.ClientHandler Information: Sending HTTP request GET http://localhost:46295/aspire.html
 | [2024-09-24T06:51:11] Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler Information: service /testcontainer-6411e65b is now in state Ready	{"ServiceName": {"name":"testcontainer-6411e65b"}, "Reconciliation": 4}
 | [2024-09-24T06:51:11] System.Net.Http.HttpClient.Default.ClientHandler Information: Received HTTP response headers after 29.2548ms - 200
 | [2024-09-24T06:51:11] Polly Information: Execution attempt. Source: '-standard//Standard-Retry', Operation Key: '', Result: '200', Handled: 'False', Attempt: '0', Execution Time: 33.5908ms
 | [2024-09-24T06:51:11] System.Net.Http.HttpClient.Default.LogicalHandler Information: End processing HTTP request after 46.9769ms - 200

[davidfowl]

yea been debugging it

[davidfowl]

/azp run

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[radical]

/azp run

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[davidfowl]

I need to chase down the race or bug.

[eerhardt]

Is this making it for 9.0.0?

[davidfowl]

Highly, unlikely, unless I figure out the bug tonight 😄. There's a single test failuree