Add back request telemetry in CLaSP queue

src/EditorFeatures/Core/LanguageServer/AbstractInProcLanguageClient.cs

@@ -6,7 +6,6 @@
 using System.Collections.Generic;
 using System.Collections.Immutable;
 using System.IO;
-using System.Runtime.ExceptionServices;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.CodeAnalysis.Editor.Shared.Utilities;
@@ -227,7 +226,7 @@ public virtual AbstractLanguageServer<RequestContext> Create(
             JsonRpc jsonRpc,
             ICapabilitiesProvider capabilitiesProvider,
             WellKnownLspServerKinds serverKind,
-            ILspServiceLogger logger,
+            AbstractLspLogger logger,
             HostServices hostServices)
         {
             var server = new RoslynLanguageServer(

src/EditorFeatures/TestUtilities/LanguageServer/AbstractLanguageServerProtocolTests.cs

@@ -44,7 +44,7 @@ namespace Roslyn.Test.Utilities
     [UseExportProvider]
     public abstract partial class AbstractLanguageServerProtocolTests
     {
-        private protected readonly ILspServiceLogger TestOutputLspLogger;
+        private protected readonly AbstractLspLogger TestOutputLspLogger;
         protected AbstractLanguageServerProtocolTests(ITestOutputHelper? testOutputHelper)
         {
             TestOutputLspLogger = testOutputHelper != null ? new TestOutputLspLogger(testOutputHelper) : NoOpLspLogger.Instance;
@@ -580,7 +580,7 @@ private static JsonMessageFormatter CreateJsonMessageFormatter()
                 return messageFormatter;
             }
 
-            internal static async Task<TestLspServer> CreateAsync(TestWorkspace testWorkspace, InitializationOptions initializationOptions, ILspServiceLogger logger)
+            internal static async Task<TestLspServer> CreateAsync(TestWorkspace testWorkspace, InitializationOptions initializationOptions, AbstractLspLogger logger)
             {
                 var locations = await GetAnnotatedLocationsAsync(testWorkspace, testWorkspace.CurrentSolution);
 
@@ -618,7 +618,7 @@ internal static async Task<TestLspServer> CreateAsync(TestWorkspace testWorkspac
                 return server;
             }
 
-            private static RoslynLanguageServer CreateLanguageServer(Stream inputStream, Stream outputStream, TestWorkspace workspace, WellKnownLspServerKinds serverKind, ILspServiceLogger logger)
+            private static RoslynLanguageServer CreateLanguageServer(Stream inputStream, Stream outputStream, TestWorkspace workspace, WellKnownLspServerKinds serverKind, AbstractLspLogger logger)
             {
                 var capabilitiesProvider = workspace.ExportProvider.GetExportedValue<ExperimentalCapabilitiesProvider>();
                 var servicesProvider = workspace.ExportProvider.GetExportedValue<CSharpVisualBasicLspServiceProvider>();

src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs

@@ -3,34 +3,33 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
-using System.Collections.Generic;
-using System.IO;
-using System.Linq;
-using System.Text;
-using System.Threading.Tasks;
+using Microsoft.CommonLanguageServerProtocol.Framework;
 using Xunit.Abstractions;
 
 namespace Microsoft.CodeAnalysis.LanguageServer.UnitTests;
-public class TestOutputLspLogger : ILspServiceLogger
+
+public sealed class TestOutputLspLogger : AbstractLspLogger, ILspService
 {
     private readonly ITestOutputHelper _testOutputHelper;
     public TestOutputLspLogger(ITestOutputHelper testOutputHelper)
     {
         _testOutputHelper = testOutputHelper;
     }
 
-    public void LogEndContext(string message, params object[] @params) => Log("End", message, @params);
+    public override void LogDebug(string message, params object[] @params) => Log("Debug", message, @params);
+
+    public override void LogEndContext(string message, params object[] @params) => Log("End", message, @params);
 
-    public void LogError(string message, params object[] @params) => Log("Error", message, @params);
+    public override void LogError(string message, params object[] @params) => Log("Error", message, @params);
 
-    public void LogException(Exception exception, string? message = null, params object[] @params)
+    public override void LogException(Exception exception, string? message = null, params object[] @params)
         => Log("Warning", $"{message}{Environment.NewLine}{exception}", @params);
 
-    public void LogInformation(string message, params object[] @params) => Log("Info", message, @params);
+    public override void LogInformation(string message, params object[] @params) => Log("Info", message, @params);
 
-    public void LogStartContext(string message, params object[] @params) => Log("Start", message, @params);
+    public override void LogStartContext(string message, params object[] @params) => Log("Start", message, @params);
 
-    public void LogWarning(string message, params object[] @params) => Log("Warning", message, @params);
+    public override void LogWarning(string message, params object[] @params) => Log("Warning", message, @params);
 
     private void Log(string level, string message, params object[] @params)
         => _testOutputHelper.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}][{level}]{message}", @params);

src/Features/LanguageServer/Microsoft.CodeAnalysis.LanguageServer/Logging/LspServiceLogger.cs

@@ -2,14 +2,15 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 // See the LICENSE file in the project root for more information.
 
+using Microsoft.CommonLanguageServerProtocol.Framework;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.CodeAnalysis.LanguageServer.Logging;
 
 /// <summary>
-/// Implements <see cref="ILspServiceLogger"/> by sending LSP log messages back to the client.
+/// Implements <see cref="AbstractLspLogger"/> by sending LSP log messages back to the client.
 /// </summary>
-internal sealed class LspServiceLogger : ILspServiceLogger
+internal sealed class LspServiceLogger : AbstractLspLogger, ILspService
 {
     private readonly ILogger _hostLogger;
 
@@ -18,18 +19,20 @@ public LspServiceLogger(ILogger hostLogger)
         _hostLogger = hostLogger;
     }
 
-    public void LogEndContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][End]{message}", @params);
+    public override void LogDebug(string message, params object[] @params) => _hostLogger.LogDebug(message, @params);
 
-    public void LogError(string message, params object[] @params) => _hostLogger.LogError(message, @params);
+    public override void LogEndContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][End]{message}", @params);
 
-    public void LogException(Exception exception, string? message = null, params object[] @params) => _hostLogger.LogError(exception, message, @params);
+    public override void LogError(string message, params object[] @params) => _hostLogger.LogError(message, @params);
+
+    public override void LogException(Exception exception, string? message = null, params object[] @params) => _hostLogger.LogError(exception, message, @params);
 
     /// <summary>
-    /// TODO - This should call LogInformation, however we need to introduce a LogDebug call in clasp first.
+    /// TODO - Switch this to call LogInformation once appropriate callers have been changed to LogDebug.
     /// </summary>
-    public void LogInformation(string message, params object[] @params) => _hostLogger.LogDebug(message, @params);
+    public override void LogInformation(string message, params object[] @params) => _hostLogger.LogDebug(message, @params);
 
-    public void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params);
+    public override void LogStartContext(string message, params object[] @params) => _hostLogger.LogDebug($"[{DateTime.UtcNow:hh:mm:ss.fff}][Start]{message}", @params);
 
-    public void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params);
+    public override void LogWarning(string message, params object[] @params) => _hostLogger.LogWarning(message, @params);
 }

