Flush logs before terminal resource notifications - #18539
Conversation
Fast-failing resources can publish a terminal state before DCP logs have been forwarded to the host logger. Flush current logs to active subscribers before terminal notifications and dedupe overlap with the follow stream. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
|
🚀 Dogfood this PR with:
curl -fsSL https://raw.githubusercontent.com/microsoft/aspire/main/eng/scripts/get-aspire-cli-pr.sh | bash -s -- 18539Or
iex "& { $(irm https://raw.githubusercontent.com/microsoft/aspire/main/eng/scripts/get-aspire-cli-pr.ps1) } 18539" |
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
Pull request overview
This PR fixes missing crashing-container/executable logs in DistributedApplicationTestingBuilder scenarios (issue #10218). Fast-failing resources could reach a terminal state (Exited/FailedToStart/Finished) before DCP's follow log stream forwarded stderr/stdout to the host logger, so WaitForResourceAsync could return before the relevant logs were visible. The change flushes a non-follow DCP log snapshot to active resource-log subscribers before publishing the terminal state notification, and routes ResourceLoggerForwarderService through a new internal synchronous Subscribe path that guarantees those logs reach ILogger before the terminal notification unblocks waiters.
Changes:
- Adds an internal synchronous
Subscribe/WaitForCompletionAsync/HasActiveSubscribers/AddLogssurface toResourceLoggerService, with occurrence-based dedup so overlapping snapshot/follow log batches don't duplicate while preserving repeated identical lines. DcpResourceWatcherflushes afollow: falselog snapshot before publishing terminalOnResourceChangedContext, gated on logs being available and an active subscriber;ResourceLoggerForwarderServiceswitches from asyncWatchAsyncto synchronousSubscribe+WaitForCompletionAsync.- Adds extensive unit/integration tests covering subscription ordering, completion, dedup, concurrency, terminal-flush ordering, and executable/container startup-failure log visibility.
Show a summary per file
| File | Description |
|---|---|
src/Aspire.Hosting/ApplicationModel/ResourceLoggerService.cs |
Adds internal Subscribe, WaitForCompletionAsync, HasActiveSubscribers, AddLogs (with dedup); completion signaling in Complete(); removes GetInternalLogger. |
src/Aspire.Hosting/Dcp/DcpResourceWatcher.cs |
Flushes a non-follow log snapshot before publishing terminal state; extracts HasLogsAvailable; follow stream now uses AddLogEntries(skipExisting:true). |
src/Aspire.Hosting/ResourceLoggerForwarderService.cs |
Switches forwarding to synchronous Subscribe + WaitForCompletionAsync; broadens caught cancellation to OperationCanceledException. |
tests/Aspire.Hosting.Tests/ResourceLoggerServiceTests.cs |
Adds tests for dedup, subscription ordering, completion, active-subscriber state, and concurrency stress. |
tests/Aspire.Hosting.Tests/Dcp/DcpExecutorTests.cs |
Adds test asserting terminal-state snapshot is flushed before the terminal notification. |
tests/Aspire.Hosting.Tests/Dcp/TestKubernetesService.cs |
Extends fake to expose the follow flag to log-stream callbacks. |
tests/Aspire.Hosting.Tests/ResourceFailureLoggingTests.cs |
Adds ExecutableDoesNotExist failure-log visibility test plus assertion helpers. |
tests/Aspire.Hosting.Containers.Tests/ResourceFailureLoggingTests.cs |
Adds ContainerExitsImmediatelyAfterStart failure-log visibility test plus assertion helpers. |
Review details
- Files reviewed: 8/8 changed files
- Comments generated: 0
- Review effort level: Medium
|
Retrying the failed CI jobs for this pull request from the CI run attempt. The rerun is being tracked in the rerun attempt. |
PR Testing ReportPR Information
Artifact Version Verification
Changes AnalyzedFiles Changed
Change Categories
Root cause / fix: Fast-failing containers and executables could reach a terminal state ( Test Scenarios ExecutedScenario 1: Fast-failing container logs captured (CLI dogfood E2E)Objective: Confirm a container that prints output then immediately exits non-zero has its stdout/stderr captured and visible via the real PR CLI. Steps:
Evidence (
Scenario 2: Fast-failing executable logs captured (CLI dogfood E2E — unhappy path)Objective: Confirm an executable resource that exits immediately with a non-zero code surfaces its stdout/stderr. Steps:
Evidence (
Expected Unhappy-Path Outcome: Executable exits non-zero ( Scenario 3: PR source tests — deterministic fix validationObjective: Run the PR's own unit/integration tests, which directly assert that resource logs are present before the terminal state unblocks the wait (the race the PR fixes). Built from an isolated worktree at PR head. Steps:
New behavior tests confirmed present and passing (in Stress validation (race-condition determinism): The 3 concurrency tests
Summary
Overall Result✅ PR VERIFIED The fix behaves as described: fast-failing containers and executables now surface their stdout/stderr through the real PR CLI's Recommendations
|
David Pine (IEvangelist)
left a comment
There was a problem hiding this comment.
Reviewed the log-ordering changes and the accompanying tests. The fix and its coverage (snapshot flushed exactly once before the terminal notification, dedup-by-occurrence, concurrency, continuous line numbering, completion semantics) look solid.
Two notes left inline:
- Performance concern — the per-batch dedup (
skipExisting: true) now runs for every resource's full lifetime rather than only around the one-time terminal flush, adding O(backlog) work per follow batch whenever subscribers are attached (the always-on forwarder always is). - Minor correctness note — a related low-confidence edge case where cross-batch identical lines could be deduped.
Approving — neither blocks merge, but #1 is worth addressing for chatty resources.
Summary: 1 performance concern, 1 minor correctness note.
PR Testing ReportPR Information
Artifact Version Verification
Changes AnalyzedFiles Changed
Change Categories
Test Scenarios ExecutedScenario 1: Dogfood artifact verificationObjective: Verify that testing used the PR CLI/package artifact for PR #18539, not a local or channel install. Steps:
Evidence:
Observations:
Scenario 2: Fresh AppHost fast-failing container logsObjective: Verify a fresh AppHost using the PR package hive exposes stderr from a fast-failing container after Steps:
Evidence:
Observations:
Scenario 3: Fresh AppHost fast-failing executable logsObjective: Verify a fresh AppHost using the PR package hive exposes stderr from a fast-failing executable after Steps:
Evidence:
Observations:
Scenario 4: Source regression testsObjective: Verify the focused unit, DCP ordering, executable failure, and Docker container failure tests added or affected by the PR. Steps:
Evidence:
Observations:
Setup Observations
Summary
Overall Result✅ PR VERIFIED Recommendations
|
Avoid rebuilding the full resource log backlog for every follow-stream batch by tracking only the snapshot entries flushed before terminal notifications. This keeps steady-state follow streaming on the normal path while still skipping the one-time snapshot/follow overlap. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
This comment has been minimized.
This comment has been minimized.
Karol Zadora-Przylecki (karolz-ms)
left a comment
There was a problem hiding this comment.
See my suggestion for DcpResourceWatcher--you probably want a full test pass again after that
DCP only guarantees complete log drain for follow streams, so use a follow stream before publishing normal terminal states. Keep FailedToStart on the snapshot path because no process stream may complete when the executable never starts. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
This comment has been minimized.
This comment has been minimized.
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
This comment has been minimized.
This comment has been minimized.
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Tests selector (audit mode)The full test matrix and all jobs still run in audit mode. The tests and jobs below are what selective CI would run under enforcement. 51 / 98 test projects · 5 jobs, from 10 changed files. Selected test projects (51 / 98)
Selected jobs (5)
How these were chosen — grouped by what changed
🔧 show 43
🔧 📦 affected project 📦 affected project 🧪 🧪 🧪 🧪 🧪 Job reasons
Selection computed for commit |
|
A docs PR was drafted on branch Triggered signals: Intended change: added a new "Diagnose resource startup failures" section to See the workflow run for details: https://github.com/microsoft/aspire/actions/runs/28404445919 |
Description
Fast-failing containers and executables could reach a terminal state before DCP stdout/stderr logs were forwarded to the host logger. That made
DistributedApplicationTestingBuilderfailures difficult to diagnose becauseWaitForResourceAsynccould return before the relevant logs were visible.This change flushes current DCP logs to active resource-log subscribers before terminal state notifications are published. The synchronous subscription path is internal and used by
ResourceLoggerForwarderService;WatchAsynckeeps its existing async stream semantics for dashboard/backchannel consumers. Snapshot/follow overlap is deduped with count-based matching so repeated identical log lines are preserved.User-facing behavior
When a resource fails during startup, test code that waits for the resource to fail can include the container or executable stdout/stderr in captured host logs.
Validation
./restore.sh && ./build.sh --build /p:SkipNativeBuild=trueResourceLoggerServiceTests, including repeated stress runsResourceLoggerForwarderServiceTestsResourceFailureLoggingTests.ExecutableDoesNotExistResourceFailureLoggingTests.ContainerExitsImmediatelyAfterStartaspire wait ... --status down, thenaspire logsshowedaspire-cli-fast-fail-e2eFixes: #10218
Checklist
<remarks />and<code />elements on your triple slash comments?