Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Support ILogger.BeginScope() for LSP logging #77647

Merged
merged 3 commits into from
Mar 27, 2025

Conversation

jasonmalinowski
Copy link
Member

@jasonmalinowski jasonmalinowski commented Mar 18, 2025

This surrounds the processing of each LSP request with a call to ILogger.BeginScope() with the name of the method that's being invoked. This is prefixed to the message we send back to the LSP client, so it's much easier to understand the source of various pieces of logging.

ILspLogger.LogStartContext/LogEndContext are deprecated here, as setting scopes plus an explicit start/end as appropriate makes things work much better when we're handling requests in parallel.

An example of what this looks like now:

[workspace/diagnostic] [LanguageServerHost] Request did not contain a textDocument, using default language handler
[workspace/diagnostic] [LanguageServerHost] Request did not contain a textDocument, using default language handler
[workspace/diagnostic] [LanguageServerHost] Starting request handler
[workspace/diagnostic] [LanguageServerHost] Starting request handler
[workspace/diagnostic] [LanguageServerHost] PublicWorkspacePullDiagnosticsHandler(category: enc) started getting diagnostics
[workspace/diagnostic] [LanguageServerHost] PublicWorkspacePullDiagnosticsHandler(category: WorkspaceDocumentsAndProject) started getting diagnostics
[workspace/diagnostic] [LanguageServerHost] previousResults.Length=0
[workspace/diagnostic] [LanguageServerHost] previousResults.Length=0
[workspace/diagnostic] [LanguageServerHost] Request did not contain a textDocument, using default language handler

I decided to put the context first since calls sometimes end up in other components, and it made it more clear the context was flowing around.

@jasonmalinowski jasonmalinowski self-assigned this Mar 18, 2025
@jasonmalinowski jasonmalinowski requested a review from a team as a code owner March 18, 2025 00:24
@dotnet-issue-labeler dotnet-issue-labeler bot added Area-IDE untriaged Issues and PRs which have not yet been triaged by a lead labels Mar 18, 2025
@@ -237,7 +239,6 @@ public async Task StartRequestAsync<TRequest, TResponse>(TRequest request, TRequ
finally
{
_requestTelemetryScope?.Dispose();
_logger.LogEndContext($"{MethodName}");
Copy link
Member Author

Choose a reason for hiding this comment

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

Removed since each branch now logs a success/failure/cancelled.

var xmlSnippetParser = document.Project.Solution.Services.ExportProvider.GetService<XmlSnippetParser>();

return InlineCompletionsHandler.GetInlineCompletionItemsAsync(logger, document, position, options, xmlSnippetParser, cancellationToken);
}

private sealed class EmptyLogger : ILspLogger
Copy link
Member Author

Choose a reason for hiding this comment

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

We already had a NoOpLspLogger to reuse.

@@ -4,6 +4,7 @@

using System;
using System.Threading.Tasks;
using Microsoft.CodeAnalysis.LanguageServer;
Copy link
Member Author

Choose a reason for hiding this comment

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

This is to use the NoOpLspLogger that already existed in this namespace from Microsoft.CodeAnalysis.LanguageServer.Protocol. If there is a desire that this example must use only stuff from CommonLanguageServerProtocol, then we should delete the package reference and move the no-op implementation to CLaSP.

{
message = $"[{categoryName}] {message}";
try
if (scope is LspLoggingScope lspLoggingScope)
Copy link
Member Author

Choose a reason for hiding this comment

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

Although nothing prevents us from just adding a string as the scope, I decided to a bit more strict about the typing here.

Copy link
Member

@dibarbet dibarbet left a comment

Choose a reason for hiding this comment

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

We should maybe do a quick test insertion to make sure nothing obvious breaks. I'm 95% sure it shouldn't... but that 5%

@jasonmalinowski
Copy link
Member Author

We should maybe do a quick test insertion to make sure nothing obvious breaks.

Validation run was ran, and verified good.

Otherwise this gets logged by the LSP client as a generic message,
which isn't prefixed with a severity like everything else.
This surrounds the processing of each LSP request with a call to
ILogger.BeginScope() with the name of the method that's being invoked.
This is prefixed to the message we send back to the LSP client, so
it's much easier to understand the source of various pieces of logging.

ILspLogger.LogStartContext/LogEndContext are deprecated here, as
setting scopes plus an explicit start/end as appropriate makes things
work much better when we're handling requests in parallel.
@jasonmalinowski jasonmalinowski force-pushed the support-logging-scopes branch from 748d7e6 to c8c9e5b Compare March 27, 2025 00:11
@jasonmalinowski jasonmalinowski merged commit fae3e15 into dotnet:main Mar 27, 2025
25 checks passed
@jasonmalinowski jasonmalinowski deleted the support-logging-scopes branch March 27, 2025 18:07
@dotnet-policy-service dotnet-policy-service bot added this to the Next milestone Mar 27, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area-IDE untriaged Issues and PRs which have not yet been triaged by a lead VSCode
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants