Skip to content

Commit

Permalink
Implement LogOutputWindow for Logging (#5065)
Browse files Browse the repository at this point in the history 
* 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
  • Loading branch information
@JustinGrote
JustinGrote authored Nov 15, 2024
1 parent 7126891 commit 400fd75
Show file tree
Hide file tree
Showing 12 changed files with 422 additions and 245 deletions.
4 changes: 2 additions & 2 deletions docs/troubleshooting.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
46 changes: 23 additions & 23 deletions package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -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,
Expand Down Expand Up @@ -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!**"
}
}
},
Expand Down
22 changes: 17 additions & 5 deletions src/extension.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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";

Expand All @@ -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,
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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(),
};
}

Expand Down
45 changes: 18 additions & 27 deletions src/features/DebugSession.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down Expand Up @@ -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;

Expand All @@ -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 = {
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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 {
Expand Down
13 changes: 9 additions & 4 deletions src/features/ExternalApi.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ export interface IPowerShellExtensionClient {
getPowerShellVersionDetails(uuid: string): Promise<IExternalPowerShellDetails>;
waitUntilStarted(uuid: string): Promise<void>;
getStorageUri(): vscode.Uri;
getLogUri(): vscode.Uri;
}

/*
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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}`);
}
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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();
}

Expand All @@ -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.
}
Expand Down
24 changes: 12 additions & 12 deletions src/features/UpdatePowerShell.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand All @@ -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;
}
}
Expand All @@ -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;
}

Expand All @@ -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);
Expand Down Expand Up @@ -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
Expand Down
Loading

0 comments on commit 400fd75

Please sign in to comment.