Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 46 additions & 0 deletions playground/Stress/Stress.ApiService/Program.cs
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System.Diagnostics;
using System.Threading.Channels;
using Stress.ApiService;

var builder = WebApplication.CreateBuilder(args);
Expand All @@ -25,4 +27,48 @@
return "Big trace created";
});

app.MapGet("/many-logs", (ILoggerFactory loggerFactory, CancellationToken cancellationToken) =>
{
var channel = Channel.CreateUnbounded<string>();
var logger = loggerFactory.CreateLogger("ManyLogs");

cancellationToken.Register(() =>
{
logger.LogInformation("Writing logs canceled.");
});

// Write logs for 1 minute.
_ = Task.Run(async () =>
{
var stopwatch = Stopwatch.StartNew();
var logCount = 0;
while (stopwatch.Elapsed < TimeSpan.FromMinutes(1))
{
cancellationToken.ThrowIfCancellationRequested();

logCount++;
logger.LogInformation("This is log message {LogCount}.", logCount);

if (logCount % 100 == 0)
{
channel.Writer.TryWrite($"Logged {logCount} messages.");
}

await Task.Delay(5, cancellationToken);
}

channel.Writer.Complete();
}, cancellationToken);

return WriteOutput();

async IAsyncEnumerable<string> WriteOutput()
{
await foreach (var message in channel.Reader.ReadAllAsync(cancellationToken))
{
yield return message;
}
}
});

app.Run();
22 changes: 21 additions & 1 deletion src/Aspire.Dashboard/Components/Controls/LogViewer.razor
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,27 @@
@inject IJSRuntime JS
@implements IAsyncDisposable

<div class="log-overflow">
<div class="log-overflow continuous-scroll-overflow">
<div class="log-container" id="logContainer">
<Virtualize Items="_logEntries" ItemSize="20" OverscanCount="100">
<div class="line-row-container">
<div class="line-row">
<span class="line-area" role="log">
<span class="line-number">@context.LineNumber</span>
<span class="content">
@if (context.Timestamp is { } timestamp)
{
<span class="timestamp">@GetDisplayTimestamp(timestamp)</span>
}
@if (context.Type == LogEntryType.Error)
{
<fluent-badge appearance="accent">stderr</fluent-badge>
}
@((MarkupString)(context.Content ?? string.Empty))
</span>
</span>
</div>
</div>
</Virtualize>
</div>
</div>
124 changes: 102 additions & 22 deletions src/Aspire.Dashboard/Components/Controls/LogViewer.razor.cs
Original file line number Diff line number Diff line change
@@ -1,7 +1,10 @@
// Licensed to the .NET Foundation under one or more agreements.
// The .NET Foundation licenses this file to you under the MIT license.

