Implement LogOutputWindow for Logging (#5065)

* Implement LogOutputChannel and move settings to UI

* Remove unnecessary comment

* Remove File Logging (done by LogOutputWindow automatically)

* First Connect

* Add output adapters, LSP restart settings

* Fix Log Uri Test

* Forgot to add to extension facing API

* Accidentally made a recursive rather than reference what I wanted to. Thanks Copilot...

* Pre-Restart Experiments

* Move Commands out of logger temporarily

* Initial Cleanup of Logging, looks good ATM

* Merge client and server editorservices logs

* Add new MergedOutputChannel log

* Remove unnecessary Import

* Update settings for new EditorServicesLogLevels

* Wire up loglevels in-band due to LSP bug

* Rework multiple classes into a parser function injection

* Fix some glyphs

* Revert extra config settings for dynamic log configuration for now

* Remove SetLSPTrace for now

* Clean import

* Align logging terminology to vscode output windows and remove editorServices from options definitions

Author: JustinGrote

docs/troubleshooting.md

@@ -253,11 +253,11 @@ Logs provide context for what was happening when the issue occurred. **You shoul
 your logs for any sensitive information you would not like to share online!**
 
 * Before sending through logs, try and reproduce the issue with **log level set to
-  Diagnostic**. You can set this in the [VS Code Settings][]
+  Trace**. You can set this in the [VS Code Settings][]
   (<kbd>Ctrl</kbd>+<kbd>,</kbd>) with:
 
   ```json
-  "powershell.developer.editorServicesLogLevel": "Diagnostic"
+  "powershell.developer.editorServicesLogLevel": "Trace"
   ```
 
 * After you have captured the issue with the log level turned up, you may want to return

package.json

@@ -916,24 +916,24 @@
         },
         "powershell.developer.editorServicesLogLevel": {
           "type": "string",
-          "default": "Normal",
+          "default": "Warning",
           "enum": [
-            "Diagnostic",
-            "Verbose",
-            "Normal",
+            "Trace",
+            "Debug",
+            "Information",
             "Warning",
             "Error",
             "None"
           ],
           "markdownEnumDescriptions": [
             "Enables all logging possible, please use this setting when submitting logs for bug reports!",
-            "Enables more logging than normal.",
-            "The default logging level.",
-            "Only log warnings and errors.",
+            "Enables more detailed logging of the extension",
+            "Logs high-level information about what the extension is doing.",
+            "Only log warnings and errors. This is the default setting",
             "Only log errors.",
             "Disable all logging possible. No log files will be written!"
           ],
-          "markdownDescription": "Sets the log verbosity for both the extension and its LSP server, PowerShell Editor Services. **Please set to `Diagnostic` when recording logs for a bug report!**"
+          "markdownDescription": "Sets the log verbosity for both the extension and its LSP server, PowerShell Editor Services. **Please set to `Trace` when recording logs for a bug report!**"
         },
         "powershell.developer.editorServicesWaitForDebugger": {
           "type": "boolean",
@@ -953,6 +953,21 @@
           "default": [],
           "markdownDescription": "An array of strings that enable experimental features in the PowerShell extension. **No flags are currently available!**"
         },
+        "powershell.developer.traceDap": {
+          "type": "boolean",
+          "default": false,
+          "markdownDescription": "Traces the DAP communication between VS Code and the PowerShell Editor Services [DAP Server](https://microsoft.github.io/debug-adapter-protocol/). The output will be logged and also visible in the Output pane, where the verbosity is configurable. **For extension developers and issue troubleshooting only!**"
+        },
+        "powershell.trace.server": {
+          "type": "string",
+          "enum": [
+            "off",
+            "messages",
+            "verbose"
+          ],
+          "default": "off",
+          "markdownDescription": "Traces the communication between VS Code and the PowerShell Editor Services [LSP Server](https://microsoft.github.io/language-server-protocol/). The output will be logged and also visible in the Output pane, where the verbosity is configurable. **For extension developers and issue troubleshooting only!**"
+        },
         "powershell.developer.waitForSessionFileTimeoutSeconds": {
           "type": "number",
           "default": 240,
@@ -1002,21 +1017,6 @@
           "type": "boolean",
           "default": false,
           "markdownDescription": "Show buttons in the editor's title bar for moving the terminals pane (with the PowerShell Extension Terminal) around."
-        },
-        "powershell.trace.server": {
-          "type": "string",
-          "enum": [
-            "off",
-            "messages",
-            "verbose"
-          ],
-          "default": "off",
-          "markdownDescription": "Traces the communication between VS Code and the PowerShell Editor Services [LSP Server](https://microsoft.github.io/language-server-protocol/). **only for extension developers and issue troubleshooting!**"
-        },
-        "powershell.trace.dap": {
-          "type": "boolean",
-          "default": false,
-          "markdownDescription": "Traces the communication between VS Code and the PowerShell Editor Services [DAP Server](https://microsoft.github.io/debug-adapter-protocol/). **This setting is only meant for extension developers and issue troubleshooting!**"
         }
       }
     },

