Simplify timestamp display in console logs (#5455)

JamesNK · web-flow · commit f5d9f80c3c66 · 2024-08-27T07:30:32.000Z
diff --git a/src/Aspire.Dashboard/Components/Controls/LogViewer.razor b/src/Aspire.Dashboard/Components/Controls/LogViewer.razor
@@ -1,5 +1,7 @@
 ﻿@namespace Aspire.Dashboard.Components
+@using System.Globalization
 @using Aspire.Dashboard.Model
+@using Aspire.Dashboard.Utils
 @using Aspire.Hosting.ConsoleLogs
 @inject IJSRuntime JS
 @implements IAsyncDisposable
@@ -12,15 +14,20 @@
                     <span class="log-line-area" role="log">
                         <span class="log-line-number">@context.LineNumber</span>
                         <span class="log-content">
+                            @{
+                                var hasPrefix = false;
+                            }
                             @if (context.Timestamp is { } timestamp)
                             {
-                                <span class="timestamp">@GetDisplayTimestamp(timestamp)</span>
+                                hasPrefix = true;
+                                <span class="timestamp" title="@FormatHelpers.FormatDateTime(TimeProvider, timestamp, MillisecondsDisplay.Full, CultureInfo.CurrentCulture)">@GetDisplayTimestamp(timestamp)</span>
                             }
                             @if (context.Type == LogEntryType.Error)
                             {
+                                hasPrefix = true;
                                 <fluent-badge appearance="accent">stderr</fluent-badge>
                             }
-                            @((MarkupString)(context.Content ?? string.Empty))
+                            @((MarkupString)((hasPrefix ? "&#32;" : string.Empty) + (context.Content ?? string.Empty)))
                         </span>
                     </span>
                 </div>
diff --git a/src/Aspire.Dashboard/Components/Controls/LogViewer.razor.cs b/src/Aspire.Dashboard/Components/Controls/LogViewer.razor.cs
@@ -65,7 +65,7 @@ private void OnBrowserResize(object? o, EventArgs args)
         });
     }
 
-    internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IReadOnlyList<ResourceLogLine>> batches, bool convertTimestampsFromUtc)
+    internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IReadOnlyList<ResourceLogLine>> batches, bool convertTimestampsFromUtc = true)
     {
         ResourceName = resourceName;
 
@@ -102,12 +102,9 @@ internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IRea
 
     private string GetDisplayTimestamp(DateTimeOffset timestamp)
     {
-        if (_convertTimestampsFromUtc)
-        {
-            timestamp = TimeProvider.ToLocal(timestamp);
-        }
+        var date = _convertTimestampsFromUtc ? TimeProvider.ToLocal(timestamp) : timestamp.DateTime;
 
-        return timestamp.ToString(KnownFormats.ConsoleLogsTimestampFormat, CultureInfo.InvariantCulture);
+        return date.ToString(KnownFormats.ConsoleLogsUITimestampFormat, CultureInfo.InvariantCulture);
     }
 
     internal async Task ClearLogsAsync()
diff --git a/src/Aspire.Dashboard/Components/Pages/ConsoleLogs.razor.cs b/src/Aspire.Dashboard/Components/Pages/ConsoleLogs.razor.cs
@@ -278,10 +278,7 @@ private async ValueTask LoadLogsAsync()
 
             if (subscription is not null)
             {
-                var task = _logViewer.SetLogSourceAsync(
-                    PageViewModel.SelectedResource.Name,
-                    subscription,
-                    convertTimestampsFromUtc: PageViewModel.SelectedResource.IsContainer());
+                var task = _logViewer.SetLogSourceAsync(PageViewModel.SelectedResource.Name, subscription);
 
                 PageViewModel.InitialisedSuccessfully = true;
                 PageViewModel.Status = Loc[nameof(Dashboard.Resources.ConsoleLogs.ConsoleLogsWatchingLogs)];
diff --git a/src/Aspire.Hosting/Dashboard/ConsoleLogsConfigurationExtensions.cs b/src/Aspire.Hosting/Dashboard/ConsoleLogsConfigurationExtensions.cs
@@ -18,9 +18,8 @@ internal static IResourceBuilder<T> ConfigureConsoleLogs<T>(this IResourceBuilde
             // Enable ANSI Control Sequences for colors in Output Redirection
             context.EnvironmentVariables["DOTNET_SYSTEM_CONSOLE_ALLOW_ANSI_COLOR_REDIRECTION"] = "true";
 
-            // Enable Simple Console Logger Formatting with a UTC timestamp similar to RFC3339Nano that Docker generates
+            // Enable Simple Console Logger Formatting
             context.EnvironmentVariables["LOGGING__CONSOLE__FORMATTERNAME"] = "simple";
-            context.EnvironmentVariables["LOGGING__CONSOLE__FORMATTEROPTIONS__TIMESTAMPFORMAT"] = $"{KnownFormats.ConsoleLogsTimestampFormat} ";
         });
     }
 }
