Use streaming to get logs for Executables and Containers

[karolz-ms]

Replaces #2414

This PR takes advantage of the new DCP feature: streaming logs. Thus, the dashboard service is relieved from the task of watching files and interacting with container orchestrator (Docker, Podman, etc) directly.

Marking as draft PR because it requires a DCP change, which @danegsta and @bwateratmsft are currently reviewing with considerable frenzy.

Microsoft Reviewers: Open in CodeFlow

[karolz-ms]

DCP insertion has started. Marking as ready for review

[karolz-ms]

This will resolve https://github.com/microsoft/usvc/issues/8 BTW

[karolz-ms]

New DCP release is in #2442. This is ready to merge now (once approved).

[JamesNK]

@karolz-ms I'm going to test this out. In the interest of time, do you mind if I make changes to your branch if I find things to change?

[karolz-ms]

@karolz-ms I'm going to test this out. In the interest of time, do you mind if I make changes to your branch if I find things to change?

Not at all. Appreciate the help. Note you need new DCP

[JamesNK]

I got this error if I view logs for a resource as the app is starting up:

fail: Grpc.AspNetCore.Server.ServerCallHandler[6]
      Error when executing service method 'WatchResourceConsoleLogs'.
      k8s.Autorest.HttpOperationException: Operation returned an invalid status code 'NotFound', response body {"kind":"Status","apiVersion":"v1","metadata":{},"status":"Failure","message":"the server could not find the requested resource","reason":"NotFound","details":{},"code":404}

         at k8s.Kubernetes.SendRequestRaw(String requestContent, HttpRequestMessage httpRequest, CancellationToken cancellationToken)
         at Aspire.Hosting.Dcp.DcpKubernetesClient.ReadSubResourceAsStreamAsync(String group, String version, String plural, String name, String subResource, String namespaceParameter, IReadOnlyCollection`1 queryParams, CancellationToken cancellationToken) in C:\Development\Source\aspire\src\Aspire.Hosting\Dcp\DcpKubernetesClient.cs:line 71
         at Aspire.Hosting.Dcp.KubernetesService.<>c__DisplayClass14_0`1.<<GetLogStreamAsync>b__0>d.MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dcp\KubernetesService.cs:line 193
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dcp.KubernetesService.ExecuteWithRetry[TResult](DcpApiOperationType operationType, String resourceType, Func`2 operation, CancellationToken cancellationToken) in C:\Development\Source\aspire\src\Aspire.Hosting\Dcp\KubernetesService.cs:line 255
         at Aspire.Hosting.Dashboard.ResourceLogSource`1.GetAsyncEnumerator(CancellationToken cancellationToken)+MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\ResourceLogSource.cs:line 28
         at Aspire.Hosting.Dashboard.ResourceLogSource`1.GetAsyncEnumerator(CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
         at Aspire.Hosting.Dashboard.DashboardServiceData.<>c__DisplayClass6_0.<<SubscribeConsoleLogs>g__Enumerate|0>d.MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\DashboardServiceData.cs:line 56
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dashboard.DashboardServiceData.<>c__DisplayClass6_0.<<SubscribeConsoleLogs>g__Enumerate|0>d.MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\DashboardServiceData.cs:line 56
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dashboard.DashboardServiceData.<>c__DisplayClass6_0.<<SubscribeConsoleLogs>g__Enumerate|0>d.System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult(Int16 token)
         at Aspire.Hosting.Dashboard.DashboardService.<>c__DisplayClass7_0.<<WatchResourceConsoleLogs>g__WatchResourceConsoleLogsInternal|0>d.MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\DashboardService.cs:line 132
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dashboard.DashboardService.<>c__DisplayClass7_0.<<WatchResourceConsoleLogs>g__WatchResourceConsoleLogsInternal|0>d.MoveNext() in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\DashboardService.cs:line 132
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dashboard.DashboardService.WatchResourceConsoleLogs(WatchResourceConsoleLogsRequest request, IServerStreamWriter`1 responseStream, ServerCallContext context) in C:\Development\Source\aspire\src\Aspire.Hosting\Dashboard\DashboardService.cs:line 116
         at Grpc.Shared.Server.ServerStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, TRequest request, IServerStreamWriter`1 streamWriter)
         at Grpc.Shared.Server.ServerStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, TRequest request, IServerStreamWriter`1 streamWriter)
         at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext)
         at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall)

The user experience should be they click view logs for a resource that is starting, and logs start displaying when they become available.

I don't know the best implementaiton for that. Perhaps some retrying to happen for a 404 error to give DCP a chance to finish starting the resource up.

[karolz-ms]

The error above is probably due to outdated DCP version.

That said, there is known limitation in the current implementation, which is, if a Container/Executable is just created and starting, logs will not be available (will show up as empty). We will fix that with upcoming change in DCP, there will be no client change required.

[danegsta]

Seems to be working well for me locally, although on an unrelated note I do notice that the dashboard is logging cancellations every time you switch log views (Call failed with gRPC error status. Status code: 'Cancelled', Message: 'Call canceled by the client.'..), at least with TestShop.

[davidfowl]

Yea that’s a common dashboard error

[davidfowl]

Did we fix all the things? Is this ready to go?

[JamesNK]

There are some issues:

1. Karol and I both noticed when testing this that sometimes the console logs page throws an error if clicked during startup. I logged Refreshing or opening console logs in a new tab loses selected resource #2460
2. If there is an error in the server then the UI is never notified. I think this page has always been blind to errors but now there are a lot more moving parts and it's more important.

I'm looking at these both. The first issue will be a separate PR. The second issue will be added to this PR (I'll do it today).

[davidfowl]

Feels like we should merge this PR with the bool flipped (back to the current impl). Work on the issues and flip to back if we’re happy with the progress.

[JamesNK]

Dates are missing in the new logging.

Before:

After:

[JamesNK]

There is a fairly long delay (5-10 seconds) between logs being written and them showing up in the dashboard.

I have some code that writes to Debug.Write (control) the logging:

using var r = combinedTokens.Token.Register(() =>
{
    _logger.LogInformation("Console log subscription {ResourceName} cancelled.", resourceName);
    Debug.Write($"Console log subscription {resourceName} cancelled.");
});

You can see in the recording that the code executes immediately (Debug.Write outputs to VS output window), however it takes about 6.5 seconds before it shows up in the dashboard UI:

I repeated this test on the old console logs code. Previous console logging displayed updates immediately.

[karolz-ms]

Good feedback, thanks James. I talked to David and the current proposal is to have the new implementation be an opt-in behind an env var and pursue this for Aspire P5.