Robustify startup, error handling, and logging

This was a couple late nights that resulted in an overhaul of our
startup, error handling, and logging logic. Mostly because I realized
how dang easy it was to get things into a funky state when I added
`editorServicesWaitForDebugger` to the list of settings that will prompt
for a restart. This made it really easy to test, especially in the
"still starting up" state. It is still possible to generate perhaps more
error messages than I'd like, but they mostly come from the LSP client
library. In fact, the last bug I tracked down is that if the client
failed to start, it can't be stopped (which throws an exception) AND it
can't be disposed, the latter of which I think is an upstream bug I'll
need to investigate.

Author: andyleejordan

src/features/Console.ts

@@ -176,7 +176,7 @@ export class ConsoleFeature extends LanguageClientConsumer {
             vscode.commands.registerCommand("PowerShell.RunSelection", async () => {
                 if (vscode.window.activeTerminal &&
                     vscode.window.activeTerminal.name !== "PowerShell Extension") {
-                    this.logger.write("PowerShell Extension Terminal is not active! Running in current terminal using 'runSelectedText'");
+                    this.logger.write("PowerShell Extension Terminal is not active! Running in current terminal using 'runSelectedText'.");
                     await vscode.commands.executeCommand("workbench.action.terminal.runSelectedText");
 
                     // We need to honor the focusConsoleOnExecute setting here too. However, the boolean that `show`

src/features/DebugSession.ts

@@ -4,6 +4,7 @@
 import {
     debug,
     CancellationToken,
+    CancellationTokenSource,
     DebugAdapterDescriptor,
     DebugAdapterDescriptorFactory,
     DebugAdapterExecutable,
@@ -18,7 +19,6 @@ import {
     extensions,
     workspace,
     commands,
-    CancellationTokenSource,
     InputBoxOptions,
     QuickPickItem,
     QuickPickOptions,
@@ -297,7 +297,7 @@ export class DebugSessionFeature extends LanguageClientConsumer
         this.sessionManager.showDebugTerminal(true);
 
         this.logger.writeVerbose(`Connecting to pipe: ${sessionDetails.debugServicePipeName}`);
-        this.logger.writeVerbose(`Debug configuration: ${JSON.stringify(session.configuration)}`);
+        this.logger.writeVerbose(`Debug configuration: ${JSON.stringify(session.configuration, undefined, 2)}`);
 
         return new DebugAdapterNamedPipeServer(sessionDetails.debugServicePipeName);
     }
@@ -359,7 +359,10 @@ export class DebugSessionFeature extends LanguageClientConsumer
     private async createTemporaryIntegratedConsole(session: DebugSession): Promise<IEditorServicesSessionDetails | undefined> {
         const settings = getSettings();
         this.tempDebugProcess = await this.sessionManager.createDebugSessionProcess(settings);
-        this.tempSessionDetails = await this.tempDebugProcess.start(`DebugSession-${this.sessionCount++}`);
+        // TODO: Maybe set a timeout on the cancellation token?
+        const cancellationTokenSource = new CancellationTokenSource();
+        this.tempSessionDetails = await this.tempDebugProcess.start(
+            `DebugSession-${this.sessionCount++}`, cancellationTokenSource.token);
 
         // NOTE: Dotnet attach debugging is only currently supported if a temporary debug terminal is used, otherwise we get lots of lock conflicts from loading the assemblies.
         if (session.configuration.attachDotnetDebugger) {
@@ -379,16 +382,16 @@ export class DebugSessionFeature extends LanguageClientConsumer
                 // HACK: This seems like you would be calling a method on a variable not assigned yet, but it does work in the flow.
                 // 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.write(`Debugger session detected: ${dotnetAttachSession.name} (${dotnetAttachSession.id})`);
+                this.logger.writeVerbose(`Debugger session detected: ${dotnetAttachSession.name} (${dotnetAttachSession.id})`);
                 if (dotnetAttachSession.configuration.name == dotnetAttachConfig.name) {
                     const stopDebugEvent = debug.onDidTerminateDebugSession(async (terminatedDebugSession) => {
                         // Makes the event one-time
                         stopDebugEvent.dispose();
 
-                        this.logger.write(`Debugger session stopped: ${terminatedDebugSession.name} (${terminatedDebugSession.id})`);
+                        this.logger.writeVerbose(`Debugger session stopped: ${terminatedDebugSession.name} (${terminatedDebugSession.id})`);
 
                         if (terminatedDebugSession === session) {
-                            this.logger.write("Terminating dotnet debugger session associated with PowerShell debug session");
+                            this.logger.writeVerbose("Terminating dotnet debugger session associated with PowerShell debug session!");
                             await debug.stopDebugging(dotnetAttachSession);
                         }
                     });
@@ -398,8 +401,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)}`);
-            this.logger.write(`Attached dotnet debugger to process ${pid}`);
+            this.logger.writeVerbose(`Dotnet attach debug configuration: ${JSON.stringify(dotnetAttachConfig, undefined, 2)}`);
+            this.logger.writeVerbose(`Attached dotnet debugger to process: ${pid}`);
         }
         return this.tempSessionDetails;
     }

src/features/ExtensionCommands.ts

@@ -439,7 +439,7 @@ export class ExtensionCommandsFeature extends LanguageClientConsumer {
 
         default: {
             // Other URI schemes are not supported
-            const msg = JSON.stringify(saveFileDetails);
+            const msg = JSON.stringify(saveFileDetails, undefined, 2);
             this.logger.writeVerbose(
                 `<${ExtensionCommandsFeature.name}>: Saving a document with scheme '${currentFileUri.scheme}' ` +
                         `is currently unsupported. Message: '${msg}'`);
@@ -467,9 +467,9 @@ export class ExtensionCommandsFeature extends LanguageClientConsumer {
             await vscode.workspace.fs.writeFile(
                 vscode.Uri.file(destinationAbsolutePath),
                 Buffer.from(oldDocument.getText()));
-        } catch (e) {
+        } catch (err) {
             void this.logger.writeAndShowWarning(`<${ExtensionCommandsFeature.name}>: ` +
-                `Unable to save file to path '${destinationAbsolutePath}': ${e}`);
+                `Unable to save file to path '${destinationAbsolutePath}': ${err}`);
             return;
         }
 

src/features/ExternalApi.ts

@@ -57,7 +57,7 @@ export class ExternalApiFeature extends LanguageClientConsumer implements IPower
         string session uuid
     */
     public registerExternalExtension(id: string, apiVersion = "v1"): string {
-        this.logger.writeDiagnostic(`Registering extension '${id}' for use with API version '${apiVersion}'.`);
+        this.logger.writeVerbose(`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) {
@@ -98,7 +98,7 @@ export class ExternalApiFeature extends LanguageClientConsumer implements IPower
         true if it worked, otherwise throws an error.
     */
     public unregisterExternalExtension(uuid = ""): boolean {
-        this.logger.writeDiagnostic(`Unregistering extension with session UUID: ${uuid}`);
+        this.logger.writeVerbose(`Unregistering extension with session UUID: ${uuid}`);
         if (!ExternalApiFeature.registeredExternalExtension.delete(uuid)) {
             throw new Error(`No extension registered with session UUID: ${uuid}`);
         }
@@ -135,7 +135,7 @@ export class ExternalApiFeature extends LanguageClientConsumer implements IPower
     */
     public async getPowerShellVersionDetails(uuid = ""): Promise<IExternalPowerShellDetails> {
         const extension = this.getRegisteredExtension(uuid);
-        this.logger.writeDiagnostic(`Extension '${extension.id}' called 'getPowerShellVersionDetails'`);
+        this.logger.writeVerbose(`Extension '${extension.id}' called 'getPowerShellVersionDetails'.`);
 
         await this.sessionManager.waitUntilStarted();
         const versionDetails = this.sessionManager.getPowerShellVersionDetails();
@@ -163,7 +163,7 @@ export class ExternalApiFeature extends LanguageClientConsumer implements IPower
     */
     public async waitUntilStarted(uuid = ""): Promise<void> {
         const extension = this.getRegisteredExtension(uuid);
-        this.logger.writeDiagnostic(`Extension '${extension.id}' called 'waitUntilStarted'`);
+        this.logger.writeVerbose(`Extension '${extension.id}' called 'waitUntilStarted'.`);
         await this.sessionManager.waitUntilStarted();
     }
 

src/features/GetCommands.ts

@@ -65,7 +65,7 @@ export class GetCommandsFeature extends LanguageClientConsumer {
 
     private async CommandExplorerRefresh(): Promise<void> {
         if (this.languageClient === undefined) {
-            this.logger.writeVerbose(`<${GetCommandsFeature.name}>: Unable to send getCommand request`);
+            this.logger.writeVerbose(`<${GetCommandsFeature.name}>: Unable to send getCommand request!`);
             return;
         }
         await this.languageClient.sendRequest(GetCommandRequestType).then((result) => {

src/features/UpdatePowerShell.ts

@@ -51,20 +51,20 @@ export class UpdatePowerShell {
     private shouldCheckForUpdate(): boolean {
         // Respect user setting.
         if (!this.sessionSettings.promptToUpdatePowerShell) {
-            this.logger.writeDiagnostic("Setting 'promptToUpdatePowerShell' was false.");
+            this.logger.writeVerbose("Setting 'promptToUpdatePowerShell' was false.");
             return false;
         }
 
         // Respect environment configuration.
         if (process.env.POWERSHELL_UPDATECHECK?.toLowerCase() === "off") {
-            this.logger.writeDiagnostic("Environment variable 'POWERSHELL_UPDATECHECK' was 'Off'.");
+            this.logger.writeVerbose("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.writeDiagnostic("Not offering to update Windows PowerShell.");
+            this.logger.writeVerbose("Not prompting to update Windows PowerShell.");
             return false;
         }
 
@@ -78,27 +78,26 @@ export class UpdatePowerShell {
 
             // Skip if PowerShell is self-built, that is, this contains a commit hash.
             if (commit.length >= 40) {
-                this.logger.writeDiagnostic("Not offering to update development build.");
+                this.logger.writeVerbose("Not prompting to update development build.");
                 return false;
             }
 
             // Skip if preview is a daily build.
             if (daily.toLowerCase().startsWith("daily")) {
-                this.logger.writeDiagnostic("Not offering to update daily build.");
+                this.logger.writeVerbose("Not prompting to update daily build.");
                 return false;
             }
         }
 
         // TODO: Check if network is available?
         // TODO: Only check once a week.
-        this.logger.writeDiagnostic("Should check for PowerShell update.");
         return true;
     }
 
-    private async getRemoteVersion(url: string): Promise<string> {
+    private async getRemoteVersion(url: string): Promise<string | undefined> {
         const response = await fetch(url);
         if (!response.ok) {
-            throw new Error("Failed to get remote version!");
+            return undefined;
         }
         // Looks like:
         // {
@@ -107,7 +106,7 @@ export class UpdatePowerShell {
         //     "ReleaseTag": "v7.2.7"
         // }
         const data = await response.json();
-        this.logger.writeDiagnostic(`From '${url}' received:\n${data}`);
+        this.logger.writeVerbose(`Received from '${url}':\n${JSON.stringify(data, undefined, 2)}`);
         return data.ReleaseTag;
     }
 
@@ -116,38 +115,48 @@ export class UpdatePowerShell {
             return undefined;
         }
 
+        this.logger.writeVerbose("Checking for PowerShell update...");
         const tags: string[] = [];
         if (process.env.POWERSHELL_UPDATECHECK?.toLowerCase() === "lts") {
             // Only check for update to LTS.
-            this.logger.writeDiagnostic("Checking for LTS update.");
-            tags.push(await this.getRemoteVersion(UpdatePowerShell.LTSBuildInfoURL));
+            this.logger.writeVerbose("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.writeDiagnostic("Checking for stable update.");
-            tags.push(await this.getRemoteVersion(UpdatePowerShell.StableBuildInfoURL));
+            this.logger.writeVerbose("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.writeDiagnostic("Checking for preview update.");
-                tags.push(await this.getRemoteVersion(UpdatePowerShell.PreviewBuildInfoURL));
+                this.logger.writeVerbose("Checking for preview update...");
+                const tag = await this.getRemoteVersion(UpdatePowerShell.PreviewBuildInfoURL);
+                if (tag != undefined) {
+                    tags.push(tag);
+                }
             }
         }
 
         for (const tag of tags) {
             if (this.localVersion.compare(tag) === -1) {
-                this.logger.writeDiagnostic(`Offering to update PowerShell to ${tag}.`);
                 return tag;
             }
         }
 
+        this.logger.write("PowerShell is up-to-date.");
         return undefined;
     }
 
     public async checkForUpdate(): Promise<void> {
         try {
             const tag = await this.maybeGetNewRelease();
             if (tag) {
-                return await this.installUpdate(tag);
+                return await this.promptToUpdate(tag);
             }
         } catch (err) {
             // Best effort. This probably failed to fetch the data from GitHub.
@@ -160,21 +169,22 @@ export class UpdatePowerShell {
         await vscode.env.openExternal(url);
     }
 
-    private async installUpdate(tag: string): Promise<void> {
+    private async promptToUpdate(tag: string): Promise<void> {
         const releaseVersion = new SemVer(tag);
+        this.logger.write(`Prompting to update PowerShell v${this.localVersion.version} to v${releaseVersion.version}.`);
         const result = await vscode.window.showInformationMessage(
-            `You have an old version of PowerShell (${this.localVersion.version}).
-            The current latest release is ${releaseVersion.version}.
-            Would you like to open the GitHub release in your browser?`,
+            `PowerShell v${this.localVersion.version} is out-of-date.
+             The latest version is v${releaseVersion.version}.
+             Would you like to open the GitHub release in your browser?`,
             ...UpdatePowerShell.promptOptions);
 
         // If the user cancels the notification.
         if (!result) {
-            this.logger.writeDiagnostic("User canceled PowerShell update prompt.");
+            this.logger.writeVerbose("User canceled PowerShell update prompt.");
             return;
         }
 
-        this.logger.writeDiagnostic(`User said '${UpdatePowerShell.promptOptions[result.id].title}'.`);
+        this.logger.writeVerbose(`User said '${UpdatePowerShell.promptOptions[result.id].title}'.`);
 
         switch (result.id) {
         // Yes

src/logging.ts

@@ -57,7 +57,7 @@ export class Logger implements ILogger {
 
         // Early logging of the log paths for debugging.
         if (LogLevel.Diagnostic >= this.logLevel) {
-            const uriMessage = Logger.timestampMessage(`Global storage URI: '${globalStorageUri}', log file path: '${this.logFilePath}'`, LogLevel.Diagnostic);
+            const uriMessage = Logger.timestampMessage(`Log file path: '${this.logFilePath}'`, LogLevel.Verbose);
             this.logChannel.appendLine(uriMessage);
         }
 
@@ -211,7 +211,7 @@ export class Logger implements ILogger {
             try {
                 this.writingLog = true;
                 if (!this.logDirectoryCreated) {
-                    this.logChannel.appendLine(Logger.timestampMessage(`Creating log directory at: '${this.logDirectoryPath}'`, level));
+                    this.writeVerbose(`Creating log directory at: '${this.logDirectoryPath}'`);
                     await vscode.workspace.fs.createDirectory(this.logDirectoryPath);
                     this.logDirectoryCreated = true;
                 }
@@ -222,8 +222,8 @@ export class Logger implements ILogger {
                 await vscode.workspace.fs.writeFile(
                     this.logFilePath,
                     Buffer.concat([log, Buffer.from(timestampedMessage)]));
-            } catch (e) {
-                console.log(`Error writing to vscode-powershell log file: ${e}`);
+            } catch (err) {
+                console.log(`Error writing to vscode-powershell log file: ${err}`);
             } finally {
                 this.writingLog = false;
             }

src/main.ts

@@ -59,7 +59,7 @@ export async function activate(context: vscode.ExtensionContext): Promise<IPower
     // Load and validate settings (will prompt for 'cwd' if necessary).
     await validateCwdSetting(logger);
     const settings = getSettings();
-    logger.writeDiagnostic(`Loaded settings:\n${JSON.stringify(settings, undefined, 2)}`);
+    logger.writeVerbose(`Loaded settings:\n${JSON.stringify(settings, undefined, 2)}`);
 
     languageConfigurationDisposable = vscode.languages.setLanguageConfiguration(
         PowerShellLanguageId,