Robustify startup, error handling, and logging

.mocharc.json

@@ -6,7 +6,7 @@
     ".jsx"
   ],
   "require": "source-map-support/register",
-  "timeout": 30000,
+  "timeout": 60000,
   "slow": 2000,
   "spec": "out/test/**/*.test.js"
 }

.vsts-ci/azure-pipelines-ci.yml

@@ -1,4 +1,11 @@
-name: PR-$(System.PullRequest.PullRequestNumber)-$(Date:yyyyMMdd)$(Rev:.rr)
+name: CI-$(Build.SourceBranchName)-$(Date:yyyyMMdd)$(Rev:.rr)
+
+trigger:
+  - main
+pr:
+  paths:
+    exclude:
+    - '**/*.md'
 
 variables:
   # Don't download unneeded packages

.vsts-ci/misc-analysis.yml

@@ -1,12 +1,10 @@
-name: PR-$(System.PullRequest.PullRequestNumber)-$(Date:yyyyMMdd)$(Rev:.rr)
-
-trigger:
-  branches:
-    include:
-    - main
+name: Misc-$(Build.SourceBranchName)-$(Date:yyyyMMdd)$(Rev:.rr)
 
+trigger: none
 pr:
-- main
+  paths:
+    exclude:
+    - '**/*.md'
 
 resources:
   repositories:
@@ -23,6 +21,7 @@ jobs:
   - checkout: self
   - checkout: ComplianceRepo
   - template: ci-compliance.yml@ComplianceRepo
+
 # NOTE: This enables our project to work with Visual Studio's Rich Navigation:
 # https://visualstudio.microsoft.com/services/rich-code-navigation/
 - job: RichCodeNav

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,