src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework.UnitTests/Mocks/NoOpLspLogger.cs

@@ -3,36 +3,38 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
-using System.Threading;
-using System.Threading.Tasks;
 
 namespace Microsoft.CommonLanguageServerProtocol.Framework.UnitTests;
 
-public class NoOpLspLogger : ILspLogger
+public sealed class NoOpLspLogger : AbstractLspLogger, ILspLogger
 {
     public static NoOpLspLogger Instance = new();
 
-    public void LogError(string message, params object[] @params)
+    public override void LogDebug(string message, params object[] @params)
     {
     }
 
-    public void LogException(Exception exception, string? message = null, params object[] @params)
+    public override void LogError(string message, params object[] @params)
     {
     }
 
-    public void LogInformation(string message, params object[] @params)
+    public override void LogException(Exception exception, string? message = null, params object[] @params)
     {
     }
 
-    public void LogStartContext(string context, params object[] @params)
+    public override void LogInformation(string message, params object[] @params)
     {
     }
 
-    public void LogEndContext(string context, params object[] @params)
+    public override void LogStartContext(string context, params object[] @params)
     {
     }
 
-    public void LogWarning(string message, params object[] @params)
+    public override void LogEndContext(string context, params object[] @params)
+    {
+    }
+
+    public override void LogWarning(string message, params object[] @params)
     {
     }
 }

src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractLspLogger.cs