src/extension.ts

@@ -22,7 +22,7 @@ import { ShowHelpFeature } from "./features/ShowHelp";
 import { SpecifyScriptArgsFeature } from "./features/DebugSession";
 import { Logger } from "./logging";
 import { SessionManager } from "./session";
-import { LogLevel, getSettings } from "./settings";
+import { getSettings } from "./settings";
 import { PowerShellLanguageId } from "./utils";
 import { LanguageClientConsumer } from "./languageClientConsumer";
 
@@ -43,14 +43,12 @@ const documentSelector: DocumentSelector = [
 ];
 
 export async function activate(context: vscode.ExtensionContext): Promise<IPowerShellExtensionClient> {
-    const logLevel = vscode.workspace.getConfiguration(`${PowerShellLanguageId}.developer`)
-        .get<string>("editorServicesLogLevel", LogLevel.Normal);
-    logger = new Logger(logLevel, context.globalStorageUri);
+    logger = new Logger();
 
     telemetryReporter = new TelemetryReporter(TELEMETRY_KEY);
 
     const settings = getSettings();
-    logger.writeVerbose(`Loaded settings:\n${JSON.stringify(settings, undefined, 2)}`);
+    logger.writeDebug(`Loaded settings:\n${JSON.stringify(settings, undefined, 2)}`);
 
     languageConfigurationDisposable = vscode.languages.setLanguageConfiguration(
         PowerShellLanguageId,
@@ -141,6 +139,19 @@ export async function activate(context: vscode.ExtensionContext): Promise<IPower
         new PesterTestsFeature(sessionManager, logger),
         new CodeActionsFeature(logger),
         new SpecifyScriptArgsFeature(context),
+
+        vscode.commands.registerCommand(
+            "PowerShell.OpenLogFolder",
+            async () => {await vscode.commands.executeCommand(
+                "vscode.openFolder",
+                context.logUri,
+                { forceNewWindow: true }
+            );}
+        ),
+        vscode.commands.registerCommand(
+            "PowerShell.ShowLogs",
+            () => {logger.showLogPanel();}
+        )
     ];
 
     const externalApi = new ExternalApiFeature(context, sessionManager, logger);
@@ -169,6 +180,7 @@ export async function activate(context: vscode.ExtensionContext): Promise<IPower
         getPowerShellVersionDetails: uuid => externalApi.getPowerShellVersionDetails(uuid),
         waitUntilStarted: uuid => externalApi.waitUntilStarted(uuid),
         getStorageUri: () => externalApi.getStorageUri(),
+        getLogUri: () => externalApi.getLogUri(),
     };
 }
 

src/features/DebugSession.ts

@@ -335,8 +335,8 @@ export class DebugSessionFeature extends LanguageClientConsumer
         // Create or show the debug terminal (either temporary or session).
         this.sessionManager.showDebugTerminal(true);
 
-        this.logger.writeVerbose(`Connecting to pipe: ${sessionDetails.debugServicePipeName}`);
-        this.logger.writeVerbose(`Debug configuration: ${JSON.stringify(session.configuration, undefined, 2)}`);
+        this.logger.writeDebug(`Connecting to pipe: ${sessionDetails.debugServicePipeName}`);
+        this.logger.writeDebug(`Debug configuration: ${JSON.stringify(session.configuration, undefined, 2)}`);
 
         return new DebugAdapterNamedPipeServer(sessionDetails.debugServicePipeName);
     }
