Skip to content

Preserve console log timestamps and normalize carriage-return output#16796

Merged
karolz-ms merged 10 commits into
mainfrom
copilot/investigate-console-log-timestamp-issues
May 6, 2026
Merged

Preserve console log timestamps and normalize carriage-return output#16796
karolz-ms merged 10 commits into
mainfrom
copilot/investigate-console-log-timestamp-issues

Conversation

Copy link
Copy Markdown
Contributor

Copilot AI commented May 5, 2026

Description

Aspire was dropping DCP system log timestamps when formatting [sys] messages, causing those entries to sort as timestamp-less console logs. Terminal-oriented output such as curl progress could also be split on standalone carriage returns, producing timestamp-less fragments in the dashboard.

  • System log timestamps

    • Parse and retain the DCP timestamp before formatting system log content.
    • Carry timestamp metadata through ResourceLogSource into DcpResourceWatcher.
    • Keep [sys] formatting as content-only; ordering no longer depends on reparsing the formatted line.
    • Track a RawContent field in ResourceLogEntry for DCP [sys] entries that includes the timestamp prefix, so LogEntry.RawContent retains timestamps in export/serialization paths (e.g. log archive export, dashboard export).
  • Carriage-return normalization

    • Replace ReadLineAsync ingestion with a reader that treats \n/\r\n as record terminators but preserves standalone \r long enough to normalize terminal overwrite behavior.
    • Normalize terminal progress output by keeping the final overwritten segment while preserving the original timestamp prefix.
    • Handle lines that end with a trailing \r by returning the last meaningful segment before it rather than an empty string.
    • ResourceLogEntry carries normalized content, error state, timestamp metadata, and (for system logs) raw timestamped content for export; it does not preserve the raw pre-normalized log line.
    • Apply NormalizeCarriageReturns after DCP parsing to avoid corrupting the tab-delimited structure (timestamp\tlevel\tcategory\tmessage) before the parser sees it. For successfully parsed DCP lines, normalization is applied only to the extracted message content; for all other lines, the full raw line is normalized as before.
  • Bug fixes

    • Fixed isError mutation in the per-line StreamLogsAsync loop: uses a per-iteration local so that a line failing DCP parsing no longer inherits the error classification of the previous parsed line.
  • Regression coverage

    • Added DCP parser tests for UTC and offset timestamps.
    • Added resource logging tests for [sys] timestamp preservation and curl-like progress output.
    • Added regression test for a DCP system log whose message body contains \r, verifying the entry retains the [sys] prefix and correct timestamp after the normalization-ordering fix.
    • Stabilized the carriage-return progress output regression test by waiting for all expected stdout records plus the certificate authority message that can arrive first in CI.

Example normalized input:

2024-08-19T06:10:01.000Z   0%\r 50%\r100%\n

is ingested as one timestamped console log entry:

2024-08-19T06:10:01.0000000Z 100%

I have manually verified that the logs look good when changes in this PR are applied.

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?

Copilot AI and others added 4 commits May 5, 2026 18:48
Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
@karolz-ms
Copy link
Copy Markdown
Contributor

@copilot change the code so that ResourceLogEntry does not preserve the raw log line content, it is unnecessary

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/3c9c7575-244c-44de-ab64-614b0f7e8973

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 5, 2026

@copilot change the code so that ResourceLogEntry does not preserve the raw log line content, it is unnecessary

