extension: replace src/goLogging with vscode LogOutputChannel API

goLogging was used for extension's verbose/debug logging and debug
session's client-side logging ("Go Debug") output channel.

vscode's LogOutputChannel API provides log level control consistent
across all VS Code components. More importantly, this allows users
to inspect verbose/debug level logging messages from the Go output
channel easily, instead of relying on the Developer's debug console
(which is not guaranteed to be accessible from non-desktop editor
integration products).

Convert the "Go Debug" output channel to vscode LogOutputChannel.
This allows us to control the logging level separate from the shared
go.logging.level configuration.

In fact, 'go.logging.level' setting is no longer necessary.
Mark it deprecated.

Change-Id: I4180eb1ce8afee63863d741b3501f0624aa42433
Reviewed-on: https://go-review.googlesource.com/c/vscode-go/+/559739
TryBot-Result: kokoro <noreply+kokoro@google.com>
Reviewed-by: Suzy Mueller <suzmue@golang.org>
Auto-Submit: Hyang-Ah Hana Kim <hyangah@gmail.com>
Commit-Queue: Hyang-Ah Hana Kim <hyangah@gmail.com>

docs/settings.md

@@ -345,12 +345,10 @@ Specifies Lint tool name.<br/>
 Allowed Options: `staticcheck`, `golint`, `golangci-lint`, `revive`
 
 Default: `"staticcheck"`
-### `go.logging.level`
+### `go.logging.level (deprecated)`
 
-The logging level the extension logs at, defaults to 'error'<br/>
-Allowed Options: `off`, `error`, `info`, `verbose`
+This setting is deprecated. Use 'Developer: Set Log Level...' command to control logging level instead.
 
-Default: `"error"`
 ### `go.playground`
 
 The flags configured here will be passed through to command `goplay`

extension/package.json