@@ -0,0 +1,18 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+using System;
+
+namespace Microsoft.CommonLanguageServerProtocol.Framework;
+
+public abstract class AbstractLspLogger : ILspLogger
+{
+    public abstract void LogDebug(string message, params object[] @params);
+    public abstract void LogStartContext(string message, params object[] @params);
+    public abstract void LogEndContext(string message, params object[] @params);
+    public abstract void LogInformation(string message, params object[] @params);
+    public abstract void LogWarning(string message, params object[] @params);
+    public abstract void LogError(string message, params object[] @params);
+    public abstract void LogException(Exception exception, string? message = null, params object[] @params);
+}

src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractRequestScope.cs

@@ -0,0 +1,20 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+using System;
+
+namespace Microsoft.CommonLanguageServerProtocol.Framework;
+
+public abstract class AbstractRequestScope(string name) : IDisposable
+{
+    public string Name { get; } = name;
+
+    public abstract void RecordCancellation();
+    public abstract void RecordException(Exception exception);
+    public abstract void RecordWarning(string message);
+
+    public abstract void RecordExecutionStart();
+
+    public abstract void Dispose();
+}

src/Features/LanguageServer/Protocol/ILspServiceLogger.cs → src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/AbstractTelemetryService.cs

@@ -2,12 +2,9 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 // See the LICENSE file in the project root for more information.
 
-using Microsoft.CommonLanguageServerProtocol.Framework;
+namespace Microsoft.CommonLanguageServerProtocol.Framework;
 
-namespace Microsoft.CodeAnalysis.LanguageServer
+public abstract class AbstractTelemetryService
 {
-
-    internal interface ILspServiceLogger : ILspLogger, ILspService
-    {
-    }
+    public abstract AbstractRequestScope CreateRequestScope(string lspMethodName);
 }

src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/ILspLogger.cs

@@ -3,8 +3,6 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
-using System.Threading;
-using System.Threading.Tasks;
 
 namespace Microsoft.CommonLanguageServerProtocol.Framework;
 

src/Features/LanguageServer/Microsoft.CommonLanguageServerProtocol.Framework/QueueItem.cs