@@ -424,7 +424,7 @@ export class DebugSessionFeature extends LanguageClientConsumer
                 // The dispose shorthand demonry for making an event one-time courtesy of: https://github.com/OmniSharp/omnisharp-vscode/blob/b8b07bb12557b4400198895f82a94895cb90c461/test/integrationTests/launchConfiguration.integration.test.ts#L41-L45
                 startDebugEvent.dispose();
 
-                this.logger.writeVerbose(`Debugger session detected: ${dotnetAttachSession.name} (${dotnetAttachSession.id})`);
+                this.logger.writeDebug(`Debugger session detected: ${dotnetAttachSession.name} (${dotnetAttachSession.id})`);
 
                 tempConsoleDotnetAttachSession = dotnetAttachSession;
 
@@ -434,7 +434,7 @@ export class DebugSessionFeature extends LanguageClientConsumer
                     // Makes the event one-time
                     stopDebugEvent.dispose();
 
-                    this.logger.writeVerbose(`Debugger session terminated: ${tempConsoleSession.name} (${tempConsoleSession.id})`);
+                    this.logger.writeDebug(`Debugger session terminated: ${tempConsoleSession.name} (${tempConsoleSession.id})`);
 
                     // HACK: As of 2023-08-17, there is no vscode debug API to request the C# debugger to detach, so we send it a custom DAP request instead.
                     const disconnectRequest: DebugProtocol.DisconnectRequest = {
@@ -462,8 +462,8 @@ export class DebugSessionFeature extends LanguageClientConsumer
             // Start a child debug session to attach the dotnet debugger
             // TODO: Accommodate multi-folder workspaces if the C# code is in a different workspace folder
             await debug.startDebugging(undefined, dotnetAttachConfig, session);
-            this.logger.writeVerbose(`Dotnet attach debug configuration: ${JSON.stringify(dotnetAttachConfig, undefined, 2)}`);
-            this.logger.writeVerbose(`Attached dotnet debugger to process: ${pid}`);
+            this.logger.writeDebug(`Dotnet attach debug configuration: ${JSON.stringify(dotnetAttachConfig, undefined, 2)}`);
+            this.logger.writeDebug(`Attached dotnet debugger to process: ${pid}`);
         }
 
         return this.tempSessionDetails;