@@ -1514,14 +1514,7 @@
         },
         "go.logging.level": {
           "type": "string",
-          "default": "error",
-          "enum": [
-            "off",
-            "error",
-            "info",
-            "verbose"
-          ],
-          "description": "The logging level the extension logs at, defaults to 'error'",
+          "deprecationMessage": "This setting is deprecated. Use 'Developer: Set Log Level...' command to control logging level instead.",
           "scope": "machine-overridable"
         },
         "go.toolsManagement.go": {

extension/src/goDebugFactory.ts

@@ -12,15 +12,14 @@ import getPort = require('get-port');
 import path = require('path');
 import * as fs from 'fs';
 import * as net from 'net';
-import { Logger, logVerbose, TimestampedLogger } from './goLogging';
 import { DebugProtocol } from 'vscode-debugprotocol';
 import { getWorkspaceFolderPath } from './util';
 import { getEnvPath, getBinPathFromEnvVar } from './utils/pathUtils';
 import { GoExtensionContext } from './context';
 import { createRegisterCommand } from './commands';
 
 export function activate(ctx: vscode.ExtensionContext, goCtx: GoExtensionContext) {
-	const debugOutputChannel = vscode.window.createOutputChannel('Go Debug');
+	const debugOutputChannel = vscode.window.createOutputChannel('Go Debug', { log: true });
 	ctx.subscriptions.push(debugOutputChannel);
 
 	const factory = new GoDebugAdapterDescriptorFactory(debugOutputChannel);
@@ -40,7 +39,7 @@ export function activate(ctx: vscode.ExtensionContext, goCtx: GoExtensionContext
 }
 
 class GoDebugAdapterDescriptorFactory implements vscode.DebugAdapterDescriptorFactory {
-	constructor(private outputChannel?: vscode.OutputChannel) {}
+	constructor(private outputChannel: vscode.LogOutputChannel) {}
 
 	public createDebugAdapterDescriptor(
 		session: vscode.DebugSession,
@@ -59,11 +58,11 @@ class GoDebugAdapterDescriptorFactory implements vscode.DebugAdapterDescriptorFa
 	private async createDebugAdapterDescriptorDlvDap(
 		configuration: vscode.DebugConfiguration
 	): Promise<vscode.ProviderResult<vscode.DebugAdapterDescriptor>> {
-		const logger = new TimestampedLogger(configuration.trace, this.outputChannel);
-		logger.debug(`Config: ${JSON.stringify(configuration)}\n`);
+		const logger = this.outputChannel;
+		logger.debug(`Config: ${JSON.stringify(configuration)}`);
 		if (configuration.port) {
 			const host = configuration.host ?? '127.0.0.1';
-			logger.info(`Connecting to DAP server at ${host}:${configuration.port}\n`);
+			logger.info(`Connecting to DAP server at ${host}:${configuration.port}`);
 			return new vscode.DebugAdapterServer(configuration.port, host);
 		}
 		const d = new DelveDAPOutputAdapter(configuration, logger);
@@ -72,28 +71,24 @@ class GoDebugAdapterDescriptorFactory implements vscode.DebugAdapterDescriptorFa
 }
 
 class GoDebugAdapterTrackerFactory implements vscode.DebugAdapterTrackerFactory {
-	constructor(private outputChannel: vscode.OutputChannel) {}
+	constructor(private outputChannel: vscode.LogOutputChannel) {}
 
 	createDebugAdapterTracker(session: vscode.DebugSession) {
-		const level = session.configuration?.trace;
-		if (!level || level === 'off') {
-			return null;
-		}
-		const logger = new TimestampedLogger(session.configuration?.trace || 'off', this.outputChannel);
+		const logger = this.outputChannel;
 		let requestsSent = 0;
 		let responsesReceived = 0;
 		return {
 			onWillStartSession: () =>
-				logger.debug(`session ${session.id} will start with ${JSON.stringify(session.configuration)}\n`),
+				logger.debug(`session ${session.id} will start with ${JSON.stringify(session.configuration)}`),
 			onWillReceiveMessage: (message: any) => {
-				logger.trace(`client -> ${JSON.stringify(message)}\n`);
+				logger.trace(`client -> ${JSON.stringify(message)}`);
 				requestsSent++;
 			},
 			onDidSendMessage: (message: any) => {
-				logger.trace(`client  <- ${JSON.stringify(message)}\n`);
+				logger.trace(`client  <- ${JSON.stringify(message)}`);
 				responsesReceived++;
 			},
-			onError: (error: Error) => logger.error(`error: ${error}\n`),
+			onError: (error: Error) => logger.error(`error: ${error}`),
 			onWillStopSession: () => {
 				if (
 					session.configuration.debugAdapter === 'dlv-dap' &&
@@ -109,7 +104,7 @@ class GoDebugAdapterTrackerFactory implements vscode.DebugAdapterTrackerFactory
 				logger.debug(`session ${session.id} will stop\n`);
 			},
 			onExit: (code: number | undefined, signal: string | undefined) =>
-				logger.info(`debug adapter exited: (code: ${code}, signal: ${signal})\n`)
+				logger.info(`debug adapter exited: (code: ${code}, signal: ${signal})`)
 		};
 	}
 
@@ -118,6 +113,8 @@ class GoDebugAdapterTrackerFactory implements vscode.DebugAdapterTrackerFactory
 
 const TWO_CRLF = '\r\n\r\n';
 
+type ILogger = Pick<vscode.LogOutputChannel, 'error' | 'info' | 'debug' | 'trace'>;
+
 // Proxies DebugProtocolMessage exchanges between VSCode and a remote
 // process or server connected through a duplex stream, after its
 // start method is called.
@@ -126,10 +123,10 @@ export class ProxyDebugAdapter implements vscode.DebugAdapter {
 	// connection from/to server (= dlv dap)
 	private readable?: stream.Readable;
 	private writable?: stream.Writable;
-	protected logger?: Logger;
+	protected logger: ILogger;
 	private terminated = false;
 
-	constructor(logger: Logger) {
+	constructor(logger: ILogger) {
 		this.logger = logger;
 		this.onDidSendMessage = this.messageEmitter.event;
 	}
@@ -240,7 +237,7 @@ export class ProxyDebugAdapter implements vscode.DebugAdapter {
 // VSCode and a dlv dap process spawned and managed by this adapter.
 // It turns the process's stdout/stderrr into OutputEvent.
 export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
-	constructor(private configuration: vscode.DebugConfiguration, logger: Logger) {
+	constructor(private configuration: vscode.DebugConfiguration, logger: ILogger) {
 		super(logger);
 	}
 
@@ -252,7 +249,7 @@ export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
 	protected sendMessageToClient(message: vscode.DebugProtocolMessage) {
 		const m = message as any;
 		if (m.type === 'request') {
-			logVerbose(`do not forward reverse request: dropping ${JSON.stringify(m)}`);
+			this.logger.debug(`do not forward reverse request: dropping ${JSON.stringify(m)}`);
 			return;
 		}
 
@@ -262,7 +259,7 @@ export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
 	protected async sendMessageToServer(message: vscode.DebugProtocolMessage): Promise<void> {
 		const m = message as any;
 		if (m.type === 'response') {
-			logVerbose(`do not forward reverse request response: dropping ${JSON.stringify(m)}`);
+			this.logger.debug(`do not forward reverse request response: dropping ${JSON.stringify(m)}`);
 			return;
 		}
 
@@ -353,7 +350,7 @@ export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
 		} catch (err) {
 			return { connected: false, reason: err };
 		}
-		this.logger?.debug(`Running dlv dap server: pid=${this.dlvDapServer?.pid}\n`);
+		this.logger?.debug(`Running dlv dap server: pid=${this.dlvDapServer?.pid}`);
 		return { connected: true };
 	}
 
@@ -372,7 +369,7 @@ export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
 			// may not appear in the DEBUG CONSOLE. For easier debugging, log
 			// the messages through the logger that prints to Go Debug output
 			// channel.
-			this.logger?.info(msg);
+			this.logger?.trace(msg);
 		};
 
 		// If a port has been specified, assume there is an already
@@ -437,7 +434,7 @@ export class DelveDAPOutputAdapter extends ProxyDebugAdapter {
 
 		try {
 			const port = await getPort();
-			const rendezvousServerPromise = waitForDAPServer(port, 30_000);
+			const rendezvousServerPromise = waitForDAPServer(port, 30_000, this.logger);
 
 			dlvArgs.push(`--client-addr=:${port}`);
 
@@ -470,7 +467,7 @@ function getSudo(): string | null {
 	return sudoPath;
 }
 
-function waitForDAPServer(port: number, timeoutMs: number): Promise<net.Socket> {
+function waitForDAPServer(port: number, timeoutMs: number, logger: ILogger): Promise<net.Socket> {
 	return new Promise((resolve, reject) => {
 		// eslint-disable-next-line prefer-const
 		let s: net.Server | undefined;
@@ -482,7 +479,7 @@ function waitForDAPServer(port: number, timeoutMs: number): Promise<net.Socket>
 		}, timeoutMs);
 
 		s = net.createServer({ pauseOnConnect: true }, (socket) => {
-			logVerbose(
+			logger.debug(
 				`connected: ${port} (remote: ${socket.remoteAddress}:${socket.remotePort} local: ${socket.localAddress}:${socket.localPort})`
 			);
 			clearTimeout(timeoutToken);
@@ -491,7 +488,7 @@ function waitForDAPServer(port: number, timeoutMs: number): Promise<net.Socket>
 			resolve(socket);
 		});
 		s.on('error', (err) => {
-			logVerbose(`connection error ${err}`);
+			logger.error(`connection error ${err}`);
 			reject(err);
 		});
 		s.maxConnections = 1;

extension/src/goEnv.ts

@@ -8,9 +8,9 @@
 import vscode = require('vscode');
 import { getGoConfig } from './config';
 import { getCurrentGoPath, getToolsGopath, resolvePath, substituteEnv } from './util';
-import { logVerbose } from './goLogging';
 import { dirExists } from './utils/pathUtils';
 import { getFromGlobalState, updateGlobalState } from './stateUtils';
+import { outputChannel } from './goStatus';
 
 // toolInstallationEnvironment returns the environment in which tools should
 // be installed. It always returns a new object.
@@ -67,7 +67,7 @@ export function toolExecutionEnvironment(uri?: vscode.Uri, addProcessEnv = true)
 	// Remove json flag (-json or --json=<any>) from GOFLAGS because it will effect to result format of the execution
 	if (env['GOFLAGS'] && env['GOFLAGS'].includes('-json')) {
 		env['GOFLAGS'] = env['GOFLAGS'].replace(/(^|\s+)-?-json[^\s]*/g, '');
-		logVerbose(`removed -json from GOFLAGS: ${env['GOFLAGS']}`);
+		outputChannel.debug(`removed -json from GOFLAGS: ${env['GOFLAGS']}`);
 	}
 	return env;
 }
@@ -127,7 +127,9 @@ export async function setGOROOTEnvVar(configGOROOT: string) {
 			});
 	}
 
-	logVerbose(`setting GOROOT = ${goroot} (old value: ${currentGOROOT}) because "go.goroot": "${configGOROOT}"`);
+	outputChannel.debug(
+		`setting GOROOT = ${goroot} (old value: ${currentGOROOT}) because "go.goroot": "${configGOROOT}"`
+	);
 	if (goroot) {
 		process.env['GOROOT'] = goroot;
 	} else {

extension/src/goEnvironmentStatus.ts

@@ -15,7 +15,6 @@ import path = require('path');
 import { promisify } from 'util';
 import { getGoConfig, extensionInfo } from './config';
 import { toolInstallationEnvironment } from './goEnv';
-import { logVerbose } from './goLogging';
 import { addGoStatus, goEnvStatusbarItem, outputChannel, removeGoStatus } from './goStatus';
 import { getFromGlobalState, getFromWorkspaceState, updateGlobalState, updateWorkspaceState } from './stateUtils';
 import { getBinPath, getCheckForToolsUpdatesConfig, getGoVersion, GoVersion } from './util';
@@ -295,7 +294,7 @@ export function addGoRuntimeBaseToPATH(newGoRuntimeBase: string) {
 	}
 	const pathEnvVar = pathEnvVarName();
 	if (!pathEnvVar) {
-		logVerbose("couldn't find PATH property in process.env");
+		outputChannel.debug("couldn't find PATH property in process.env");
 		return;
 	}
 
@@ -304,7 +303,7 @@ export function addGoRuntimeBaseToPATH(newGoRuntimeBase: string) {
 		defaultPathEnv = <string>process.env[pathEnvVar];
 	}
 
-	logVerbose(`addGoRuntimeBase(${newGoRuntimeBase}) when PATH=${defaultPathEnv}`);
+	outputChannel.debug(`addGoRuntimeBase(${newGoRuntimeBase}) when PATH=${defaultPathEnv}`);
 
 	// calling this multiple times will override the previous value.
 	// environmentVariableCollection.clear();
@@ -354,7 +353,7 @@ export function clearGoRuntimeBaseFromPATH() {
 	}
 	const pathEnvVar = pathEnvVarName();
 	if (!pathEnvVar) {
-		logVerbose("couldn't find PATH property in process.env");
+		outputChannel.debug("couldn't find PATH property in process.env");
 		return;
 	}
 	environmentVariableCollection?.delete(pathEnvVar);

extension/src/goInstallTools.ts

@@ -16,7 +16,6 @@ import { ConfigurationTarget } from 'vscode';
 import { extensionInfo, getGoConfig, getGoplsConfig } from './config';
 import { toolExecutionEnvironment, toolInstallationEnvironment } from './goEnv';
 import { addGoRuntimeBaseToPATH, clearGoRuntimeBaseFromPATH } from './goEnvironmentStatus';
-import { logVerbose, logError } from './goLogging';
 import { GoExtensionContext } from './context';
 import { addGoStatus, initGoStatusBar, outputChannel, removeGoStatus } from './goStatus';
 import { containsTool, getConfiguredTools, getImportPathWithVersion, getTool, Tool, ToolAtVersion } from './goTools';
@@ -109,22 +108,19 @@ export async function installAllTools(updateExistingToolsOnly = false) {
 async function getGoForInstall(goVersion: GoVersion, silent?: boolean): Promise<GoVersion> {
 	const configured = getGoConfig().get<string>('toolsManagement.go');
 	if (!configured) {
-		return goVersion;
+		return goVersion; // use the default.
 	}
 
 	try {
 		const go = await getGoVersion(configured);
 		if (go) return go;
 	} catch (e) {
-		logError(`getGoForInstall failed to run 'go version' with the configured go for tool install: ${e}`);
-	} finally {
 		if (!silent) {
 			outputChannel.error(
-				`Ignoring misconfigured 'go.toolsManagement.go' (${configured}). Provide a valid path to the Go command.`
+				`failed to run "go version" with "${configured}". Provide a valid path to the Go binary`
 			);
 		}
 	}
-
 	return goVersion;
 }
 
@@ -152,7 +148,10 @@ export async function installTools(
 		return [];
 	}
 	const { silent, skipRestartGopls } = options || {};
-	outputChannel.appendLine('Installing tools...');
+	if (!silent) {
+		outputChannel.show();
+	}
+	outputChannel.clear();
 
 	const goForInstall = await getGoForInstall(goVersion);
 
@@ -219,9 +218,9 @@ export async function installTools(
 		if (silent) {
 			outputChannel.show();
 		}
-		outputChannel.error(failures.length + ' tools failed to install.\n');
+		outputChannel.appendLine(failures.length + ' tools failed to install.\n');
 		for (const failure of failures) {
-			outputChannel.error(`${failure.tool.name}: ${failure.reason} `);
+			outputChannel.appendLine(`${failure.tool.name}: ${failure.reason} `);
 		}
 	}
 	if (missing.some((tool) => tool.isImportant)) {
@@ -277,8 +276,8 @@ async function installToolWithGo(
 		const toolInstallPath = getBinPath(tool.name);
 		outputChannel.appendLine(`Installing ${importPath} (${toolInstallPath}) SUCCEEDED`);
 	} catch (e) {
-		outputChannel.error(`Installing ${importPath} FAILED`);
-		outputChannel.error(`${JSON.stringify(e, null, 1)}`);
+		outputChannel.appendLine(`Installing ${importPath} FAILED`);
+		outputChannel.appendLine(`${JSON.stringify(e, null, 1)}`);
 		return `failed to install ${tool.name}(${importPath}): ${e}`;
 	}
 }
@@ -293,7 +292,7 @@ async function installToolWithGoInstall(goVersion: GoVersion, env: NodeJS.Dict<s
 	};
 
 	const execFile = util.promisify(cp.execFile);
-	logVerbose(`$ ${goBinary} install -v ${importPath}} (cwd: ${opts.cwd})`);
+	outputChannel.trace(`$ ${goBinary} install -v ${importPath}} (cwd: ${opts.cwd})`);
 	await execFile(goBinary, ['install', '-v', importPath], opts);
 }
 
@@ -452,7 +451,7 @@ export function updateGoVarsFromConfig(goCtx: GoExtensionContext): Promise<void>
 	const { binPath, why } = getBinPathWithExplanation('go', false);
 	const goRuntimePath = binPath;
 
-	logVerbose(`updateGoVarsFromConfig: found 'go' in ${goRuntimePath}`);
+	outputChannel.debug(`updateGoVarsFromConfig: found 'go' in ${goRuntimePath}`);
 	if (!goRuntimePath || !path.isAbsolute(goRuntimePath)) {
 		// getBinPath returns the absolute path to the tool if it exists.
 		// Otherwise, it may return the tool name (e.g. 'go').
@@ -481,12 +480,13 @@ export function updateGoVarsFromConfig(goCtx: GoExtensionContext): Promise<void>
 				if (stderr) {
 					// 'go env' may output warnings about potential misconfiguration.
 					// Show the messages to users but keep processing the stdout.
-					outputChannel.error(`'${goRuntimePath} env': ${stderr}`);
+					outputChannel.append(`'${goRuntimePath} env': ${stderr}`);
 					outputChannel.show();
 				}
-				logVerbose(`${goRuntimePath} env ...:\n${stdout}`);
+				outputChannel.trace(`${goRuntimePath} env ...:\n${stdout}`);
 				const envOutput = JSON.parse(stdout);
 				if (envOutput.GOROOT && envOutput.GOROOT.trim()) {
+					outputChannel.debug('setCurrentGOROOT:', envOutput.GOROOT);
 					setCurrentGoRoot(envOutput.GOROOT.trim());
 					delete envOutput.GOROOT;
 				}