@@ -3,7 +3,7 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
-using System.Diagnostics;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.VisualStudio.Threading;
@@ -20,11 +20,12 @@ internal sealed class NoValue
 
 internal class QueueItem<TRequest, TResponse, TRequestContext> : IQueueItem<TRequestContext>
 {
-    private readonly ILspLogger _logger;
-
     private readonly TRequest _request;
     private readonly IMethodHandler _handler;
 
+    private readonly ILspLogger _logger;
+    private readonly AbstractRequestScope? _requestTelemetryScope;
+
     /// <summary>
     /// A task completion source representing the result of this queue item's work.
     /// This is the task that the client is waiting on.
@@ -60,6 +61,10 @@ private QueueItem(
 
         MutatesServerState = mutatesSolutionState;
         MethodName = methodName;
+
+        var telemetryService = lspServices.GetRequiredServices<AbstractTelemetryService>().FirstOrDefault();
+
+        _requestTelemetryScope = telemetryService?.CreateRequestScope(methodName);
     }
 
     public static (IQueueItem<TRequestContext>, Task<TResponse>) Create(
@@ -88,6 +93,9 @@ public static (IQueueItem<TRequestContext>, Task<TResponse>) Create(
     public async Task<TRequestContext?> CreateRequestContextAsync(CancellationToken cancellationToken)
     {
         cancellationToken.ThrowIfCancellationRequested();
+
+        _requestTelemetryScope?.RecordExecutionStart();
+
         var requestContextFactory = LspServices.GetRequiredService<IRequestContextFactory<TRequestContext>>();
         var context = await requestContextFactory.CreateRequestContextAsync(this, _request, cancellationToken).ConfigureAwait(false);
         return context;
@@ -116,7 +124,9 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken
                 // the requests this could happen for.  However, this assumption may not hold in the future.
                 // If that turns out to be the case, we could defer to the individual handler to decide
                 // what to do.
+                _requestTelemetryScope?.RecordWarning($"Could not get request context for {MethodName}");
                 _logger.LogWarning($"Could not get request context for {MethodName}");
+
                 _completionSource.TrySetException(new InvalidOperationException($"Unable to create request context for {MethodName}"));
             }
             else if (_handler is IRequestHandler<TRequest, TResponse, TRequestContext> requestHandler)
@@ -153,6 +163,7 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken
         catch (OperationCanceledException ex)
         {
             // Record logs + metrics on cancellation.
+            _requestTelemetryScope?.RecordCancellation();
             _logger.LogInformation($"{MethodName} - Canceled");
 
             _completionSource.TrySetCanceled(ex.CancellationToken);
@@ -161,12 +172,14 @@ public async Task StartRequestAsync(TRequestContext? context, CancellationToken
         {
             // Record logs and metrics on the exception.
             // It's important that this can NEVER throw, or the queue will hang.
+            _requestTelemetryScope?.RecordException(ex);
             _logger.LogException(ex);
 
             _completionSource.TrySetException(ex);
         }
         finally
         {
+            _requestTelemetryScope?.Dispose();
             _logger.LogEndContext($"{MethodName}");
         }
 

src/Features/LanguageServer/Protocol/CSharpVisualBasicLanguageServerFactory.cs

@@ -5,13 +5,11 @@
 using System;
 using System.Composition;
 using System.IO;
-using System.Threading.Tasks;
+using Microsoft.CodeAnalysis.Host;
 using Microsoft.CodeAnalysis.Host.Mef;
 using Microsoft.CodeAnalysis.LanguageServer.Handler;
 using Microsoft.CommonLanguageServerProtocol.Framework;
-using Microsoft.CodeAnalysis.ExternalAccess.Razor;
 using StreamJsonRpc;
-using Microsoft.CodeAnalysis.Host;
 
 namespace Microsoft.CodeAnalysis.LanguageServer
 {
@@ -32,7 +30,7 @@ public AbstractLanguageServer<RequestContext> Create(
             JsonRpc jsonRpc,
             ICapabilitiesProvider capabilitiesProvider,
             WellKnownLspServerKinds serverKind,
-            ILspServiceLogger logger,
+            AbstractLspLogger logger,
             HostServices hostServices)
         {
             var server = new RoslynLanguageServer(
@@ -47,7 +45,7 @@ public AbstractLanguageServer<RequestContext> Create(
             return server;
         }
 
-        public AbstractLanguageServer<RequestContext> Create(Stream input, Stream output, ICapabilitiesProvider capabilitiesProvider, ILspServiceLogger logger, HostServices hostServices)
+        public AbstractLanguageServer<RequestContext> Create(Stream input, Stream output, ICapabilitiesProvider capabilitiesProvider, AbstractLspLogger logger, HostServices hostServices)
         {
             var jsonRpc = new JsonRpc(new HeaderDelimitedMessageHandler(output, input));
             return Create(jsonRpc, capabilitiesProvider, WellKnownLspServerKinds.CSharpVisualBasicLspServer, logger, hostServices);

src/Features/LanguageServer/Protocol/Handler/Configuration/DidChangeConfigurationNotificationHandlerFactory.cs

@@ -6,6 +6,7 @@
 using System.Composition;
 using Microsoft.CodeAnalysis.Host.Mef;
 using Microsoft.CodeAnalysis.Options;
+using Microsoft.CommonLanguageServerProtocol.Framework;
 
 namespace Microsoft.CodeAnalysis.LanguageServer.Handler.Configuration
 {
@@ -25,7 +26,7 @@ public DidChangeConfigurationNotificationHandlerFactory(
         public ILspService CreateILspService(LspServices lspServices, WellKnownLspServerKinds serverKind)
         {
             var clientManager = lspServices.GetRequiredService<IClientLanguageServerManager>();
-            var lspLogger = lspServices.GetRequiredService<ILspServiceLogger>();
+            var lspLogger = lspServices.GetRequiredService<AbstractLspLogger>();
             return new DidChangeConfigurationNotificationHandler(lspLogger, _globalOptionService, clientManager);
         }
     }

src/Features/LanguageServer/Protocol/Handler/RequestContextFactory.cs

@@ -23,7 +23,7 @@ public Task<RequestContext> CreateRequestContextAsync<TRequestParam>(IQueueItem<
     {
         var clientCapabilitiesManager = _lspServices.GetRequiredService<IInitializeManager>();
         var clientCapabilities = clientCapabilitiesManager.TryGetClientCapabilities();
-        var logger = _lspServices.GetRequiredService<ILspServiceLogger>();
+        var logger = _lspServices.GetRequiredService<AbstractLspLogger>();
         var serverInfoProvider = _lspServices.GetRequiredService<ServerInfoProvider>();
 
         if (clientCapabilities is null && queueItem.MethodName != Methods.InitializeName)