@@ -606,36 +606,27 @@ export class DebugSessionFeature extends LanguageClientConsumer
 
 class PowerShellDebugAdapterTrackerFactory implements DebugAdapterTrackerFactory, Disposable {
     disposables: Disposable[] = [];
-    dapLogEnabled: boolean = workspace.getConfiguration("powershell").get<boolean>("trace.dap") ?? false;
-    constructor(private adapterName = "PowerShell") {
-        this.disposables.push(workspace.onDidChangeConfiguration(change => {
-            if (
-                change.affectsConfiguration("powershell.trace.dap")
-            ) {
-                this.dapLogEnabled = workspace.getConfiguration("powershell").get<boolean>("trace.dap") ?? false;
-                if (this.dapLogEnabled) {
-                    // Trigger the output pane to appear. This gives the user time to position it before starting a debug.
-                    this.log?.show(true);
-                }
-            }
-        }));
-    }
+    constructor(private adapterName = "PowerShell") {}
 
-    /* We want to use a shared output log for separate debug sessions as usually only one is running at a time and we
-    *  dont need an output window for every debug session. We also want to leave it active so user can copy and paste
-    *  even on run end. When user changes the setting and disables it getter will return undefined, which will result
+
+    _log: LogOutputChannel | undefined;
+    /** Lazily creates a {@link LogOutputChannel} for debug tracing, and presents it only when DAP logging is enabled.
+    *
+    * We want to use a shared output log for separate debug sessions as usually only one is running at a time and we
+    * dont need an output window for every debug session. We also want to leave it active so user can copy and paste
+    * even on run end. When user changes the setting and disables it getter will return undefined, which will result
     * in a noop for the logging activities, effectively pausing logging but not disposing the output channel. If the
     * user re-enables, then logging resumes.
     */
-    _log: LogOutputChannel | undefined;
     get log(): LogOutputChannel | undefined {
-        if (this.dapLogEnabled && this._log === undefined) {
-            this._log = window.createOutputChannel(`${this.adapterName} Trace - DAP`, { log: true });
+        if (workspace.getConfiguration("powershell.developer").get<boolean>("traceDap") && this._log === undefined) {
+            this._log = window.createOutputChannel(`${this.adapterName}: Trace DAP`, { log: true });
             this.disposables.push(this._log);
         }
-        return this.dapLogEnabled ? this._log : undefined;
+        return this._log;
     }
 
+    // This tracker effectively implements the logging for the debug adapter to a LogOutputChannel
     createDebugAdapterTracker(session: DebugSession): DebugAdapterTracker {
         const sessionInfo = `${this.adapterName} Debug Session: ${session.name} [${session.id}]`;
         return {

src/features/ExternalApi.ts

@@ -19,6 +19,7 @@ export interface IPowerShellExtensionClient {
     getPowerShellVersionDetails(uuid: string): Promise<IExternalPowerShellDetails>;
     waitUntilStarted(uuid: string): Promise<void>;
     getStorageUri(): vscode.Uri;
+    getLogUri(): vscode.Uri;
 }
 
 /*
@@ -55,7 +56,7 @@ export class ExternalApiFeature implements IPowerShellExtensionClient {
         string session uuid
     */
     public registerExternalExtension(id: string, apiVersion = "v1"): string {
-        this.logger.writeVerbose(`Registering extension '${id}' for use with API version '${apiVersion}'.`);
+        this.logger.writeDebug(`Registering extension '${id}' for use with API version '${apiVersion}'.`);
 
         // eslint-disable-next-line @typescript-eslint/no-unused-vars
         for (const [_name, externalExtension] of ExternalApiFeature.registeredExternalExtension) {
@@ -96,7 +97,7 @@ export class ExternalApiFeature implements IPowerShellExtensionClient {
         true if it worked, otherwise throws an error.
     */
     public unregisterExternalExtension(uuid = ""): boolean {
-        this.logger.writeVerbose(`Unregistering extension with session UUID: ${uuid}`);
+        this.logger.writeDebug(`Unregistering extension with session UUID: ${uuid}`);
         if (!ExternalApiFeature.registeredExternalExtension.delete(uuid)) {
             throw new Error(`No extension registered with session UUID: ${uuid}`);
         }
@@ -133,7 +134,7 @@ export class ExternalApiFeature implements IPowerShellExtensionClient {
     */
     public async getPowerShellVersionDetails(uuid = ""): Promise<IExternalPowerShellDetails> {
         const extension = this.getRegisteredExtension(uuid);
-        this.logger.writeVerbose(`Extension '${extension.id}' called 'getPowerShellVersionDetails'.`);
+        this.logger.writeDebug(`Extension '${extension.id}' called 'getPowerShellVersionDetails'.`);
 
         await this.sessionManager.waitUntilStarted();
         const versionDetails = this.sessionManager.getPowerShellVersionDetails();
@@ -161,7 +162,7 @@ export class ExternalApiFeature implements IPowerShellExtensionClient {
     */
     public async waitUntilStarted(uuid = ""): Promise<void> {
         const extension = this.getRegisteredExtension(uuid);
-        this.logger.writeVerbose(`Extension '${extension.id}' called 'waitUntilStarted'.`);
+        this.logger.writeDebug(`Extension '${extension.id}' called 'waitUntilStarted'.`);
         await this.sessionManager.waitUntilStarted();
     }
 
@@ -171,6 +172,10 @@ export class ExternalApiFeature implements IPowerShellExtensionClient {
         return this.extensionContext.globalStorageUri.with({ scheme: "file"});
     }
 
+    public getLogUri(): vscode.Uri {
+        return this.extensionContext.logUri.with({ scheme: "file"});
+    }
+
     public dispose(): void {
         // Nothing to dispose.
     }

src/features/UpdatePowerShell.ts

@@ -51,20 +51,20 @@ export class UpdatePowerShell {
     private shouldCheckForUpdate(): boolean {
         // Respect user setting.
         if (!this.sessionSettings.promptToUpdatePowerShell) {
-            this.logger.writeVerbose("Setting 'promptToUpdatePowerShell' was false.");
+            this.logger.writeDebug("Setting 'promptToUpdatePowerShell' was false.");
             return false;
         }
 
         // Respect environment configuration.
         if (process.env.POWERSHELL_UPDATECHECK?.toLowerCase() === "off") {
-            this.logger.writeVerbose("Environment variable 'POWERSHELL_UPDATECHECK' was 'Off'.");
+            this.logger.writeDebug("Environment variable 'POWERSHELL_UPDATECHECK' was 'Off'.");
             return false;
         }
 
         // Skip prompting when using Windows PowerShell for now.
         if (this.localVersion.compare("6.0.0") === -1) {
             // TODO: Maybe we should announce PowerShell Core?
-            this.logger.writeVerbose("Not prompting to update Windows PowerShell.");
+            this.logger.writeDebug("Not prompting to update Windows PowerShell.");
             return false;
         }
 
@@ -78,13 +78,13 @@ export class UpdatePowerShell {
 
             // Skip if PowerShell is self-built, that is, this contains a commit hash.
             if (commit.length >= 40) {
-                this.logger.writeVerbose("Not prompting to update development build.");
+                this.logger.writeDebug("Not prompting to update development build.");
                 return false;
             }
 
             // Skip if preview is a daily build.
             if (daily.toLowerCase().startsWith("daily")) {
-                this.logger.writeVerbose("Not prompting to update daily build.");
+                this.logger.writeDebug("Not prompting to update daily build.");
                 return false;
             }
         }
@@ -106,7 +106,7 @@ export class UpdatePowerShell {
         //     "ReleaseTag": "v7.2.7"
         // }
         const data = await response.json();
-        this.logger.writeVerbose(`Received from '${url}':\n${JSON.stringify(data, undefined, 2)}`);
+        this.logger.writeDebug(`Received from '${url}':\n${JSON.stringify(data, undefined, 2)}`);
         return data.ReleaseTag;
     }
 
@@ -115,26 +115,26 @@ export class UpdatePowerShell {
             return undefined;
         }
 
-        this.logger.writeVerbose("Checking for PowerShell update...");
+        this.logger.writeDebug("Checking for PowerShell update...");
         const tags: string[] = [];
         if (process.env.POWERSHELL_UPDATECHECK?.toLowerCase() === "lts") {
             // Only check for update to LTS.
-            this.logger.writeVerbose("Checking for LTS update...");
+            this.logger.writeDebug("Checking for LTS update...");
             const tag = await this.getRemoteVersion(UpdatePowerShell.LTSBuildInfoURL);
             if (tag != undefined) {
                 tags.push(tag);
             }
         } else {
             // Check for update to stable.
-            this.logger.writeVerbose("Checking for stable update...");
+            this.logger.writeDebug("Checking for stable update...");
             const tag = await this.getRemoteVersion(UpdatePowerShell.StableBuildInfoURL);
             if (tag != undefined) {
                 tags.push(tag);
             }
 
             // Also check for a preview update.
             if (this.localVersion.prerelease.length > 0) {
-                this.logger.writeVerbose("Checking for preview update...");
+                this.logger.writeDebug("Checking for preview update...");
                 const tag = await this.getRemoteVersion(UpdatePowerShell.PreviewBuildInfoURL);
                 if (tag != undefined) {
                     tags.push(tag);
@@ -181,11 +181,11 @@ export class UpdatePowerShell {
 
         // If the user cancels the notification.
         if (!result) {
-            this.logger.writeVerbose("User canceled PowerShell update prompt.");
+            this.logger.writeDebug("User canceled PowerShell update prompt.");
             return;
         }
 
-        this.logger.writeVerbose(`User said '${UpdatePowerShell.promptOptions[result.id].title}'.`);
+        this.logger.writeDebug(`User said '${UpdatePowerShell.promptOptions[result.id].title}'.`);
 
         switch (result.id) {
         // Yes