diff --git a/src/Shared/KnownFormats.cs b/src/Shared/KnownFormats.cs
@@ -6,8 +6,13 @@ namespace Aspire;
 internal static class KnownFormats
 {
     /// <summary>
-    /// Format is passed to apps as an env var to override logging's timestamp format.
-    /// It is also used to parse logs when they're displayed in the dashboard's console logs UI.
+    /// Internal timestamp format that is used to add the timestamp to a log line.
+    /// Preserve second precision and timezone information.
     /// </summary>
-    public const string ConsoleLogsTimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffffff";
+    public const string ConsoleLogsTimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffffffK";
+
+    /// <summary>
+    /// UI timestamp displayed on the console logs UI.
+    /// </summary>
+    public const string ConsoleLogsUITimestampFormat = "yyyy-MM-ddTHH:mm:ss";
 }
diff --git a/tests/Aspire.Hosting.Testing.Tests/ResourceLoggerForwarderServiceTests.cs b/tests/Aspire.Hosting.Testing.Tests/ResourceLoggerForwarderServiceTests.cs
@@ -119,12 +119,12 @@ public async Task ResourceLogsAreForwardedToHostLogging()
         // Category is derived from the application name and resource name
         // Logs sent at information level or lower are logged as information, otherwise they are logged as error
         Assert.Collection(hostLogs,
-            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("1: 2000-12-29T20:59:59.0000000 Test trace message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
-            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("2: 2000-12-29T20:59:59.0000000 Test debug message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
-            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("3: 2000-12-29T20:59:59.0000000 Test information message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
-            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("4: 2000-12-29T20:59:59.0000000 Test warning message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
-            log => { Assert.Equal(LogLevel.Error, log.Level); Assert.Equal("5: 2000-12-29T20:59:59.0000000 Test error message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
-            log => { Assert.Equal(LogLevel.Error, log.Level); Assert.Equal("6: 2000-12-29T20:59:59.0000000 Test critical message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); });
+            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("1: 2000-12-29T20:59:59.0000000Z Test trace message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
+            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("2: 2000-12-29T20:59:59.0000000Z Test debug message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
+            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("3: 2000-12-29T20:59:59.0000000Z Test information message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
+            log => { Assert.Equal(LogLevel.Information, log.Level); Assert.Equal("4: 2000-12-29T20:59:59.0000000Z Test warning message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
+            log => { Assert.Equal(LogLevel.Error, log.Level); Assert.Equal("5: 2000-12-29T20:59:59.0000000Z Test error message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); },
+            log => { Assert.Equal(LogLevel.Error, log.Level); Assert.Equal("6: 2000-12-29T20:59:59.0000000Z Test critical message", log.Message); Assert.Equal("TestApp.AppHost.Resources.myresource", log.Category); });
     }
 
     private sealed class CustomResource(string name) : Resource(name)
diff --git a/tests/Aspire.Hosting.Tests/Dcp/ApplicationExecutorTests.cs b/tests/Aspire.Hosting.Tests/Dcp/ApplicationExecutorTests.cs
@@ -424,7 +424,7 @@ public async Task ResourceLogging_MultipleStreams_StreamedOverTime()
         await pipes.StandardOut.Writer.WriteAsync(Encoding.UTF8.GetBytes("2024-08-19T06:10:33.473275911Z Hello world" + Environment.NewLine));
         Assert.True(await moveNextTask);
         var logLine = watchLogsEnumerator.Current.Single();
-        Assert.Equal("2024-08-19T06:10:33.4732759 Hello world", logLine.Content);
+        Assert.Equal("2024-08-19T06:10:33.4732759Z Hello world", logLine.Content);
         Assert.Equal(1, logLine.LineNumber);
         Assert.False(logLine.IsErrorMessage);
 
@@ -435,7 +435,7 @@ public async Task ResourceLogging_MultipleStreams_StreamedOverTime()
         await pipes.StandardErr.Writer.WriteAsync(Encoding.UTF8.GetBytes("2024-08-19T06:10:32.661Z Next" + Environment.NewLine));
         Assert.True(await moveNextTask);
         logLine = watchLogsEnumerator.Current.Single();
-        Assert.Equal("2024-08-19T06:10:32.6610000 Next", logLine.Content);
+        Assert.Equal("2024-08-19T06:10:32.6610000Z Next", logLine.Content);
         Assert.Equal(2, logLine.LineNumber);
         Assert.True(logLine.IsErrorMessage);
 
diff --git a/tests/Aspire.Hosting.Tests/ProjectResourceTests.cs b/tests/Aspire.Hosting.Tests/ProjectResourceTests.cs
@@ -163,11 +163,6 @@ public async Task AddProjectAddsEnvironmentVariablesAndServiceMetadata()
             {
                 Assert.Equal("LOGGING__CONSOLE__FORMATTERNAME", env.Key);
                 Assert.Equal("simple", env.Value);
-            },
-            env =>
-            {
-                Assert.Equal("LOGGING__CONSOLE__FORMATTEROPTIONS__TIMESTAMPFORMAT", env.Key);
-                Assert.Equal("yyyy-MM-ddTHH:mm:ss.fffffff ", env.Value);
             });
     }
 
diff --git a/tests/Aspire.Hosting.Tests/ResourceLoggerServiceTests.cs b/tests/Aspire.Hosting.Tests/ResourceLoggerServiceTests.cs
@@ -31,10 +31,10 @@ public async Task AddingResourceLoggerAnnotationAllowsLogging()
         // Wait for logs to be read
         var allLogs = await logsLoop.WaitAsync(TimeSpan.FromSeconds(15));
 
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, world!", allLogs[0].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, world!", allLogs[0].Content);
         Assert.False(allLogs[0].IsErrorMessage);
 
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, error!", allLogs[1].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, error!", allLogs[1].Content);
         Assert.True(allLogs[1].IsErrorMessage);
 
         // New sub should get the previous logs
@@ -45,8 +45,8 @@ public async Task AddingResourceLoggerAnnotationAllowsLogging()
         allLogs = await logsLoop.WaitAsync(TimeSpan.FromSeconds(15));
 
         Assert.Equal(2, allLogs.Count);
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, world!", allLogs[0].Content);
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, error!", allLogs[1].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, world!", allLogs[0].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, error!", allLogs[1].Content);
 
         await logsEnumerator1.DisposeAsync();
         await logsEnumerator2.DisposeAsync();
@@ -76,8 +76,8 @@ public async Task StreamingLogsCancelledAfterComplete()
         var allLogs = await logsLoop.WaitAsync(TimeSpan.FromSeconds(15));
 
         Assert.Collection(allLogs,
-            l => Assert.Equal("2000-12-29T20:59:59.0000000 Hello, world!", l.Content),
-            l => Assert.Equal("2000-12-29T20:59:59.0000000 Hello, error!", l.Content));
+            l => Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, world!", l.Content),
+            l => Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, error!", l.Content));
 
         // New sub should not get new logs as the stream is completed
         logsLoop = ConsoleLoggingTestHelpers.WatchForLogsAsync(service, 100, testResource);
@@ -107,10 +107,10 @@ public async Task SecondSubscriberGetsBacklog()
         // Wait for logs to be read
         var allLogs = await logsLoop.WaitAsync(TimeSpan.FromSeconds(15));
 
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, world!", allLogs[0].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, world!", allLogs[0].Content);
         Assert.False(allLogs[0].IsErrorMessage);
 
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, error!", allLogs[1].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, error!", allLogs[1].Content);
         Assert.True(allLogs[1].IsErrorMessage);
 
         // New sub should get the previous logs (backlog)
@@ -121,8 +121,8 @@ public async Task SecondSubscriberGetsBacklog()
         allLogs = await logsLoop.WaitAsync(TimeSpan.FromSeconds(15));
 
         Assert.Equal(2, allLogs.Count);
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, world!", allLogs[0].Content);
-        Assert.Equal("2000-12-29T20:59:59.0000000 Hello, error!", allLogs[1].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, world!", allLogs[0].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z Hello, error!", allLogs[1].Content);
 
         // Clear the backlog and ensure new subs only get new logs
         service.ClearBacklog(testResource.Name);
@@ -136,7 +136,7 @@ public async Task SecondSubscriberGetsBacklog()
 
         // The backlog should be cleared so only new logs are received
         Assert.Equal(1, allLogs.Count);
-        Assert.Equal("2000-12-29T20:59:59.0000000 The third log", allLogs[0].Content);
+        Assert.Equal("2000-12-29T20:59:59.0000000Z The third log", allLogs[0].Content);
     }
 
     private sealed class TestResource(string name) : Resource(name)

Original file line number	Diff line number	Diff line change
`@@ -65,7 +65,7 @@ private void OnBrowserResize(object? o, EventArgs args)`
`65`	`65`	`});`
`66`	`66`	`}`
`67`	`67`
`68`		`- internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IReadOnlyList<ResourceLogLine>> batches, bool convertTimestampsFromUtc)`
	`68`	`+ internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IReadOnlyList<ResourceLogLine>> batches, bool convertTimestampsFromUtc = true)`
`69`	`69`	`{`
`70`	`70`	`ResourceName = resourceName;`
`71`	`71`
`@@ -102,12 +102,9 @@ internal async Task SetLogSourceAsync(string resourceName, IAsyncEnumerable<IRea`
`102`	`102`
`103`	`103`	`private string GetDisplayTimestamp(DateTimeOffset timestamp)`
`104`	`104`	`{`
`105`		`- if (_convertTimestampsFromUtc)`
`106`		`- {`
`107`		`- timestamp = TimeProvider.ToLocal(timestamp);`
`108`		`- }`
	`105`	`+ var date = _convertTimestampsFromUtc ? TimeProvider.ToLocal(timestamp) : timestamp.DateTime;`
`109`	`106`
`110`		`- return timestamp.ToString(KnownFormats.ConsoleLogsTimestampFormat, CultureInfo.InvariantCulture);`
	`107`	`+ return date.ToString(KnownFormats.ConsoleLogsUITimestampFormat, CultureInfo.InvariantCulture);`
`111`	`108`	`}`
`112`	`109`
`113`	`110`	`internal async Task ClearLogsAsync()`
Original file line number	Diff line number	Diff line change
`@@ -18,9 +18,8 @@ internal static IResourceBuilder<T> ConfigureConsoleLogs<T>(this IResourceBuilde`
`18`	`18`	`// Enable ANSI Control Sequences for colors in Output Redirection`
`19`	`19`	`context.EnvironmentVariables["DOTNET_SYSTEM_CONSOLE_ALLOW_ANSI_COLOR_REDIRECTION"] = "true";`
`20`	`20`
`21`		`- // Enable Simple Console Logger Formatting with a UTC timestamp similar to RFC3339Nano that Docker generates`
	`21`	`+ // Enable Simple Console Logger Formatting`
`22`	`22`	`context.EnvironmentVariables["LOGGING__CONSOLE__FORMATTERNAME"] = "simple";`
`23`		`- context.EnvironmentVariables["LOGGING__CONSOLE__FORMATTEROPTIONS__TIMESTAMPFORMAT"] = $"{KnownFormats.ConsoleLogsTimestampFormat} ";`
`24`	`23`	`});`
`25`	`24`	`}`
`26`	`25`	`}`
Original file line number	Diff line number	Diff line change
`@@ -163,11 +163,6 @@ public async Task AddProjectAddsEnvironmentVariablesAndServiceMetadata()`
`163`	`163`	`{`
`164`	`164`	`Assert.Equal("LOGGING__CONSOLE__FORMATTERNAME", env.Key);`
`165`	`165`	`Assert.Equal("simple", env.Value);`
`166`		`- },`
`167`		`- env =>`
`168`		`- {`
`169`		`- Assert.Equal("LOGGING__CONSOLE__FORMATTEROPTIONS__TIMESTAMPFORMAT", env.Key);`
`170`		`- Assert.Equal("yyyy-MM-ddTHH:mm:ss.fffffff ", env.Value);`
`171`	`166`	`});`
`172`	`167`	`}`
`173`	`168`