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 539e808..3809cb9 100644 --- a/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Hosting/LanguageServerOptionsExtensions.cs @@ -18,6 +18,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; @@ -44,7 +45,10 @@ public static void AddStandardHandlers(this LanguageServerOptions options) .AddHandler() .AddHandler() // F23: textDocument/inlayHint — binding info hints on .feature steps. - .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..45f4f21 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; @@ -40,8 +41,22 @@ 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); + // --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); + // 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 @@ -56,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); + ConfigureServer(options, ideId, logLevel, initialTrace, protocolLogLevel); }); using var preloadCts = new CancellationTokenSource(); @@ -109,17 +124,40 @@ 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 + /// 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. + /// + /// + /// + /// 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) + 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 @@ -137,7 +175,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(); @@ -150,6 +188,13 @@ internal static void ConfigureServer(LanguageServerOptions options, string? clie options.OnInitialized((languageServer, request, response, ct) => { + // 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(); response.Capabilities.SemanticTokensProvider = new SemanticTokensRegistrationOptions.StaticOptions @@ -221,4 +266,26 @@ internal static TraceLevel ParseLogLevel(string[] args) => Enum.TryParse(ParseArg(args, "--log-level"), ignoreCase: true, out var parsedLevel) ? 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) + ? 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 2605d44..75db6f7 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; @@ -39,6 +40,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; @@ -52,7 +54,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)) @@ -74,11 +76,18 @@ 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 (--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(), sp.GetRequiredService(), - sp.GetRequiredService())); + sp.GetRequiredService(), + sp.GetRequiredService())); } /// @@ -161,6 +170,7 @@ public static IServiceCollection AddReqnrollLspHandlers(this IServiceCollection .AddSingleton() .AddSingleton() .AddSingleton() - .AddSingleton(); + .AddSingleton() + .AddSingleton(); } } 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/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..80f25b7 --- /dev/null +++ b/src/LSP/Reqnroll.IdeSupport.LSP.Server/Tracing/TraceService.cs @@ -0,0 +1,41 @@ +#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, InitializeTrace initialLevel = InitializeTrace.Off) + { + _languageServer = languageServer; + _level = initialLevel; + } + + 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/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/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/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/Hosting/ProgramTests.cs b/tests/LSP/Reqnroll.IdeSupport.LSP.Server.Tests/Hosting/ProgramTests.cs index 98b6013..a6f3ee7 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; @@ -35,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() { @@ -48,6 +87,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)] 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); + } +} 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")); + } +} 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 } }