using System.Diagnostics;
using System.Globalization;
using Aspire.Dashboard.ConsoleLogs;
using Aspire.Dashboard.Extensions;
using Aspire.Dashboard.Model;
using Aspire.Dashboard.Utils;
using Microsoft.AspNetCore.Components;
Expand All @@ -14,30 +17,35 @@ namespace Aspire.Dashboard.Components;
/// </summary>
public sealed partial class LogViewer
{
private readonly TaskCompletionSource _whenDomReady = new();
private readonly CancellationSeries _cancellationSeries = new();
private IJSObjectReference? _jsModule;
private bool _convertTimestampsFromUtc;
private bool _applicationChanged;

[Inject]
public required BrowserTimeProvider TimeProvider { get; init; }

protected override async Task OnAfterRenderAsync(bool firstRender)
{
if (_applicationChanged)
{
await JS.InvokeVoidAsync("resetContinuousScrollPosition");
_applicationChanged = false;
}
if (firstRender)
{
_jsModule ??= await JS.InvokeAsync<IJSObjectReference>("import", "/Components/Controls/LogViewer.razor.js");

_whenDomReady.TrySetResult();
await JS.InvokeVoidAsync("initializeContinuousScroll");
}
}

internal async Task SetLogSourceAsync(IAsyncEnumerable<IReadOnlyList<(string Content, bool IsErrorMessage)>> batches, bool convertTimestampsFromUtc)
private readonly List<LogEntry> _logEntries = new();
private int? _baseLineNumber;

internal async Task SetLogSourceAsync(IAsyncEnumerable<IReadOnlyList<ResourceLogLine>> batches, bool convertTimestampsFromUtc)
{
var cancellationToken = await _cancellationSeries.NextAsync();
var logParser = new LogParser(TimeProvider, convertTimestampsFromUtc);
_convertTimestampsFromUtc = convertTimestampsFromUtc;

// Ensure we are able to write to the DOM.
await _whenDomReady.Task;
var cancellationToken = await _cancellationSeries.NextAsync();
var logParser = new LogParser();

await foreach (var batch in batches.WithCancellation(cancellationToken))
{
Expand All @@ -46,33 +54,105 @@ internal async Task SetLogSourceAsync(IAsyncEnumerable<IReadOnlyList<(string Con
continue;
}

List<LogEntry> entries = new(batch.Count);

foreach (var (content, isErrorOutput) in batch)
foreach (var (lineNumber, content, isErrorOutput) in batch)
{
entries.Add(logParser.CreateLogEntry(content, isErrorOutput));
// Keep track of the base line number to ensure that we can calculate the line number of each log entry.
// This becomes important when the total number of log entries exceeds the limit and is truncated.
if (_baseLineNumber is null)
{
_baseLineNumber = lineNumber;
}

InsertSorted(_logEntries, logParser.CreateLogEntry(content, isErrorOutput));
}

await _jsModule!.InvokeVoidAsync("addLogEntries", cancellationToken, entries);
StateHasChanged();
}
}

internal async Task ClearLogsAsync(CancellationToken cancellationToken = default)
private void InsertSorted(List<LogEntry> logEntries, LogEntry logEntry)
{
await _cancellationSeries.ClearAsync();
if (logEntry.ParentId != null)
{
// If we have a parent id, then we know we're on a non-timestamped line that is part
Copy link
Member

Choose a reason for hiding this comment

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

Was hoping the need to do this interleaving would go away at some point. I guess that some point is not yet...

Copy link
Member Author

@JamesNK JamesNK Mar 21, 2024

Choose a reason for hiding this comment

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

I just replicated what JS was doing. I'm not a fan of it. Reordering data from the server just before it is rendered is probably the wrong place. If reordering is required, it should happen before storing the data inside the host.

I'm thinking about line numbers right now, and this reordering makes it difficult.

Can you talk more about why it is required? What was the original issue?

Copy link
Member

Choose a reason for hiding this comment

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

Yeah, sorry, I probably could have been more clear on that comment. I had hoped it was going to go away with streaming logs, but @karolz-ms indicated there were still two separate streams so there might be an issue.

The reordering was required because the logs arrived out of order from the two different streams (stdout and stderr). This was especially true with logs being written to the file system - the first stderr line could have been seconds or minutes after the first stdout line, but since the two files were read at the same time, we'd get them in unpredictable order. Though whatever the source is (docker logs acted slightly differently) they'd still need to be interleaved at some point.

Looking through the current code on the dashboard side, I don't see anywhere obvious where we see the two different streams anymore. Maybe @karolz-ms can speak to how that works in the streaming world now?

Copy link
Member Author

Choose a reason for hiding this comment

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

There are still two streams, they now come from k8s service:

var stdoutStream = await kubernetesService.GetLogStreamAsync(resource, Logs.StreamTypeStdOut, follow: true, timestamps: timestamps, cancellationToken).ConfigureAwait(false);
var stderrStream = await kubernetesService.GetLogStreamAsync(resource, Logs.StreamTypeStdErr, follow: true, timestamps: timestamps, cancellationToken).ConfigureAwait(false);

I think this would still be a problem.

Copy link
Member

Choose a reason for hiding this comment

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

DCP could combine the streams (and apply timestamps to Executable logs), but then we need to figure out how to convey what entries come from stdout vs stderr. E.g. change the format to JSON lines or something similar, but then there is a question of how to deal with non-printable characters etc.

Copy link
Member Author

@JamesNK JamesNK Mar 22, 2024

Choose a reason for hiding this comment

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

If DCP combined the streams, would they be in the correct order? How does DCP get its data? Is it reading from files written to disk, or receiving it more directly?

Copy link
Member Author

@JamesNK JamesNK Mar 22, 2024

Choose a reason for hiding this comment

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

E.g. change the format to JSON lines or something similar, but then there is a question of how to deal with non-printable characters etc.

I guess a JSON serializer would escape them to \uXXXX format.

Copy link
Member

Choose a reason for hiding this comment

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

For Containers the logs arrive in the order the container orchestrator is providing them. But since we are using the CLI to talk to the orchestrator, it boils down to reading stdout and stderr.

The same applies to Executables. When DCP launches Executables directly, it is also responsible for reading stdout and stderr streams. When using the IDE to launch Executables (i.e. dealing with VS projects), it is relying on the IDE to provide the logs.

Bottom line this is probably sufficient for UI to have logs emitted ROUGHLY at the same time to surface close in the combined stream. But there will definitively be some jitter involved, and if the expectation is that developers will be able to infer the order in which things happened based on the order in which they appeared in the (combined) log stream, especially if we are talking about microseconds delay between writes to stdout vs stderr, that is probably a stretch.

// of a multi-line log entry. We need to find the prior line from that entry
for (var rowIndex = logEntries.Count - 1; rowIndex >= 0; rowIndex--)
{
var current = logEntries[rowIndex];

if (_jsModule is not null)
if (current.Id == logEntry.ParentId && logEntry.LineIndex - 1 == current.LineIndex)
{
InsertLogEntry(logEntries, rowIndex + 1, logEntry);
return;
}
}
}
else if (logEntry.Timestamp != null)
{
await _jsModule.InvokeVoidAsync("clearLogs", cancellationToken);
// Otherwise, if we have a timestamped line, we just need to find the prior line.
// Since the rows are always in order, as soon as we see a timestamp
// that is less than the one we're adding, we can insert it immediately after that
for (var rowIndex = logEntries.Count - 1; rowIndex >= 0; rowIndex--)
{
var current = logEntries[rowIndex];
var currentTimestamp = current.Timestamp ?? current.ParentTimestamp;

if (currentTimestamp != null && currentTimestamp < logEntry.Timestamp)
{
InsertLogEntry(logEntries, rowIndex + 1, logEntry);
return;
}
}
}

// If we didn't find a place to insert then append it to the end. This happens with the first entry, but
// could also happen if the logs don't have recognized timestamps.
InsertLogEntry(logEntries, logEntries.Count, logEntry);

void InsertLogEntry(List<LogEntry> logEntries, int index, LogEntry logEntry)
{
// Set the line number of the log entry.
if (index == 0)
{
Debug.Assert(_baseLineNumber != null, "Should be set before this method is run.");
logEntry.LineNumber = _baseLineNumber.Value;
}
else
{
logEntry.LineNumber = logEntries[index - 1].LineNumber + 1;
}

logEntries.Insert(index, logEntry);

// If a log entry isn't inserted at the end then update the line numbers of all subsequent entries.
for (var i = index + 1; i < logEntries.Count; i++)
{
logEntries[i].LineNumber++;
}
}
}

public async ValueTask DisposeAsync()
private string GetDisplayTimestamp(DateTimeOffset timestamp)
{
_whenDomReady.TrySetCanceled();
if (_convertTimestampsFromUtc)
{
timestamp = TimeProvider.ToLocal(timestamp);
}

return timestamp.ToString(KnownFormats.ConsoleLogsTimestampFormat, CultureInfo.InvariantCulture);
}

internal async Task ClearLogsAsync()
{
await _cancellationSeries.ClearAsync();

await JSInteropHelpers.SafeDisposeAsync(_jsModule);
_applicationChanged = true;
_logEntries.Clear();
StateHasChanged();
}

public async ValueTask DisposeAsync()
{
await _cancellationSeries.ClearAsync();
}
}
10 changes: 3 additions & 7 deletions src/Aspire.Dashboard/Components/Controls/LogViewer.razor.css
Original file line number Diff line number Diff line change
Expand Up @@ -34,21 +34,19 @@
background: var(--console-background-color);
color: var(--console-font-color);
font-family: 'Cascadia Mono', Consolas, monospace;
font-size: 12px;
font-size: 13px;
margin: 16px 0 0 0;
padding-bottom: 24px;
line-height: 20px;
overflow: visible;
display: flex;
flex-direction: column;
width: 100%;
counter-reset: line-number 0;
}

::deep .line-row-container {
width: 100%;
overflow: hidden;
counter-increment: line-number 1;
}

::deep .line-row {
Expand Down Expand Up @@ -79,10 +77,8 @@
align-self: flex-start;
flex-shrink: 0;
color: var(--line-number-color);
}

::deep .line-number::before {
content: counter(line-number);
user-select: none;
cursor: default;
}

::deep .content {
Expand Down
Loading