From 7fe194741576ae2efc0e05b0e9916d0649165990 Mon Sep 17 00:00:00 2001 From: Chris Rudolphi <1702962+clrudolphi@users.noreply.github.com> Date: Fri, 3 Jul 2026 18:33:40 -0500 Subject: [PATCH 1/4] Add LSP trace level support ($/setTrace, $/logTrace) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The server ignored InitializeParams.Trace entirely and had no support for the standard $/setTrace notification or for issuing $/logTrace notifications — no way for a client to opt into protocol tracing (#41). Add a TraceService that tracks the current InitializeTrace level (seeded from InitializeParams.Trace at the initialize handshake, updatable at runtime via a new SetTraceNotificationHandler for $/setTrace) and exposes Trace(message, verboseMessage) to send $/logTrace notifications — a no-op when trace is Off, and only building the verbose detail string when the level is Verbose. Wire it into OperationDurationRecorder, the existing centralized instrumentation seam for the four interactive performance targets, so enabling trace surfaces the same PERF measurements already written to the log file as $/logTrace notifications in the client's trace output. Broader per-request tracing across every handler is a natural follow-up if wanted, but this keeps the change to a single well-tested seam rather than a large cross-cutting refactor. Co-Authored-By: Claude Sonnet 5 --- .../Performance/OperationDurationRecorder.cs | 13 +++- .../LanguageServerOptionsExtensions.cs | 6 +- .../Hosting/Program.cs | 5 ++ .../Hosting/ServiceCollectionExtensions.cs | 11 +++- .../Tracing/ITraceService.cs | 26 ++++++++ .../Tracing/SetTraceNotificationHandler.cs | 27 ++++++++ .../Tracing/TraceService.cs | 40 ++++++++++++ .../OperationDurationRecorderTests.cs | 36 +++++++++++ .../SetTraceNotificationHandlerTests.cs | 20 ++++++ .../Tracing/TraceServiceTests.cs | 64 +++++++++++++++++++ 10 files changed, 244 insertions(+), 4 deletions(-) create mode 100644 src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/ITraceService.cs create mode 100644 src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/SetTraceNotificationHandler.cs create mode 100644 src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs create mode 100644 tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/SetTraceNotificationHandlerTests.cs create mode 100644 tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/TraceServiceTests.cs diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Diagnostics/Performance/OperationDurationRecorder.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Diagnostics/Performance/OperationDurationRecorder.cs index 2c0c48e..85a9928 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Diagnostics/Performance/OperationDurationRecorder.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Diagnostics/Performance/OperationDurationRecorder.cs @@ -7,6 +7,7 @@ using Reqnroll.IdeSupport.Common.Diagnostics; using Reqnroll.IdeSupport.LSP.Server.Hosting; using Reqnroll.IdeSupport.LSP.Server.Telemetry; +using Reqnroll.IdeSupport.LSP.Server.Tracing; namespace Reqnroll.IdeSupport.LSP.Server.Diagnostics.Performance; @@ -29,17 +30,20 @@ public sealed class OperationDurationRecorder : IOperationDurationRecorder private readonly ClientIdeContext _ide; private readonly ILspTelemetryService? _telemetry; private readonly IPerfTelemetrySampler _sampler; + private readonly ITraceService? _trace; public OperationDurationRecorder( IDeveroomLogger logger, ClientIdeContext ide, ILspTelemetryService? telemetry = null, - IPerfTelemetrySampler? sampler = null) + IPerfTelemetrySampler? sampler = null, + ITraceService? trace = null) { _logger = logger; _ide = ide; _telemetry = telemetry; _sampler = sampler ?? PerfTelemetrySampler.FromEnvironment(); + _trace = trace; } public IDisposable Measure(string operation, DocumentUri? uri = null) @@ -53,6 +57,13 @@ public void Record(string operation, double elapsedMs, DocumentUri? uri = null) ? $"PERF op={operation} ms={elapsedMs:F1}" : $"PERF op={operation} ms={elapsedMs:F1} uri={uri}"); + // F41: mirror the same measurement as a $/logTrace notification (a no-op unless the + // client opted into tracing via InitializeParams.Trace or $/setTrace). The URI only goes + // into the verbose detail, matching the log line's own privacy posture. + _trace?.Trace( + $"{operation}: {elapsedMs:F1}ms", + uri is null ? null : () => uri.ToString()); + // Secondary sink: sampled telemetry metric — no URI/path (privacy). if (_telemetry is not null && _sampler.ShouldSample()) { diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs index 94f0488..78840b6 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs @@ -17,6 +17,7 @@ using Reqnroll.IdeSupport.LSP.Server.Features.Rename; using Reqnroll.IdeSupport.LSP.Server.Features.SemanticTokens; using Reqnroll.IdeSupport.LSP.Server.Diagnostics.Performance; +using Reqnroll.IdeSupport.LSP.Server.Tracing; using Reqnroll.IdeSupport.LSP.Server.Protocol; using Reqnroll.IdeSupport.LSP.Server.Workspace; using OmniSharp.Extensions.LanguageServer.Protocol; @@ -41,7 +42,10 @@ public static void AddStandardHandlers(this LanguageServerOptions options) .AddHandler() .AddHandler() .AddHandler() - .AddHandler(); + .AddHandler() + // F41: standard $/setTrace notification, letting the client change the trace + // level at runtime. + .AddHandler(); } /// diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs index f645c73..2dfd28f 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs @@ -23,6 +23,7 @@ using Reqnroll.IdeSupport.LSP.Server.Configuration; using Reqnroll.IdeSupport.LSP.Server.Pipeline; using Reqnroll.IdeSupport.LSP.Server.Features.SemanticTokens; +using Reqnroll.IdeSupport.LSP.Server.Tracing; using Reqnroll.IdeSupport.LSP.Server.Workspace; namespace Reqnroll.IdeSupport.LSP.Server.Hosting; @@ -150,6 +151,10 @@ internal static void ConfigureServer(LanguageServerOptions options, string? clie options.OnInitialized((languageServer, request, response, ct) => { + // F41: respect the trace level the client asked for at the handshake; $/setTrace + // (SetTraceNotificationHandler) can change it afterwards. + languageServer.Services.GetRequiredService().Level = request.Trace; + var tokenService = languageServer.Services.GetRequiredService(); response.Capabilities.SemanticTokensProvider = new SemanticTokensRegistrationOptions.StaticOptions diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs index fed4a43..3cc4b24 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs @@ -37,6 +37,7 @@ using Reqnroll.IdeSupport.LSP.Server.Features.SemanticTokens; using Reqnroll.IdeSupport.LSP.Server.Telemetry; using Reqnroll.IdeSupport.LSP.Server.Tagging; +using Reqnroll.IdeSupport.LSP.Server.Tracing; using Reqnroll.IdeSupport.LSP.Server.Workspace; namespace Reqnroll.IdeSupport.LSP.Server.Hosting; @@ -72,11 +73,16 @@ public static IServiceCollection AddReqnrollLspCoreServices(this IServiceCollect // PERF lines to the log and (when REQNROLL_PERF_TELEMETRY_SAMPLE is set) emits sampled // PerfSample telemetry. Singleton so the sampler's RNG is shared across handlers. .AddSingleton(_ => PerfTelemetrySampler.FromEnvironment()) + // F41: tracks the LSP `trace` level (InitializeParams.Trace / $/setTrace) and issues + // $/logTrace notifications. Singleton so the level set by $/setTrace is visible to + // every consumer (currently OperationDurationRecorder's PERF lines). + .AddSingleton() .AddSingleton(sp => new OperationDurationRecorder( sp.GetRequiredService(), sp.GetRequiredService(), sp.GetRequiredService(), - sp.GetRequiredService())); + sp.GetRequiredService(), + sp.GetRequiredService())); } /// @@ -157,6 +163,7 @@ public static IServiceCollection AddReqnrollLspHandlers(this IServiceCollection .AddSingleton() .AddSingleton() .AddSingleton() - .AddSingleton(); + .AddSingleton() + .AddSingleton(); } } diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/ITraceService.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/ITraceService.cs new file mode 100644 index 0000000..7015ab3 --- /dev/null +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/ITraceService.cs @@ -0,0 +1,26 @@ +#nullable enable + +using OmniSharp.Extensions.LanguageServer.Protocol.Models; + +namespace Reqnroll.IdeSupport.LSP.Server.Tracing; + +/// +/// Tracks the LSP trace level negotiated with the client (F41) and issues +/// $/logTrace notifications when it is anything other than . +/// +public interface ITraceService +{ + /// + /// The current trace level: the value from InitializeParams.Trace at startup, + /// subsequently overridden by any $/setTrace notification. + /// + InitializeTrace Level { get; set; } + + /// + /// Sends a $/logTrace notification to the client, unless is + /// . is only invoked (and + /// only sent) when is , so callers + /// can defer building an expensive detail string until it is actually wanted. + /// + void Trace(string message, System.Func? verboseMessage = null); +} diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/SetTraceNotificationHandler.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/SetTraceNotificationHandler.cs new file mode 100644 index 0000000..8ece889 --- /dev/null +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/SetTraceNotificationHandler.cs @@ -0,0 +1,27 @@ +#nullable enable + +using MediatR; +using OmniSharp.Extensions.LanguageServer.Protocol.Models; +using OmniSharp.Extensions.LanguageServer.Protocol.Server; + +namespace Reqnroll.IdeSupport.LSP.Server.Tracing; + +/// +/// Handles the standard $/setTrace notification (F41), letting the client change the +/// trace level at runtime without restarting the server. +/// +public sealed class SetTraceNotificationHandler : SetTraceHandlerBase +{ + private readonly ITraceService _traceService; + + public SetTraceNotificationHandler(ITraceService traceService) + { + _traceService = traceService; + } + + public override Task Handle(SetTraceParams request, CancellationToken cancellationToken) + { + _traceService.Level = request.Value; + return Unit.Task; + } +} diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs new file mode 100644 index 0000000..802a248 --- /dev/null +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs @@ -0,0 +1,40 @@ +#nullable enable + +using OmniSharp.Extensions.LanguageServer.Protocol.Models; +using OmniSharp.Extensions.LanguageServer.Protocol.Server; + +namespace Reqnroll.IdeSupport.LSP.Server.Tracing; + +/// +public sealed class TraceService : ITraceService +{ + private readonly ILanguageServerFacade _languageServer; + private volatile InitializeTrace _level = InitializeTrace.Off; + + public TraceService(ILanguageServerFacade languageServer) + { + _languageServer = languageServer; + } + + public InitializeTrace Level + { + get => _level; + set => _level = value; + } + + public void Trace(string message, System.Func? verboseMessage = null) + { + var level = _level; + if (level == InitializeTrace.Off) + return; + + // ILanguageServerFacade doesn't implement ILanguageServer directly (the generated + // LogTrace(this ILanguageServer, ...) extension can't target it), but it does implement + // IResponseRouter — the same interface that extension delegates to internally. + _languageServer.SendNotification(new LogTraceParams + { + Message = message, + Verbose = level == InitializeTrace.Verbose ? verboseMessage?.Invoke() : null + }); + } +} diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Diagnostics/Performance/OperationDurationRecorderTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Diagnostics/Performance/OperationDurationRecorderTests.cs index 6a86445..1ccf419 100644 --- a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Diagnostics/Performance/OperationDurationRecorderTests.cs +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Diagnostics/Performance/OperationDurationRecorderTests.cs @@ -8,6 +8,7 @@ using Reqnroll.IdeSupport.LSP.Server.Diagnostics.Performance; using Reqnroll.IdeSupport.LSP.Server.Hosting; using Reqnroll.IdeSupport.LSP.Server.Telemetry; +using Reqnroll.IdeSupport.LSP.Server.Tracing; namespace Reqnroll.IdeSupport.LSP.Server.Tests.Diagnostics.Performance; @@ -122,6 +123,41 @@ public void Measure_records_on_dispose() .Which.Should().Contain("op=textDocument/semanticTokens/full"); } + [Fact] + public void Record_mirrors_the_measurement_as_a_trace_notification() + { + var trace = Substitute.For(); + var sut = new OperationDurationRecorder( + new CapturingLogger(), Ide(), telemetry: null, sampler: new FixedSampler(false), trace: trace); + + sut.Record("textDocument/completion#step", 42.5); + + trace.Received(1).Trace("textDocument/completion#step: 42.5ms", Arg.Any?>()); + } + + [Fact] + public void Record_does_not_pass_a_verbose_callback_when_no_uri_is_given() + { + var trace = Substitute.For(); + var sut = new OperationDurationRecorder( + new CapturingLogger(), Ide(), telemetry: null, sampler: new FixedSampler(false), trace: trace); + + sut.Record("textDocument/definition", 10); + + trace.Received(1).Trace(Arg.Any(), null); + } + + [Fact] + public void Record_works_without_a_trace_service() + { + var sut = new OperationDurationRecorder( + new CapturingLogger(), Ide(), telemetry: null, sampler: new FixedSampler(false)); + + var act = () => sut.Record("textDocument/definition", 10); + + act.Should().NotThrow(); + } + [Theory] [InlineData(5, "<=10")] [InlineData(40, "<=50")] diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/SetTraceNotificationHandlerTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/SetTraceNotificationHandlerTests.cs new file mode 100644 index 0000000..b959b7f --- /dev/null +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/SetTraceNotificationHandlerTests.cs @@ -0,0 +1,20 @@ +#nullable enable + +using OmniSharp.Extensions.LanguageServer.Protocol.Models; +using Reqnroll.IdeSupport.LSP.Server.Tracing; + +namespace Reqnroll.IdeSupport.LSP.Server.Tests.Tracing; + +public class SetTraceNotificationHandlerTests +{ + [Fact] + public async Task Handle_updates_the_trace_services_level() + { + var traceService = Substitute.For(); + var sut = new SetTraceNotificationHandler(traceService); + + await sut.Handle(new SetTraceParams { Value = InitializeTrace.Verbose }, CancellationToken.None); + + traceService.Level.Should().Be(InitializeTrace.Verbose); + } +} diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/TraceServiceTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/TraceServiceTests.cs new file mode 100644 index 0000000..8b24026 --- /dev/null +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Tracing/TraceServiceTests.cs @@ -0,0 +1,64 @@ +#nullable enable + +using MediatR; +using OmniSharp.Extensions.LanguageServer.Protocol.Models; +using OmniSharp.Extensions.LanguageServer.Protocol.Server; +using Reqnroll.IdeSupport.LSP.Server.Tracing; + +namespace Reqnroll.IdeSupport.LSP.Server.Tests.Tracing; + +public class TraceServiceTests +{ + private static TraceService CreateSut(ILanguageServerFacade facade) => new(facade); + + [Fact] + public void Trace_sends_nothing_when_level_is_Off() + { + var facade = Substitute.For(); + var sut = CreateSut(facade); + sut.Level = InitializeTrace.Off; + + sut.Trace("hello"); + + facade.DidNotReceiveWithAnyArgs().SendNotification(default(IRequest)!); + } + + [Fact] + public void Trace_sends_a_logTrace_notification_when_level_is_Messages() + { + var facade = Substitute.For(); + var sut = CreateSut(facade); + sut.Level = InitializeTrace.Messages; + + sut.Trace("hello"); + + facade.Received(1).SendNotification(Arg.Is(r => + ((LogTraceParams)r).Message == "hello" && ((LogTraceParams)r).Verbose == null)); + } + + [Fact] + public void Trace_does_not_invoke_the_verbose_callback_when_level_is_Messages() + { + var facade = Substitute.For(); + var sut = CreateSut(facade); + sut.Level = InitializeTrace.Messages; + var verboseCalled = false; + + sut.Trace("hello", () => { verboseCalled = true; return "detail"; }); + + verboseCalled.Should().BeFalse("verbose detail should only be computed when trace is Verbose"); + } + + [Fact] + public void Trace_includes_verbose_detail_when_level_is_Verbose() + { + var facade = Substitute.For(); + var sut = CreateSut(facade); + sut.Level = InitializeTrace.Verbose; + + sut.Trace("hello", () => "detail"); + + facade.Received(1).SendNotification(Arg.Is(r => + ((LogTraceParams)r).Message == "hello" && ((LogTraceParams)r).Verbose == "detail")); + } +} From ef3e975b073e6bb47373458d7b58adc585c0e2ff Mon Sep 17 00:00:00 2001 From: Chris Rudolphi <1702962+clrudolphi@users.noreply.github.com> Date: Fri, 3 Jul 2026 19:16:29 -0500 Subject: [PATCH 2/4] Add --trace CLI default and fix VS Code's always-on trace level MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two follow-ups to the $/setTrace / $/logTrace support: - Server: add a --trace command-line default, mirroring --log-level. Precedence is cmdline -> InitializeParams.Trace -> $/setTrace, but InitializeTrace.Off is indistinguishable from "the client didn't set this field" so it must not clobber an explicit --trace default — only override when the client actually asked for something (Program.ResolveInitialTrace). - VS Code: TeeLogOutputChannel.logLevel was hardcoded to Trace so vscode-languageclient would always capture full wire traffic for the lsp-viewer inspector log file. But vscode-languageclient also reads that same logLevel to decide what to send as InitializeParams.Trace and later $/setTrace — hardcoding it meant every VS Code session told the server to trace at least "messages", regardless of the `reqnroll.trace.server` setting the server now actually listens to. logLevel now mirrors that setting directly (Off when 'off', Trace otherwise), and fires onDidChangeLogLevel on live setting changes so vscode-languageclient's own config-change handling sends an updated $/setTrace without a window reload. VS extension still doesn't set InitializeParams.Trace or send $/setTrace at all, so the new --trace command-line default is the only lever available there for now (a future PR would need to wire the picker/setting through to the server args or send $/setTrace). Co-Authored-By: Claude Sonnet 5 --- .../Hosting/Program.cs | 50 ++++++++++++++++--- .../Hosting/ServiceCollectionExtensions.cs | 13 +++-- .../Tracing/TraceService.cs | 3 +- src/VSCode/src/lspInspectorLogger.ts | 33 +++++++++--- .../src/test/lspInspectorLogger.test.ts | 42 +++++++++++++++- .../Hosting/ProgramTests.cs | 39 +++++++++++++++ 6 files changed, 160 insertions(+), 20 deletions(-) diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs index 2dfd28f..9f2be1e 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs @@ -43,6 +43,12 @@ public static async Task Main(string[] args) // write maximum-verbosity logs indefinitely; pass --log-level Verbose for full tracing. var logLevel = ParseLogLevel(args); + // F41: --trace seeds the LSP protocol trace level (distinct from + // --log-level's file/protocol-log verbosity above) before the client ever connects, so an + // IDE glue component that doesn't populate InitializeParams.Trace still gets a configurable + // default. See ConfigureServer's initialTrace parameter for the full precedence order. + var initialTrace = ParseTraceLevel(args); + // Write any unhandled startup exception to a file next to the LSP inspector logs // so crashes are self-diagnosing without needing to capture stderr. try @@ -57,7 +63,7 @@ public static async Task Main(string[] args) // Production transport: the IDE talks to the server over stdio. options.WithInput(Console.OpenStandardInput()) .WithOutput(Console.OpenStandardOutput()); - ConfigureServer(options, ideId, logLevel); + ConfigureServer(options, ideId, logLevel, initialTrace); }); using var preloadCts = new CancellationTokenSource(); @@ -114,8 +120,21 @@ public static async Task Main(string[] args) /// and the OmniSharp protocol-logging minimum level, so wire-level debugging and file logging /// stay in lockstep unless a caller explicitly asks for more (e.g. --log-level Verbose). /// + /// + /// F41: the LSP protocol trace level ($/logTrace), resolved with the following + /// precedence — later stages only apply when they actually say something: + /// + /// this --trace command-line default (defaults to ); + /// InitializeParams.Trace, applied in OnInitialized below — + /// but only when the client sent something other than , since + /// that value is indistinguishable from "the client didn't set this field at all" and must not + /// silently clobber an explicit --trace default; + /// $/setTrace (), which can + /// set any value — including back to Off — at any time after that. + /// + /// internal static void ConfigureServer(LanguageServerOptions options, string? clientIde = null, - TraceLevel logLevel = TraceLevel.Warning) + TraceLevel logLevel = TraceLevel.Warning, InitializeTrace initialTrace = InitializeTrace.Off) { options.ConfigureLogging(logging => { @@ -138,7 +157,7 @@ internal static void ConfigureServer(LanguageServerOptions options, string? clie // notification to two handler instances (the transient from the scan and // the singleton from the explicit call). .AddMediatR(typeof(Program).Assembly) - .AddReqnrollLspCoreServices(clientIde, logLevel) + .AddReqnrollLspCoreServices(clientIde, logLevel, initialTrace) .AddReqnrollProjectSystem() .AddReqnrollEditorServices() .AddReqnrollLspHandlers(); @@ -151,9 +170,12 @@ internal static void ConfigureServer(LanguageServerOptions options, string? clie options.OnInitialized((languageServer, request, response, ct) => { - // F41: respect the trace level the client asked for at the handshake; $/setTrace - // (SetTraceNotificationHandler) can change it afterwards. - languageServer.Services.GetRequiredService().Level = request.Trace; + // F41: apply the client's requested trace level over the --trace command-line + // default, unless the client didn't actually request one. $/setTrace + // (SetTraceNotificationHandler) can still change the level — including back to + // Off — at any time after this. + var traceService = languageServer.Services.GetRequiredService(); + traceService.Level = ResolveInitialTrace(traceService.Level, request.Trace); var tokenService = languageServer.Services.GetRequiredService(); @@ -226,4 +248,20 @@ internal static TraceLevel ParseLogLevel(string[] args) => Enum.TryParse(ParseArg(args, "--log-level"), ignoreCase: true, out var parsedLevel) ? parsedLevel : TraceLevel.Warning; + + /// Parses --trace (Off/Messages/Verbose) from , defaulting to when absent or unrecognized. + internal static InitializeTrace ParseTraceLevel(string[] args) + => Enum.TryParse(ParseArg(args, "--trace"), ignoreCase: true, out var parsedLevel) + ? parsedLevel + : InitializeTrace.Off; + + /// + /// F41: resolves the trace level to apply at the initialize handshake. (InitializeParams.Trace) wins whenever the client actually asked + /// for something; there is indistinguishable from "the + /// client didn't set this field", so it must not clobber (the + /// --trace command-line default). + /// + internal static InitializeTrace ResolveInitialTrace(InitializeTrace current, InitializeTrace requested) + => requested == InitializeTrace.Off ? current : requested; } diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs index 3cc4b24..8ceb77d 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/ServiceCollectionExtensions.cs @@ -1,6 +1,7 @@ using System.Diagnostics; using MediatR; using Microsoft.Extensions.DependencyInjection; +using OmniSharp.Extensions.LanguageServer.Protocol.Models; using Reqnroll.IdeSupport.Common; using Reqnroll.IdeSupport.Common.Configuration; using Reqnroll.IdeSupport.Common.Diagnostics; @@ -51,7 +52,7 @@ public static class ServiceCollectionExtensions /// Registers core infrastructure and cross-cutting services. /// public static IServiceCollection AddReqnrollLspCoreServices(this IServiceCollection services, string? clientIde, - TraceLevel logLevel = TraceLevel.Warning) + TraceLevel logLevel = TraceLevel.Warning, InitializeTrace initialTrace = InitializeTrace.Off) { return services .AddSingleton(new ClientIdeContext(clientIde, logLevel)) @@ -73,10 +74,12 @@ public static IServiceCollection AddReqnrollLspCoreServices(this IServiceCollect // PERF lines to the log and (when REQNROLL_PERF_TELEMETRY_SAMPLE is set) emits sampled // PerfSample telemetry. Singleton so the sampler's RNG is shared across handlers. .AddSingleton(_ => PerfTelemetrySampler.FromEnvironment()) - // F41: tracks the LSP `trace` level (InitializeParams.Trace / $/setTrace) and issues - // $/logTrace notifications. Singleton so the level set by $/setTrace is visible to - // every consumer (currently OperationDurationRecorder's PERF lines). - .AddSingleton() + // F41: tracks the LSP `trace` level (--trace / InitializeParams.Trace / $/setTrace) and + // issues $/logTrace notifications. Singleton so the level set by $/setTrace is visible + // to every consumer (currently OperationDurationRecorder's PERF lines). + .AddSingleton(sp => new TraceService( + sp.GetRequiredService(), + initialTrace)) .AddSingleton(sp => new OperationDurationRecorder( sp.GetRequiredService(), sp.GetRequiredService(), diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs index 802a248..80f25b7 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs @@ -11,9 +11,10 @@ public sealed class TraceService : ITraceService private readonly ILanguageServerFacade _languageServer; private volatile InitializeTrace _level = InitializeTrace.Off; - public TraceService(ILanguageServerFacade languageServer) + public TraceService(ILanguageServerFacade languageServer, InitializeTrace initialLevel = InitializeTrace.Off) { _languageServer = languageServer; + _level = initialLevel; } public InitializeTrace Level diff --git a/src/VSCode/src/lspInspectorLogger.ts b/src/VSCode/src/lspInspectorLogger.ts index 9e5a35f..6806663 100644 --- a/src/VSCode/src/lspInspectorLogger.ts +++ b/src/VSCode/src/lspInspectorLogger.ts @@ -9,9 +9,15 @@ import * as vscode from 'vscode'; * * Why LogOutputChannel (not plain OutputChannel): * vscode-languageclient v10 types traceOutputChannel as LogOutputChannel and - * reads its logLevel property at construction time to set the internal trace - * level. We always return LogLevel.Trace from logLevel so the client enables - * tracing and routes messages to channel.trace(). + * reads its logLevel property to decide whether tracing is enabled at all + * (see refreshTrace in its client.js): logLevel !== Trace collapses straight + * to Trace.Off, bypassing the `reqnroll.trace.server` setting entirely; + * anything else lets that setting pick Messages/Verbose. logLevel must + * therefore mirror the same setting `createTraceChannel` used to decide + * whether to allocate this channel in the first place — hardcoding it to + * Trace (as this class used to) meant vscode-languageclient always sent at + * least `trace: "messages"` in InitializeParams and via $/setTrace on + * config changes, even when the user had chosen "off". * * Why only trace() writes to file: * vscode-languageclient routes all LSP request/response/notification entries @@ -37,21 +43,32 @@ class TeeLogOutputChannel implements vscode.LogOutputChannel { readonly name: string; private readonly _inner: vscode.LogOutputChannel; private _stream: fs.WriteStream | undefined; + private readonly _onDidChangeLogLevel = new vscode.EventEmitter(); + private readonly _configListener: vscode.Disposable; constructor(name: string, stream: fs.WriteStream | undefined) { this._inner = vscode.window.createOutputChannel(name, { log: true }); this.name = this._inner.name; this._stream = stream; + // vscode-languageclient's own onDidChangeConfiguration listener calls + // refreshTrace(), but that reads a *cached* copy of logLevel that only + // updates via onDidChangeLogLevel — so this channel must fire its own + // event on the same setting change for a live "off" toggle (no window + // reload) to actually reach the server as `$/setTrace`. + this._configListener = vscode.workspace.onDidChangeConfiguration((e) => { + if (e.affectsConfiguration('reqnroll.trace.server')) { + this._onDidChangeLogLevel.fire(this.logLevel); + } + }); } get logLevel(): vscode.LogLevel { - // Always report Trace so vscode-languageclient enables tracing and routes - // all LSP messages to channel.trace() rather than suppressing them. - return vscode.LogLevel.Trace; + const level = vscode.workspace.getConfiguration('reqnroll').get('trace.server', 'off'); + return level === 'off' ? vscode.LogLevel.Off : vscode.LogLevel.Trace; } get onDidChangeLogLevel(): vscode.Event { - return this._inner.onDidChangeLogLevel; + return this._onDidChangeLogLevel.event; } trace(message: string, ...args: unknown[]): void { @@ -100,6 +117,8 @@ class TeeLogOutputChannel implements vscode.LogOutputChannel { this._inner.dispose(); this._stream?.end(); this._stream = undefined; + this._configListener.dispose(); + this._onDidChangeLogLevel.dispose(); } private _writeLspEntry(message: string): void { diff --git a/src/VSCode/src/test/lspInspectorLogger.test.ts b/src/VSCode/src/test/lspInspectorLogger.test.ts index 4dd04e7..3909456 100644 --- a/src/VSCode/src/test/lspInspectorLogger.test.ts +++ b/src/VSCode/src/test/lspInspectorLogger.test.ts @@ -1,6 +1,6 @@ import * as assert from 'assert'; import * as vscode from 'vscode'; -import { traceServerToLogLevel } from '../lspInspectorLogger'; +import { createTraceChannel, traceServerToLogLevel } from '../lspInspectorLogger'; suite('traceServerToLogLevel', () => { const config = vscode.workspace.getConfiguration('reqnroll'); @@ -29,3 +29,43 @@ suite('traceServerToLogLevel', () => { assert.strictEqual(traceServerToLogLevel(), 'Verbose'); }); }); + +// The channel's logLevel is what vscode-languageclient reads to decide the InitializeParams.Trace +// value it sends the server (see the TeeLogOutputChannel doc comment) — it must track the +// `reqnroll.trace.server` setting rather than always claiming Trace, or the server ends up +// tracing regardless of what the user actually asked for. +suite('createTraceChannel logLevel', () => { + const config = vscode.workspace.getConfiguration('reqnroll'); + let channel: vscode.LogOutputChannel; + + teardown(async () => { + channel?.dispose(); + await config.update('trace.server', undefined, vscode.ConfigurationTarget.Global); + }); + + test("reports Trace when the setting is 'messages'", async () => { + await config.update('trace.server', 'messages', vscode.ConfigurationTarget.Global); + channel = createTraceChannel(); + assert.strictEqual(channel.logLevel, vscode.LogLevel.Trace); + }); + + test("reports Trace when the setting is 'verbose'", async () => { + await config.update('trace.server', 'verbose', vscode.ConfigurationTarget.Global); + channel = createTraceChannel(); + assert.strictEqual(channel.logLevel, vscode.LogLevel.Trace); + }); + + test('reflects a live setting change back to off, and fires onDidChangeLogLevel', async () => { + await config.update('trace.server', 'verbose', vscode.ConfigurationTarget.Global); + channel = createTraceChannel(); + assert.strictEqual(channel.logLevel, vscode.LogLevel.Trace); + + const changed = new Promise((resolve) => { + channel.onDidChangeLogLevel((level) => resolve(level)); + }); + await config.update('trace.server', 'off', vscode.ConfigurationTarget.Global); + + assert.strictEqual(await changed, vscode.LogLevel.Off); + assert.strictEqual(channel.logLevel, vscode.LogLevel.Off); + }); +}); diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs index 98b6013..790cf7a 100644 --- a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs @@ -1,5 +1,6 @@ using System.Diagnostics; using Microsoft.Extensions.Logging; +using OmniSharp.Extensions.LanguageServer.Protocol.Models; using Reqnroll.IdeSupport.LSP.Server.Hosting; namespace Reqnroll.IdeSupport.LSP.Server.Tests.Hosting; @@ -48,6 +49,44 @@ public void ParseArg_returns_null_when_the_flag_is_absent() Program.ParseArg(new[] { "--ide", "vscode" }, "--log-level").Should().BeNull(); } + [Fact] + public void ParseTraceLevel_defaults_to_Off_when_flag_is_absent() + { + Program.ParseTraceLevel(new[] { "--ide", "visualstudio" }).Should().Be(InitializeTrace.Off); + } + + [Fact] + public void ParseTraceLevel_defaults_to_Off_for_no_args() + { + Program.ParseTraceLevel(Array.Empty()).Should().Be(InitializeTrace.Off); + } + + [Theory] + [InlineData("Off", InitializeTrace.Off)] + [InlineData("MESSAGES", InitializeTrace.Messages)] + [InlineData("verbose", InitializeTrace.Verbose)] + public void ParseTraceLevel_parses_case_insensitively(string arg, InitializeTrace expected) + { + Program.ParseTraceLevel(new[] { "--trace", arg }).Should().Be(expected); + } + + [Fact] + public void ParseTraceLevel_defaults_to_Off_for_an_unrecognized_value() + { + Program.ParseTraceLevel(new[] { "--trace", "not-a-level" }).Should().Be(InitializeTrace.Off); + } + + [Theory] + [InlineData(InitializeTrace.Off, InitializeTrace.Off, InitializeTrace.Off)] + [InlineData(InitializeTrace.Verbose, InitializeTrace.Off, InitializeTrace.Verbose)] + [InlineData(InitializeTrace.Off, InitializeTrace.Messages, InitializeTrace.Messages)] + [InlineData(InitializeTrace.Verbose, InitializeTrace.Messages, InitializeTrace.Messages)] + public void ResolveInitialTrace_prefers_the_requested_level_unless_it_is_Off( + InitializeTrace current, InitializeTrace requested, InitializeTrace expected) + { + Program.ResolveInitialTrace(current, requested).Should().Be(expected); + } + [Theory] [InlineData(TraceLevel.Off, LogLevel.None)] [InlineData(TraceLevel.Error, LogLevel.Error)] From 0bb611e9adaa1e81300b8e55b5c034d534fdd205 Mon Sep 17 00:00:00 2001 From: Chris Rudolphi <1702962+clrudolphi@users.noreply.github.com> Date: Sat, 4 Jul 2026 07:48:45 -0500 Subject: [PATCH 3/4] Bridge OmniSharp's internal diagnostics to a file; decouple --log-level from protocol logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two follow-ups from an audit of the logging/tracing story after $/setTrace and $/logTrace landed: - OmniSharp's own internal diagnostics (request dispatch, DryIoc, JSON-RPC plumbing) only ever reached window/logMessage — visible to the connected client, never persisted anywhere we can look at after the fact. Add ProtocolLoggerProvider, an ILoggerProvider that bridges those Microsoft.Extensions.Logging entries into a dedicated reqnroll-*-protocol-*.log file (separate from the main server log, so two independent writers never append to the same file concurrently). - --log-level was doing double duty: gating both our own file logger AND logging.SetMinimumLevel(...) for the OmniSharp-internal pipeline above. Turning up file logging for our own diagnosis would also flood the client's Output panel with library internals, and there was no way to ask for library-internal detail without also cranking our own app log. Add --protocol-log-level as an independent dial (same Off/Error/Warning/ Info/Verbose scale, same Warning default) purely for the OmniSharp pipeline; --log-level now controls only IDeveroomLogger's own file. Co-Authored-By: Claude Sonnet 5 --- .../Hosting/Program.cs | 40 +++++-- .../Logging/ProtocolLoggerProvider.cs | 100 ++++++++++++++++++ .../Hosting/ProgramTests.cs | 38 +++++++ .../Logging/ProtocolLoggerProviderTests.cs | 81 ++++++++++++++ 4 files changed, 251 insertions(+), 8 deletions(-) create mode 100644 src/LSP/Reqnroll.IdeSupport.LSP.Server/Logging/ProtocolLoggerProvider.cs create mode 100644 tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Logging/ProtocolLoggerProviderTests.cs diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs index 9f2be1e..45f4f21 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/Program.cs @@ -41,10 +41,18 @@ public static async Task Main(string[] args) // Each IDE's glue component may pass --log-level (Off/Error/Warning/Info/Verbose) // when spawning the server. Defaults to Warning when absent so a normal session doesn't // write maximum-verbosity logs indefinitely; pass --log-level Verbose for full tracing. + // Controls ONLY our own app-level IDeveroomLogger file (reqnroll-*-server-*.log). var logLevel = ParseLogLevel(args); - // F41: --trace seeds the LSP protocol trace level (distinct from - // --log-level's file/protocol-log verbosity above) before the client ever connects, so an + // --protocol-log-level is the equivalent dial for OmniSharp's own internal + // diagnostics (request dispatch, DryIoc, JSON-RPC plumbing — whatever the library logs via + // ILogger), deliberately decoupled from --log-level: turning up our own app logging + // shouldn't also flood the client's Output panel (window/logMessage) or a separate protocol + // log file with library internals, and vice versa. See ConfigureServer for where it's used. + var protocolLogLevel = ParseProtocolLogLevel(args); + + // F41: --trace seeds the LSP protocol trace level ($/logTrace) — + // yet another independent dial from the two above — before the client ever connects, so an // IDE glue component that doesn't populate InitializeParams.Trace still gets a configurable // default. See ConfigureServer's initialTrace parameter for the full precedence order. var initialTrace = ParseTraceLevel(args); @@ -63,7 +71,7 @@ public static async Task Main(string[] args) // Production transport: the IDE talks to the server over stdio. options.WithInput(Console.OpenStandardInput()) .WithOutput(Console.OpenStandardOutput()); - ConfigureServer(options, ideId, logLevel, initialTrace); + ConfigureServer(options, ideId, logLevel, initialTrace, protocolLogLevel); }); using var preloadCts = new CancellationTokenSource(); @@ -116,9 +124,8 @@ public static async Task Main(string[] args) /// /// /// The --log-level verbosity requested by the client, defaulting to - /// . Drives both the file-backed - /// and the OmniSharp protocol-logging minimum level, so wire-level debugging and file logging - /// stay in lockstep unless a caller explicitly asks for more (e.g. --log-level Verbose). + /// . Drives only the file-backed + /// (our own app-level logging) — deliberately independent of . /// /// /// F41: the LSP protocol trace level ($/logTrace), resolved with the following @@ -133,13 +140,24 @@ public static async Task Main(string[] args) /// set any value — including back to Off — at any time after that. /// /// + /// + /// The --protocol-log-level verbosity for OmniSharp's own internal diagnostics, + /// defaulting to . Drives the OmniSharp protocol-logging + /// minimum level, which feeds both the standard window/logMessage notification + /// (AddLanguageProtocolLogging(), visible to the client) and + /// (a dedicated reqnroll-*-protocol-*.log file, so that content survives even if the + /// client's Output panel is never inspected). Independent of — + /// see that parameter's remarks. + /// internal static void ConfigureServer(LanguageServerOptions options, string? clientIde = null, - TraceLevel logLevel = TraceLevel.Warning, InitializeTrace initialTrace = InitializeTrace.Off) + TraceLevel logLevel = TraceLevel.Warning, InitializeTrace initialTrace = InitializeTrace.Off, + TraceLevel protocolLogLevel = TraceLevel.Warning) { options.ConfigureLogging(logging => { - logging.SetMinimumLevel(ToLogLevel(logLevel)); + logging.SetMinimumLevel(ToLogLevel(protocolLogLevel)); logging.AddLanguageProtocolLogging(); + logging.AddProvider(new ProtocolLoggerProvider(clientIde, protocolLogLevel)); }); options.WithServerInfo(new ServerInfo @@ -249,6 +267,12 @@ internal static TraceLevel ParseLogLevel(string[] args) ? parsedLevel : TraceLevel.Warning; + /// Parses --protocol-log-level from , defaulting to when absent or unrecognized. + internal static TraceLevel ParseProtocolLogLevel(string[] args) + => Enum.TryParse(ParseArg(args, "--protocol-log-level"), ignoreCase: true, out var parsedLevel) + ? parsedLevel + : TraceLevel.Warning; + /// Parses --trace (Off/Messages/Verbose) from , defaulting to when absent or unrecognized. internal static InitializeTrace ParseTraceLevel(string[] args) => Enum.TryParse(ParseArg(args, "--trace"), ignoreCase: true, out var parsedLevel) diff --git a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Logging/ProtocolLoggerProvider.cs b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Logging/ProtocolLoggerProvider.cs new file mode 100644 index 0000000..b4ee468 --- /dev/null +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Logging/ProtocolLoggerProvider.cs @@ -0,0 +1,100 @@ +#nullable enable + +using System.Diagnostics; +using Microsoft.Extensions.Logging; +using Reqnroll.IdeSupport.Common.Diagnostics; + +namespace Reqnroll.IdeSupport.LSP.Server.Logging; + +/// +/// Bridges OmniSharp's own internal diagnostics +/// (request dispatch, DryIoc, JSON-RPC plumbing — whatever the library itself logs via +/// ILogger<T>) into a dedicated Reqnroll log file, in addition to the existing +/// window/logMessage notification (AddLanguageProtocolLogging()) that only reaches +/// the connected client. +/// +/// +/// Without this, OmniSharp-internal diagnostics exist only as a transient client notification — +/// if the user doesn't think to copy their editor's Output panel, that information is gone by the +/// time we're asked to look at a bug report. Writes to a separate reqnroll-*-protocol-*.log +/// file (not the main server log) so two independent writers never append to the same file +/// concurrently, and gated by its own --protocol-log-level rather than the main +/// --log-level — the two are deliberately decoupled (F41 follow-up): a user turning up file +/// logging for our own app-level diagnosis shouldn't also flood their editor's Output panel with +/// library internals, and vice versa. +/// +public sealed class ProtocolLoggerProvider : ILoggerProvider +{ + private readonly IDeveroomLogger _logger; + + public ProtocolLoggerProvider(string? clientIde, TraceLevel protocolLogLevel) + : this(BuildDefaultLogger(clientIde, protocolLogLevel)) + { + } + + /// Test seam: bypasses the real file/debug sinks. + internal ProtocolLoggerProvider(IDeveroomLogger logger) + { + _logger = logger; + } + + private static IDeveroomLogger BuildDefaultLogger(string? clientIde, TraceLevel protocolLogLevel) + { + var idePrefix = clientIde switch + { + "visualstudio" => "vs", + "vscode" => "vscode", + _ => "lsp" + }; + return new DeveroomCompositeLogger() + .Add(new DeveroomDebugLogger()) + .Add(new SynchronousFileLogger(idePrefix, "protocol", protocolLogLevel)); + } + + public ILogger CreateLogger(string categoryName) => new ProtocolLoggerAdapter(categoryName, _logger); + + public void Dispose() + { + } +} + +/// Adapts a single category onto . +internal sealed class ProtocolLoggerAdapter : ILogger +{ + private readonly string _categoryName; + private readonly IDeveroomLogger _logger; + + public ProtocolLoggerAdapter(string categoryName, IDeveroomLogger logger) + { + _categoryName = categoryName; + _logger = logger; + } + + // The .NET logging pipeline already applies logging.SetMinimumLevel(...) before this + // method is ever invoked, so no further filtering is needed here — only the + // IDeveroomLogger sink's own level (protocolLogLevel) applies from this point on. + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + _logger.Log(new LogMessage(ToTraceLevel(logLevel), formatter(state, exception), _categoryName, exception)); + } + + public IDisposable BeginScope(TState state) => NullScope.Instance; + + private sealed class NullScope : IDisposable + { + public static readonly NullScope Instance = new(); + public void Dispose() { } + } + + internal static TraceLevel ToTraceLevel(LogLevel level) => level switch + { + LogLevel.Trace or LogLevel.Debug => TraceLevel.Verbose, + LogLevel.Information => TraceLevel.Info, + LogLevel.Warning => TraceLevel.Warning, + LogLevel.Error or LogLevel.Critical => TraceLevel.Error, + _ => TraceLevel.Off, + }; +} diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs index 790cf7a..a6f3ee7 100644 --- a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs @@ -36,6 +36,44 @@ public void ParseLogLevel_defaults_to_Warning_for_an_unrecognized_value() Program.ParseLogLevel(new[] { "--log-level", "not-a-level" }).Should().Be(TraceLevel.Warning); } + [Fact] + public void ParseProtocolLogLevel_defaults_to_Warning_when_flag_is_absent() + { + Program.ParseProtocolLogLevel(new[] { "--ide", "visualstudio" }).Should().Be(TraceLevel.Warning); + } + + [Fact] + public void ParseProtocolLogLevel_defaults_to_Warning_for_no_args() + { + Program.ParseProtocolLogLevel(Array.Empty()).Should().Be(TraceLevel.Warning); + } + + [Theory] + [InlineData("Off", TraceLevel.Off)] + [InlineData("error", TraceLevel.Error)] + [InlineData("WARNING", TraceLevel.Warning)] + [InlineData("Info", TraceLevel.Info)] + [InlineData("verbose", TraceLevel.Verbose)] + public void ParseProtocolLogLevel_parses_case_insensitively(string arg, TraceLevel expected) + { + Program.ParseProtocolLogLevel(new[] { "--protocol-log-level", arg }).Should().Be(expected); + } + + [Fact] + public void ParseProtocolLogLevel_defaults_to_Warning_for_an_unrecognized_value() + { + Program.ParseProtocolLogLevel(new[] { "--protocol-log-level", "not-a-level" }).Should().Be(TraceLevel.Warning); + } + + [Fact] + public void ParseProtocolLogLevel_is_independent_of_log_level() + { + var args = new[] { "--log-level", "Off", "--protocol-log-level", "Verbose" }; + + Program.ParseLogLevel(args).Should().Be(TraceLevel.Off); + Program.ParseProtocolLogLevel(args).Should().Be(TraceLevel.Verbose); + } + [Fact] public void ParseArg_returns_the_value_following_the_flag() { diff --git a/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Logging/ProtocolLoggerProviderTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Logging/ProtocolLoggerProviderTests.cs new file mode 100644 index 0000000..9a89365 --- /dev/null +++ b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Logging/ProtocolLoggerProviderTests.cs @@ -0,0 +1,81 @@ +#nullable enable + +using System.Diagnostics; +using Microsoft.Extensions.Logging; +using Reqnroll.IdeSupport.Common.Diagnostics; +using Reqnroll.IdeSupport.LSP.Server.Logging; + +namespace Reqnroll.IdeSupport.LSP.Server.Tests.Logging; + +public class ProtocolLoggerProviderTests +{ + private sealed class CapturingLogger : IDeveroomLogger + { + public TraceLevel Level => TraceLevel.Verbose; + public List Messages { get; } = new(); + public void Log(LogMessage message) => Messages.Add(message); + } + + [Fact] + public void CreateLogger_returns_a_logger_that_forwards_to_the_underlying_IDeveroomLogger() + { + var captured = new CapturingLogger(); + var provider = new ProtocolLoggerProvider(captured); + + var logger = provider.CreateLogger("OmniSharp.Extensions.LanguageServer.Server.LanguageServer"); + logger.Log(LogLevel.Information, new EventId(0), "state", null, (s, _) => "handling request"); + + var message = captured.Messages.Should().ContainSingle().Subject; + message.Message.Should().Be("handling request"); + message.Level.Should().Be(TraceLevel.Info); + message.CallerMethod.Should().Be("OmniSharp.Extensions.LanguageServer.Server.LanguageServer"); + message.Exception.Should().BeNull(); + } + + [Fact] + public void CreateLogger_forwards_the_exception() + { + var captured = new CapturingLogger(); + var provider = new ProtocolLoggerProvider(captured); + var ex = new InvalidOperationException("boom"); + + var logger = provider.CreateLogger("Category"); + logger.Log(LogLevel.Error, new EventId(0), "state", ex, (s, e) => "failed"); + + captured.Messages.Should().ContainSingle().Which.Exception.Should().BeSameAs(ex); + } + + [Fact] + public void IsEnabled_is_always_true_because_SetMinimumLevel_already_filtered_upstream() + { + var adapter = new ProtocolLoggerAdapter("cat", new CapturingLogger()); + + adapter.IsEnabled(LogLevel.Trace).Should().BeTrue(); + adapter.IsEnabled(LogLevel.Critical).Should().BeTrue(); + } + + [Fact] + public void BeginScope_returns_a_disposable_that_does_not_throw() + { + var adapter = new ProtocolLoggerAdapter("cat", new CapturingLogger()); + + var scope = adapter.BeginScope("state"); + + scope.Should().NotBeNull(); + var act = () => scope.Dispose(); + act.Should().NotThrow(); + } + + [Theory] + [InlineData(LogLevel.Trace, TraceLevel.Verbose)] + [InlineData(LogLevel.Debug, TraceLevel.Verbose)] + [InlineData(LogLevel.Information, TraceLevel.Info)] + [InlineData(LogLevel.Warning, TraceLevel.Warning)] + [InlineData(LogLevel.Error, TraceLevel.Error)] + [InlineData(LogLevel.Critical, TraceLevel.Error)] + [InlineData(LogLevel.None, TraceLevel.Off)] + public void ToTraceLevel_maps_each_LogLevel(LogLevel logLevel, TraceLevel expected) + { + ProtocolLoggerAdapter.ToTraceLevel(logLevel).Should().Be(expected); + } +} From 4080b0b8e7995e12be0c10abbd447e59cddb31d7 Mon Sep 17 00:00:00 2001 From: Chris Rudolphi <1702962+clrudolphi@users.noreply.github.com> Date: Sun, 5 Jul 2026 10:17:10 -0500 Subject: [PATCH 4/4] Wire --trace and --protocol-log-level into VS server launch (F41) Visual Studio had no way to enable LSP tracing or OmniSharp's internal diagnostics: unlike VS Code's reqnroll.trace.server setting, VS's ILanguageClient gives the extension no hook to set InitializeParams.Trace or send $/setTrace, so the server always ran at CLI defaults (Off/Warning). Pass explicit --trace and --protocol-log-level (and align --log-level) alongside --ide, with chattier defaults in DEBUG builds since there's no VS-side UI to turn these up after the fact. Co-Authored-By: Claude Sonnet 5 --- .../LspServerConnectionService.cs | 18 ++++++++++++++---- .../LspServerConnectionServiceTests.cs | 13 +++++++++++-- 2 files changed, 25 insertions(+), 6 deletions(-) diff --git a/src/VisualStudio/Reqnroll.IdeSupport.VisualStudio.Extension/LspInterception/LspServerConnectionService.cs b/src/VisualStudio/Reqnroll.IdeSupport.VisualStudio.Extension/LspInterception/LspServerConnectionService.cs index 5ea31b8..2da93d0 100644 --- a/src/VisualStudio/Reqnroll.IdeSupport.VisualStudio.Extension/LspInterception/LspServerConnectionService.cs +++ b/src/VisualStudio/Reqnroll.IdeSupport.VisualStudio.Extension/LspInterception/LspServerConnectionService.cs @@ -112,11 +112,21 @@ internal static string ResolveServerExePath(string extensionAssemblyLocation) /// /// The command-line arguments passed to the LSP server process: --ide selects the - /// semantic token profile, --log-level keeps the server's own file/protocol logging in - /// step with the client's default rather than the server falling back to its own default - /// independently. Extracted as a constant so it's unit-testable without spawning a process. + /// semantic token profile; --log-level, --protocol-log-level, and --trace + /// set the server's own file logging, OmniSharp's internal diagnostics, and the LSP + /// $/logTrace level respectively, rather than letting the server fall back to its own + /// defaults independently. A DEBUG build of this extension (a developer F5-ing the extension + /// project, not an installed VSIX) asks for the chattiest reasonable defaults across all three; + /// a RELEASE build — what real users run — asks for quiet ones, since VS itself has no UI for + /// a user to raise these afterward (unlike VS Code's reqnroll.trace.server setting). + /// Extracted as a constant so it's unit-testable without spawning a process. /// - internal const string ServerArguments = "--ide visualstudio --log-level Warning"; + internal const string ServerArguments = +#if DEBUG + "--ide visualstudio --log-level Verbose --protocol-log-level Info --trace Verbose"; +#else + "--ide visualstudio --log-level Warning --protocol-log-level Warning --trace Off"; +#endif private async Task StartAsync() { diff --git a/tests/VisualStudio/Reqnroll.VisualStudio.Tests/LspInterception/LspServerConnectionServiceTests.cs b/tests/VisualStudio/Reqnroll.VisualStudio.Tests/LspInterception/LspServerConnectionServiceTests.cs index a871be0..5ea34ee 100644 --- a/tests/VisualStudio/Reqnroll.VisualStudio.Tests/LspInterception/LspServerConnectionServiceTests.cs +++ b/tests/VisualStudio/Reqnroll.VisualStudio.Tests/LspInterception/LspServerConnectionServiceTests.cs @@ -36,8 +36,17 @@ public void Resolution_is_relative_to_the_assembly_directory_not_the_working_dir } [Fact] - public void Server_arguments_identify_the_ide_and_a_quiet_default_log_level() + public void Server_arguments_identify_the_ide_and_set_all_three_logging_dials() { - LspServerConnectionService.ServerArguments.Should().Be("--ide visualstudio --log-level Warning"); + // The test assembly and the extension assembly share the same build configuration, so the + // #if DEBUG branch actually taken here is whatever configuration this test itself was + // compiled under. +#if DEBUG + LspServerConnectionService.ServerArguments.Should().Be( + "--ide visualstudio --log-level Verbose --protocol-log-level Info --trace Verbose"); +#else + LspServerConnectionService.ServerArguments.Should().Be( + "--ide visualstudio --log-level Warning --protocol-log-level Warning --trace Off"); +#endif } }