From da36a1229796d07f7ad762a8e105d32613d47ede Mon Sep 17 00:00:00 2001 From: Andy Jordan Date: Mon, 31 Oct 2022 12:53:22 -0700 Subject: [PATCH] Capture more logs By starting the logger earlier. --- src/features/UpdatePowerShell.ts | 23 +++++++---- src/logging.ts | 70 +++++++++++++++++++------------- src/main.ts | 19 +++++---- src/session.ts | 19 +++++---- src/settings.ts | 23 ++++++----- test/core/settings.test.ts | 6 +-- 6 files changed, 95 insertions(+), 65 deletions(-) diff --git a/src/features/UpdatePowerShell.ts b/src/features/UpdatePowerShell.ts index 45ef47c801..aec794892f 100644 --- a/src/features/UpdatePowerShell.ts +++ b/src/features/UpdatePowerShell.ts @@ -12,6 +12,7 @@ import * as util from "util"; import { MessageItem, ProgressLocation, window } from "vscode"; import { LanguageClient } from "vscode-languageclient/node"; +import { Logger } from "../logging"; import { SessionManager } from "../session"; import * as Settings from "../settings"; import { isMacOS, isWindows } from "../utils"; @@ -21,7 +22,7 @@ const streamPipeline = util.promisify(stream.pipeline); const PowerShellGitHubReleasesUrl = "https://api.github.com/repos/PowerShell/PowerShell/releases/latest"; -const PowerShellGitHubPrereleasesUrl = +const PowerShellGitHubPreReleasesUrl = "https://api.github.com/repos/PowerShell/PowerShell/releases"; export class GitHubReleaseInformation { @@ -40,7 +41,7 @@ export class GitHubReleaseInformation { // Fetch the latest PowerShell releases from GitHub. const response = await fetch( - preview ? PowerShellGitHubPrereleasesUrl : PowerShellGitHubReleasesUrl, + preview ? PowerShellGitHubPreReleasesUrl : PowerShellGitHubReleasesUrl, requestConfig); if (!response.ok) { @@ -85,7 +86,8 @@ export async function InvokePowerShellUpdateCheck( languageServerClient: LanguageClient, localVersion: semver.SemVer, arch: string, - release: GitHubReleaseInformation) { + release: GitHubReleaseInformation, + logger: Logger) { const options: IUpdateMessageItem[] = [ { id: 0, @@ -103,6 +105,7 @@ export async function InvokePowerShellUpdateCheck( // If our local version is up-to-date, we can return early. if (semver.compare(localVersion, release.version) >= 0) { + logger.writeDiagnostic("PowerShell is up-to-date!"); return; } @@ -111,8 +114,7 @@ export async function InvokePowerShellUpdateCheck( }.`; if (process.platform === "linux") { - await window.showInformationMessage( - `${commonText} We recommend updating to the latest version.`); + void logger.writeAndShowInformation(`${commonText} We recommend updating to the latest version.`); return; } @@ -122,7 +124,10 @@ export async function InvokePowerShellUpdateCheck( }`, ...options); // If the user cancels the notification. - if (!result) { return; } + if (!result) { + logger.writeDiagnostic("User canceled PowerShell update prompt."); + return; + } // Yes choice. switch (result.id) { @@ -152,6 +157,7 @@ export async function InvokePowerShellUpdateCheck( }); // Stop the session because Windows likes to hold on to files. + logger.writeDiagnostic("MSI downloaded, stopping session and closing terminals!"); await sessionManager.stop(); // Close all terminals with the name "pwsh" in the current VS Code session. @@ -164,10 +170,12 @@ export async function InvokePowerShellUpdateCheck( } // Invoke the MSI via cmd. + logger.writeDiagnostic(`Running '${msiDownloadPath}' to update PowerShell...`); const msi = spawn("msiexec", ["/i", msiDownloadPath]); msi.on("close", () => { // Now that the MSI is finished, restart the session. + logger.writeDiagnostic("MSI installation finished, restarting session."); void sessionManager.start(); fs.unlinkSync(msiDownloadPath); }); @@ -177,6 +185,7 @@ export async function InvokePowerShellUpdateCheck( ? "brew upgrade --cask powershell-preview" : "brew upgrade --cask powershell"; + logger.writeDiagnostic(`Running '${script}' to update PowerShell...`); await languageServerClient.sendRequest(EvaluateRequestType, { expression: script, }); @@ -186,7 +195,7 @@ export async function InvokePowerShellUpdateCheck( // Never choice. case 2: - await Settings.change("promptToUpdatePowerShell", false, true); + await Settings.change("promptToUpdatePowerShell", false, true, logger); break; default: break; diff --git a/src/logging.ts b/src/logging.ts index c007088374..ef280cf8d8 100644 --- a/src/logging.ts +++ b/src/logging.ts @@ -5,6 +5,7 @@ import utils = require("./utils"); import os = require("os"); import vscode = require("vscode"); +// NOTE: This is not a string enum because the order is used for comparison. export enum LogLevel { Diagnostic, Verbose, @@ -27,17 +28,29 @@ export interface ILogger { } export class Logger implements ILogger { - public logBasePath: vscode.Uri; - public logSessionPath: vscode.Uri | undefined; - public MinimumLogLevel: LogLevel = LogLevel.Normal; + public logDirectoryPath: vscode.Uri; + private logLevel: LogLevel; private commands: vscode.Disposable[]; private logChannel: vscode.OutputChannel; - private logFilePath: vscode.Uri | undefined; + private logFilePath: vscode.Uri; + private logDirectoryCreated = false; - constructor(logBasePath: vscode.Uri) { + constructor(logLevelName: string, globalStorageUri: vscode.Uri) { + this.logLevel = Logger.logLevelNameToValue(logLevelName); this.logChannel = vscode.window.createOutputChannel("PowerShell Extension Logs"); - this.logBasePath = vscode.Uri.joinPath(logBasePath, "logs"); + this.logDirectoryPath = vscode.Uri.joinPath( + globalStorageUri, + "logs", + `${Math.floor(Date.now() / 1000)}-${vscode.env.sessionId}`); + this.logFilePath = this.getLogFilePath("vscode-powershell"); + + // 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); + this.logChannel.appendLine(uriMessage); + } + this.commands = [ vscode.commands.registerCommand( "PowerShell.ShowLogs", @@ -57,11 +70,11 @@ export class Logger implements ILogger { } public getLogFilePath(baseName: string): vscode.Uri { - return vscode.Uri.joinPath(this.logSessionPath!, `${baseName}.log`); + return vscode.Uri.joinPath(this.logDirectoryPath, `${baseName}.log`); } private writeAtLevel(logLevel: LogLevel, message: string, ...additionalMessages: string[]): void { - if (logLevel >= this.MinimumLogLevel) { + if (logLevel >= this.logLevel) { void this.writeLine(message, logLevel); for (const additionalMessage of additionalMessages) { @@ -140,20 +153,8 @@ export class Logger implements ILogger { } } - public async startNewLog(minimumLogLevel = "Normal"): Promise { - this.MinimumLogLevel = Logger.logLevelNameToValue(minimumLogLevel); - - this.logSessionPath = - vscode.Uri.joinPath( - this.logBasePath, - `${Math.floor(Date.now() / 1000)}-${vscode.env.sessionId}`); - - this.logFilePath = this.getLogFilePath("vscode-powershell"); - await vscode.workspace.fs.createDirectory(this.logSessionPath); - } - // TODO: Make the enum smarter about strings so this goes away. - public static logLevelNameToValue(logLevelName: string): LogLevel { + private static logLevelNameToValue(logLevelName: string): LogLevel { switch (logLevelName.trim().toLowerCase()) { case "diagnostic": return LogLevel.Diagnostic; case "verbose": return LogLevel.Verbose; @@ -165,27 +166,40 @@ export class Logger implements ILogger { } } + public updateLogLevel(logLevelName: string): void { + this.logLevel = Logger.logLevelNameToValue(logLevelName); + } + private showLogPanel(): void { this.logChannel.show(); } private async openLogFolder(): Promise { - if (this.logSessionPath) { + if (this.logDirectoryCreated) { // Open the folder in VS Code since there isn't an easy way to // open the folder in the platform's file browser - await vscode.commands.executeCommand("vscode.openFolder", this.logSessionPath, true); + await vscode.commands.executeCommand("vscode.openFolder", this.logDirectoryPath, true); + } else { + void this.writeAndShowError("Cannot open PowerShell log directory as it does not exist!"); } } - // TODO: Should we await this function above? - private async writeLine(message: string, level: LogLevel = LogLevel.Normal): Promise { + private static timestampMessage(message: string, level: LogLevel): string { const now = new Date(); - const timestampedMessage = - `${now.toLocaleDateString()} ${now.toLocaleTimeString()} [${LogLevel[level].toUpperCase()}] - ${message}${os.EOL}`; + return `${now.toLocaleDateString()} ${now.toLocaleTimeString()} [${LogLevel[level].toUpperCase()}] - ${message}${os.EOL}`; + } + // TODO: Should we await this function above? + private async writeLine(message: string, level: LogLevel = LogLevel.Normal): Promise { + const timestampedMessage = Logger.timestampMessage(message, level); this.logChannel.appendLine(timestampedMessage); - if (this.logFilePath && this.MinimumLogLevel !== LogLevel.None) { + if (this.logLevel !== LogLevel.None) { try { + if (!this.logDirectoryCreated) { + this.logChannel.appendLine(Logger.timestampMessage(`Creating log directory at: '${this.logDirectoryPath}'`, level)); + await vscode.workspace.fs.createDirectory(this.logDirectoryPath); + this.logDirectoryCreated = await utils.checkIfDirectoryExists(this.logDirectoryPath); + } let log = new Uint8Array(); if (await utils.checkIfFileExists(this.logFilePath)) { log = await vscode.workspace.fs.readFile(this.logFilePath); diff --git a/src/main.ts b/src/main.ts index 36849e4878..e34ff062d7 100644 --- a/src/main.ts +++ b/src/main.ts @@ -37,6 +37,7 @@ const PackageJSON: any = require("../package.json"); // the application insights key (also known as instrumentation key) used for telemetry. const AI_KEY = "AIF-d9b70cd4-b9f9-4d70-929b-a071c400b217"; +let languageConfigurationDisposable: vscode.Disposable; let logger: Logger; let sessionManager: SessionManager; let languageClientConsumers: LanguageClientConsumer[] = []; @@ -48,23 +49,27 @@ const documentSelector: DocumentSelector = [ { language: "powershell", scheme: "untitled" }, ]; -// NOTE: Now that this is async, we can probably improve a lot! export async function activate(context: vscode.ExtensionContext): Promise { + const logLevel = vscode.workspace.getConfiguration(`${PowerShellLanguageId}.developer`) + .get("editorServicesLogLevel", "Normal"); + logger = new Logger(logLevel, context.globalStorageUri); + telemetryReporter = new TelemetryReporter(PackageJSON.name, PackageJSON.version, AI_KEY); // If both extensions are enabled, this will cause unexpected behavior since both register the same commands. // TODO: Merge extensions and use preview channel in marketplace instead. if (PackageJSON.name.toLowerCase() === "powershell-preview" && vscode.extensions.getExtension("ms-vscode.powershell")) { - void vscode.window.showErrorMessage( + void logger.writeAndShowError( "'PowerShell' and 'PowerShell Preview' are both enabled. Please disable one for best performance."); } // Load and validate settings (will prompt for 'cwd' if necessary). - await Settings.validateCwdSetting(); + await Settings.validateCwdSetting(logger); const settings = Settings.load(); + logger.writeDiagnostic(`Loaded settings:\n${JSON.stringify(settings, undefined, 2)}`); - vscode.languages.setLanguageConfiguration( + languageConfigurationDisposable = vscode.languages.setLanguageConfiguration( PowerShellLanguageId, { // TODO: Remove the useless escapes @@ -125,10 +130,6 @@ export async function activate(context: vscode.ExtensionContext): Promise { // Dispose of telemetry reporter await telemetryReporter.dispose(); + + languageConfigurationDisposable.dispose(); } diff --git a/src/session.ts b/src/session.ts index c3fcb3848b..dd6672de5c 100644 --- a/src/session.ts +++ b/src/session.ts @@ -163,7 +163,6 @@ export class SessionManager implements Middleware { } // Create a folder for the session files. await vscode.workspace.fs.createDirectory(this.sessionsFolder); - await this.logger.startNewLog(this.sessionSettings.developer.editorServicesLogLevel); await this.promptPowerShellExeSettingsCleanup(); await this.migrateWhitespaceAroundPipeSetting(); this.PowerShellExeDetails = await this.findPowerShell(); @@ -212,7 +211,7 @@ export class SessionManager implements Middleware { await this.stop(); // Re-load and validate the settings. - await Settings.validateCwdSetting(); + await Settings.validateCwdSetting(this.logger); this.sessionSettings = Settings.load(); await this.start(exeNameOverride); @@ -348,8 +347,8 @@ export class SessionManager implements Middleware { const configurationTargetOfOldSetting = Settings.getEffectiveConfigurationTarget(deprecatedSetting); if (configurationTargetOfOldSetting !== undefined && configurationTargetOfNewSetting === undefined) { const value = configuration.get(deprecatedSetting, configurationTargetOfOldSetting); - await Settings.change(newSetting, value, configurationTargetOfOldSetting); - await Settings.change(deprecatedSetting, undefined, configurationTargetOfOldSetting); + await Settings.change(newSetting, value, configurationTargetOfOldSetting, this.logger); + await Settings.change(deprecatedSetting, undefined, configurationTargetOfOldSetting, this.logger); } } @@ -373,7 +372,7 @@ export class SessionManager implements Middleware { this.suppressRestartPrompt = true; try { - await Settings.change("powerShellExePath", undefined, true); + await Settings.change("powerShellExePath", undefined, true, this.logger); } finally { this.suppressRestartPrompt = false; } @@ -386,6 +385,7 @@ export class SessionManager implements Middleware { private async onConfigurationUpdated() { const settings = Settings.load(); + this.logger.updateLogLevel(settings.developer.editorServicesLogLevel); // Detect any setting changes that would affect the session if (!this.suppressRestartPrompt && @@ -534,8 +534,8 @@ export class SessionManager implements Middleware { if (await utils.checkIfDirectoryExists(path.join(devBundledModulesPath, "PowerShellEditorServices/bin"))) { bundledModulesPath = devBundledModulesPath; } else { - this.logger.write( - "\nWARNING: In development mode but PowerShellEditorServices dev module path cannot be " + + void this.logger.writeAndShowWarning( + "In development mode but PowerShellEditorServices dev module path cannot be " + `found (or has not been built yet): ${devBundledModulesPath}\n`); } } @@ -731,7 +731,8 @@ Type 'help' to get help. this.languageClient!, localVersion!, this.versionDetails!.architecture, - release); + release, + this.logger); } catch (err) { // Best effort. This probably failed to fetch the data from GitHub. this.logger.writeWarning(err instanceof Error ? err.message : "unknown"); @@ -804,7 +805,7 @@ Type 'help' to get help. private async changePowerShellDefaultVersion(exePath: IPowerShellExeDetails) { this.suppressRestartPrompt = true; try { - await Settings.change("powerShellDefaultVersion", exePath.displayName, true); + await Settings.change("powerShellDefaultVersion", exePath.displayName, true, this.logger); } finally { this.suppressRestartPrompt = false; } diff --git a/src/settings.ts b/src/settings.ts index 372cbc3f68..6a64992ce3 100644 --- a/src/settings.ts +++ b/src/settings.ts @@ -4,6 +4,7 @@ import vscode = require("vscode"); import utils = require("./utils"); import os = require("os"); +import { Logger } from "./logging"; enum CodeFormattingPreset { Custom, @@ -299,11 +300,17 @@ export async function change( settingName: string, // eslint-disable-next-line @typescript-eslint/no-explicit-any newValue: any, - configurationTarget?: vscode.ConfigurationTarget | boolean): Promise { + configurationTarget: vscode.ConfigurationTarget | boolean | undefined, + logger: Logger | undefined): Promise { - const configuration = vscode.workspace.getConfiguration(utils.PowerShellLanguageId); - // TODO: Consider wrapping with try/catch, but we can't log the error. - await configuration.update(settingName, newValue, configurationTarget); + logger?.writeDiagnostic(`Changing '${settingName}' at scope '${configurationTarget} to '${newValue}'`); + + try { + const configuration = vscode.workspace.getConfiguration(utils.PowerShellLanguageId); + await configuration.update(settingName, newValue, configurationTarget); + } catch (err) { + logger?.writeError(`Failed to change setting: ${err}`); + } } function getWorkspaceSettingsWithDefaults( @@ -322,7 +329,7 @@ function getWorkspaceSettingsWithDefaults( // We don't want to query the user more than once, so this is idempotent. let hasPrompted = false; -export async function validateCwdSetting(): Promise { +export async function validateCwdSetting(logger: Logger): Promise { let cwd = vscode.workspace.getConfiguration(utils.PowerShellLanguageId).get("cwd"); // Only use the cwd setting if it exists. @@ -347,11 +354,7 @@ export async function validateCwdSetting(): Promise { // Save the picked 'cwd' to the workspace settings. // We have to check again because the user may not have picked. if (cwd !== undefined && await utils.checkIfDirectoryExists(cwd)) { - try { - await change("cwd", cwd); - } catch { - // Could fail if workspace file is invalid. - } + await change("cwd", cwd, undefined, logger); } } diff --git a/test/core/settings.test.ts b/test/core/settings.test.ts index c245209383..8e9f771309 100644 --- a/test/core/settings.test.ts +++ b/test/core/settings.test.ts @@ -11,16 +11,16 @@ describe("Settings module", function () { }); it("Updates correctly", async function () { - await Settings.change("helpCompletion", "LineComment", false); + await Settings.change("helpCompletion", "LineComment", false, undefined); assert.strictEqual(Settings.load().helpCompletion, "LineComment"); }); it("Gets the effective configuration target", async function () { - await Settings.change("helpCompletion", "LineComment", false); + await Settings.change("helpCompletion", "LineComment", false, undefined); let target = Settings.getEffectiveConfigurationTarget("helpCompletion"); assert.strictEqual(target, vscode.ConfigurationTarget.Workspace); - await Settings.change("helpCompletion", undefined, false); + await Settings.change("helpCompletion", undefined, false, undefined); target = Settings.getEffectiveConfigurationTarget("helpCompletion"); assert.strictEqual(target, undefined); });