Addressed in c29ae01 by removing raw log line preservation from ResourceLogEntry and using the normalized entry content when creating LogEntry instances.

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

  • pc2vsblobprodcus360.vsblob.vsassets.io
    • Triggering command: /usr/share/dotnet/dotnet dotnet build src/Aspire.Hosting/Aspire.Hosting.csproj --no-restore /p:SkipNativeBuild=true (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

Copilot AI requested a review from karolz-ms May 5, 2026 20:20
@karolz-ms karolz-ms marked this pull request as ready for review May 5, 2026 20:35
@karolz-ms karolz-ms requested a review from mitchdenny as a code owner May 5, 2026 20:35
Copilot AI review requested due to automatic review settings May 5, 2026 20:35
@github-actions
Copy link
Copy Markdown
Contributor

github-actions Bot commented May 5, 2026

🚀 Dogfood this PR with:

⚠️ WARNING: Do not do this without first carefully reviewing the code of this PR to satisfy yourself it is safe.

curl -fsSL https://raw.githubusercontent.com/microsoft/aspire/main/eng/scripts/get-aspire-cli-pr.sh | bash -s -- 16796

Or

  • Run remotely in PowerShell:
iex "& { $(irm https://raw.githubusercontent.com/microsoft/aspire/main/eng/scripts/get-aspire-cli-pr.ps1) } 16796"

Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Fixes log ordering issues in the hosting/DCP log ingestion pipeline by preserving timestamps for DCP [sys] messages and normalizing terminal-style carriage-return (\r) output so progress updates (e.g., curl) don’t produce timestamp-less fragments.

Changes:

  • Extend DcpLogParser to extract a timestamp from DCP-formatted log lines (UTC and offset forms) and add parser coverage.
  • Carry timestamp metadata through ResourceLogSource via a new ResourceLogEntry type, and prefer that timestamp in DcpResourceWatcher when creating LogEntry instances.
  • Replace ReadLineAsync ingestion with a custom reader that terminates on \n/\r\n while preserving standalone \r long enough to normalize overwrite behavior; add regression tests for sys timestamps and curl-like progress output.

Reviewed changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated 3 comments.

Show a summary per file
File Description
tests/Aspire.Hosting.Tests/Dcp/DcpLogParserTests.cs Adds coverage for UTC and offset timestamp parsing in DCP log lines.
tests/Aspire.Hosting.Tests/Dcp/DcpExecutorTests.cs Adds regression tests for [sys] timestamp preservation and \r progress normalization.
src/Aspire.Hosting/Dcp/ResourceLogSource.cs Introduces ResourceLogEntry with timestamp metadata and a custom line reader + \r normalization.
src/Aspire.Hosting/Dcp/DcpResourceWatcher.cs Consumes ResourceLogEntry timestamps to create LogEntry instances without re-parsing formatted [sys] content.
src/Aspire.Hosting/Dcp/DcpLogParser.cs Adds new TryParseDcpLog overloads that extract a timestamp from the first tab-delimited field.

Comment thread src/Aspire.Hosting/Dcp/ResourceLogSource.cs Outdated
Comment thread src/Aspire.Hosting/Dcp/ResourceLogSource.cs Outdated
Comment thread src/Aspire.Hosting/Dcp/DcpResourceWatcher.cs Outdated
karolz-ms and others added 2 commits May 5, 2026 17:09
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
…mestamps in export path

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/8225b8c8-ec38-47af-b955-f82f15695d9d

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 6, 2026

Just as a heads up, I was blocked by some firewall rules while working on your feedback. Expand below for details.

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

  • pc2vsblobprodcus360.vsblob.vsassets.io
    • Triggering command: /usr/share/dotnet/dotnet dotnet build src/Aspire.Hosting/Aspire.Hosting.csproj /p:SkipNativeBuild=true (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

@github-actions
Copy link
Copy Markdown
Contributor

github-actions Bot commented May 6, 2026

🎬 CLI E2E Test Recordings — 64 recordings uploaded (commit 8fbcfb7)

View all recordings
Status Test Recording
AddPackageInteractiveWhileAppHostRunningDetached ▶️ View Recording
AddPackageWhileAppHostRunningDetached ▶️ View Recording
AgentCommands_AllHelpOutputs_AreCorrect ▶️ View Recording
AgentInitCommand_DefaultSelection_InstallsSkillOnly ▶️ View Recording
AgentInitCommand_MigratesDeprecatedConfig ▶️ View Recording
AspireAddPackageVersionToDirectoryPackagesProps ▶️ View Recording
AspireUpdateRemovesAppHostPackageVersionFromDirectoryPackagesProps ▶️ View Recording
Banner_DisplayedOnFirstRun ▶️ View Recording
Banner_DisplayedWithExplicitFlag ▶️ View Recording
Banner_NotDisplayedWithNoLogoFlag ▶️ View Recording
ConfigSetGet_CreatesNestedJsonFormat ▶️ View Recording
CreateAndRunAspireStarterProject ▶️ View Recording
CreateAndRunAspireStarterProjectWithBundle ▶️ View Recording
CreateAndRunEmptyAppHostProject ▶️ View Recording
CreateAndRunJavaEmptyAppHostProject ▶️ View Recording
CreateAndRunJsReactProject ▶️ View Recording
CreateAndRunPythonReactProject ▶️ View Recording
CreateAndRunTypeScriptEmptyAppHostProject ▶️ View Recording
CreateAndRunTypeScriptStarterProject ▶️ View Recording
CreateJavaAppHostWithViteApp ▶️ View Recording
CreateTypeScriptAppHostWithViteApp_UsesConfiguredToolchain ▶️ View Recording
DashboardRunWithOtelTracesReturnsNoTraces ▶️ View Recording
DeployK8sBasicApiService ▶️ View Recording
DeployK8sWithGarnet ▶️ View Recording
DeployK8sWithMongoDB ▶️ View Recording
DeployK8sWithMySql ▶️ View Recording
DeployK8sWithPostgres ▶️ View Recording
DeployK8sWithRedis ▶️ View Recording
DeployK8sWithSqlServer ▶️ View Recording
DeployK8sWithValkey ▶️ View Recording
DeployTypeScriptAppToKubernetes ▶️ View Recording
DescribeCommandResolvesReplicaNames ▶️ View Recording
DescribeCommandShowsRunningResources ▶️ View Recording
DoListStepsShowsPipelineSteps ▶️ View Recording
DocsCommand_RendersInteractiveMarkdownFromLocalSource ▶️ View Recording
DoctorCommand_DetectsDeprecatedAgentConfig ▶️ View Recording
DoctorCommand_TypeScriptAppHostReportsMissingConfiguredToolchain ▶️ View Recording
DoctorCommand_WithSslCertDir_ShowsTrusted ▶️ View Recording
DoctorCommand_WithoutSslCertDir_ShowsPartiallyTrusted ▶️ View Recording
GlobalMigration_HandlesCommentsAndTrailingCommas ▶️ View Recording
GlobalMigration_HandlesMalformedLegacyJson ▶️ View Recording
GlobalMigration_PreservesAllValueTypes ▶️ View Recording
GlobalMigration_SkipsWhenNewConfigExists ▶️ View Recording
GlobalSettings_MigratedFromLegacyFormat ▶️ View Recording
InitTypeScriptAppHost_AugmentsExistingViteRepoAtRoot ▶️ View Recording
InteractiveCSharpInitCreatesExpectedFiles ▶️ View Recording
LatestCliCanStartStableChannelAppHost ▶️ View Recording
LatestCliCanStartStableChannelTypeScriptAppHost ▶️ View Recording
LegacySettingsMigration_AdjustsRelativeAppHostPath ▶️ View Recording
OtelLogsReturnsStructuredLogsFromStarterAppCore ▶️ View Recording
PsCommandListsRunningAppHost ▶️ View Recording
PsFormatJsonOutputsOnlyJsonToStdout ▶️ View Recording
RestoreGeneratesSdkFiles ▶️ View Recording
RestoreGeneratesSdkFiles_WithConfiguredToolchain ▶️ View Recording
RestoreRefreshesGeneratedSdkAfterAddingIntegration ▶️ View Recording
RestoreSupportsConfigOnlyHelperPackageAndCrossPackageTypes ▶️ View Recording
RunFromParentDirectory_UsesExistingConfigNearAppHost ▶️ View Recording
SecretCrudOnTypeScriptAppHost ▶️ View Recording
StagingChannel_ConfigureAndVerifySettings_ThenSwitchChannels ▶️ View Recording
StartAndWaitForTypeScriptSqlServerAppHostWithNativeAssets ▶️ View Recording
StopAllAppHostsFromAppHostDirectory ▶️ View Recording
StopNonInteractiveSingleAppHost ▶️ View Recording
StopWithNoRunningAppHostExitsSuccessfully ▶️ View Recording
UnAwaitedChainsCompileWithAutoResolvePromises ▶️ View Recording

📹 Recordings uploaded automatically from CI run #25409294198

Copy link
Copy Markdown
Member

@JamesNK JamesNK left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good overall — the timestamp preservation, CR normalization, isError per-iteration fix, and RawContent plumbing are well done. One potential correctness issue noted inline (normalization ordering vs. DCP parsing for the system stream).

Comment thread src/Aspire.Hosting/Dcp/ResourceLogSource.cs
Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 6, 2026

Just as a heads up, I was blocked by some firewall rules while working on your feedback. Expand below for details.

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

  • pc2vsblobprodcus360.vsblob.vsassets.io
    • Triggering command: /usr/share/dotnet/dotnet dotnet build src/Aspire.Hosting/Aspire.Hosting.csproj (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

@karolz-ms
Copy link
Copy Markdown
Contributor

@copilot The ResourceLogging_CarriageReturnProgressOutput_NormalizesOverwrittenLines test in DcpExecutorTests suite failed in the last CI run. Investigate and fix as appropriate

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/56825262-4c19-4588-a586-1f93ce482670

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Copy link
Copy Markdown
Contributor Author

Copilot AI commented May 6, 2026

@copilot The ResourceLogging_CarriageReturnProgressOutput_NormalizesOverwrittenLines test in DcpExecutorTests suite failed in the last CI run. Investigate and fix as appropriate

Fixed in 8915099. The test was waiting for only 3 entries, but the certificate authority log can arrive before the 3 stdout records in CI, so the captured batch could miss the final Done line. It now waits for 4 entries (3 stdout records + the certificate authority message). Validated with the targeted test and DcpExecutorTests locally.

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

  • https://api.github.com/graphql
    • Triggering command: /usr/bin/gh gh pr list --repo microsoft/aspire --head copilot/investigate-console-log-timestamp-issues --json number,url,headRefName,statusCheckRollup --limit 5 (http block)
  • https://api.github.com/repos/microsoft/aspire/pulls
    • Triggering command: /usr/bin/gh gh api repos/microsoft/aspire/pulls?head=microsoft:copilot/investigate-console-log-timestamp-issues&amp;state=open --jq .[] | {number,url:.html_url,head:.head.ref} (http block)
    • Triggering command: /usr/bin/gh gh api -H Accept: application/vnd.github&#43;json repos/microsoft/aspire/pulls?head=microsoft:copilot/investigate-console-log-timestamp-issues&amp;state=open (http block)
  • pc2vsblobprodcus360.vsblob.vsassets.io
    • Triggering command: /usr/share/dotnet/dotnet dotnet test --project tests/Aspire.Hosting.Tests/Aspire.Hosting.Tests.csproj --no-launch-profile -- --filter-method *.ResourceLogging_CarriageReturnProgressOutput_NormalizesOverwrittenLines --filter-not-trait quarantined=true --filter-not-trait outerloop=true (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

@karolz-ms karolz-ms merged commit f23abf4 into main May 6, 2026
563 of 573 checks passed
@github-actions github-actions Bot added this to the 13.4 milestone May 6, 2026
nellshamrell pushed a commit to nellshamrell/aspire that referenced this pull request May 18, 2026
…icrosoft#16796)

* Preserve DCP log timestamps and normalize carriage returns

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Adjust carriage return regression assertion

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Preserve original raw log content

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Clarify log parsing helper names

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/db6cb5cb-e08f-41ec-9cab-d1b240212f6e

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Remove raw content from resource log entries

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/3c9c7575-244c-44de-ab64-614b0f7e8973

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Handle lines that end with CR

Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>

* Track RawContent in ResourceLogEntry for [sys] entries to preserve timestamps in export path

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/8225b8c8-ec38-47af-b955-f82f15695d9d

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Fix normalization ordering: try DCP parsing before CR normalization

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/7237c511-0243-48a5-b39e-7e33c098d724

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Add clarifying comment for targetLogCount in system log CR test

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/7237c511-0243-48a5-b39e-7e33c098d724

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

* Stabilize carriage return resource logging test

Agent-Logs-Url: https://github.com/microsoft/aspire/sessions/56825262-4c19-4588-a586-1f93ce482670

Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>

---------

Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com>
Co-authored-by: karolz-ms <15271049+karolz-ms@users.noreply.github.com>
Co-authored-by: Karol Zadora-Przylecki <karolz@microsoft.com>
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants