Merge branch 'topic/vscode-logging' into 'master'

Set up logging in the VS Code extension

See merge request eng/ide/ada_language_server!1285

Author: eliericha

.vscode/tasks.json

@@ -24,7 +24,7 @@
          "script": "compile",
          "path": "integration/vscode/ada",
          "group": "build",
-         "problemMatcher": [],
+         "problemMatcher": ["$tsc"],
          "label": "npm: compile",
          "detail": "node ./node_modules/typescript/bin/tsc",
          "presentation": {

integration/vscode/ada/package-lock.json

@@ -790,10 +790,11 @@
     "dependencies": {
         "@types/command-exists": "1.2.0",
         "command-exists": "1.2.9",
+        "fast-xml-parser": "4.2.5",
         "fp-ts": "2.12.0",
         "process": "0.11.10",
         "vscode-languageclient": "7.0.0",
-        "ws": "8.13.0",
-        "fast-xml-parser": "4.2.5"
+        "winston": "3.10.0",
+        "ws": "8.13.0"
     }
 }

integration/vscode/ada/package.json

@@ -7,7 +7,7 @@ import {
     LanguageClientOptions,
     ServerOptions,
 } from 'vscode-languageclient/node';
-import { mainLogChannel } from './extension';
+import { logger } from './extension';
 import GnatTaskProvider from './gnatTaskProvider';
 import GprTaskProvider from './gprTaskProvider';
 import { logErrorAndThrow } from './helpers';
@@ -128,7 +128,7 @@ function createClient(
             logErrorAndThrow(
                 `The Ada language server given in the ALS environment ` +
                     `variable does not exist: ${serverExecPath}`,
-                mainLogChannel
+                logger
             );
         }
     } else {
@@ -138,11 +138,13 @@ function createClient(
                     `language server for your architecture (${process.arch}) ` +
                     `and platform (${process.platform}) ` +
                     `at the expected location: ${serverExecPath}`,
-                mainLogChannel
+                logger
             );
         }
     }
 
+    logger.debug(`Using ALS at: ${serverExecPath}`);
+
     // The debug options for the server
     // let debugOptions = { execArgv: [] };
     // If the extension is launched in debug mode then the debug server options are used

integration/vscode/ada/src/clients.ts

@@ -2,7 +2,7 @@ import * as vscode from 'vscode';
 import { SymbolKind } from 'vscode';
 import { ContextClients } from './clients';
 import { getOrAskForProgram } from './debugConfigProvider';
-import { mainLogChannel } from './extension';
+import { mainOutputChannel } from './extension';
 import { getEnclosingSymbol } from './taskProviders';
 
 export function registerCommands(context: vscode.ExtensionContext, clients: ContextClients) {
@@ -13,7 +13,7 @@ export function registerCommands(context: vscode.ExtensionContext, clients: Cont
         vscode.commands.registerCommand('ada.subprogramBox', addSupbrogramBoxCommand)
     );
     context.subscriptions.push(
-        vscode.commands.registerCommand('ada.showExtensionOutput', () => mainLogChannel.show())
+        vscode.commands.registerCommand('ada.showExtensionOutput', () => mainOutputChannel.show())
     );
     context.subscriptions.push(
         vscode.commands.registerCommand('ada.showAdaLSOutput', () =>

integration/vscode/ada/src/commands.ts

@@ -19,7 +19,10 @@
 import * as process from 'process';
 import * as vscode from 'vscode';
 
-import { LanguageClient, Middleware } from 'vscode-languageclient/node';
+import { MESSAGE } from 'triple-beam';
+import { ExecuteCommandRequest, LanguageClient, Middleware } from 'vscode-languageclient/node';
+import winston, { format, transports } from 'winston';
+import Transport from 'winston-transport';
 import { ALSClientFeatures } from './alsClientFeatures';
 import { alsCommandExecutor } from './alsExecuteCommand';
 import { ContextClients } from './clients';
@@ -28,39 +31,116 @@ import { initializeDebugging } from './debugConfigProvider';
 import { initializeTestView } from './gnattest';
 import {
     assertSupportedEnvironments,
+    getCustomEnvSettingName,
     getEvaluatedCustomEnv,
     setCustomEnvironment,
+    startedInDebugMode,
 } from './helpers';
-import { ExecuteCommandRequest } from 'vscode-languageclient/node';
 
 const ADA_CONTEXT = 'ADA_PROJECT_CONTEXT';
 export let contextClients: ContextClients;
-export let mainLogChannel: vscode.OutputChannel;
+
+/**
+ * The `vscode.OutputChannel` that hosts messages from the extension. This is
+ * different from the channels associated with the language servers.
+ */
+export let mainOutputChannel: vscode.OutputChannel;
+
+/**
+ * A Winston logger object associated with the main output channel that allows
+ * logging messages in a uniform format.
+ */
+export const logger: winston.Logger = winston.createLogger({
+    format: format.combine(
+        // Include a timestamp
+        format.timestamp({
+            format: 'YYYY-MM-DD HH:mm:ss.SSS',
+        }),
+        // Annotate log messages with a label
+        format.label({ label: 'Ada Extension' }),
+        // Pad message levels for alignment
+        format.padLevels(),
+        // Include a stack trace for logged Error objects
+        format.errors({ stack: true }),
+        // Perform printf-style %s,%d replacements
+        format.splat()
+    ),
+});
+
+/**
+ * This is a custom Winston transport that forwards logged messages onto a given
+ * `vscode.OutputChannel`.
+ */
+class VSCodeOutputChannelTransport extends Transport {
+    outputChannel: vscode.OutputChannel;
+
+    constructor(channel: vscode.OutputChannel, opts?: Transport.TransportStreamOptions) {
+        super(opts);
+        this.outputChannel = channel;
+    }
+
+    /**
+     * This implementation is based on the Winston documentation for custom transports.
+     *
+     * @param info - the log entry info object
+     * @param next - a callback
+     */
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    public log(info: any, next: () => void) {
+        setImmediate(() => {
+            this.emit('logged', info);
+        });
+
+        /*
+         * The formatted message is stored under the 'message' symbol in the info object.
+         */
+        // eslint-disable-next-line max-len
+        // eslint-disable-next-line @typescript-eslint/no-unsafe-argument, @typescript-eslint/no-unsafe-member-access
+        this.outputChannel.appendLine(info[MESSAGE]);
+
+        if (next) {
+            next();
+        }
+    }
+}
 
 export async function activate(context: vscode.ExtensionContext): Promise<void> {
-    // Create an output channel for the extension. There are dedicated channels
-    // for the Ada and Gpr language servers, and this one is a general channel
-    // for non-LSP features of the extension.
-    mainLogChannel = vscode.window.createOutputChannel('Ada Extension');
-    mainLogChannel.appendLine('Starting Ada extension');
+    setUpLogging();
+
+    logger.info('Starting Ada extension');
+
+    try {
+        await activateExtension(context);
+    } catch (error) {
+        logger.error('Error while starting Ada extension. ', error);
+        throw error;
+    }
+
+    logger.info('Finished starting Ada extension');
+}
+
+async function activateExtension(context: vscode.ExtensionContext) {
+    assertSupportedEnvironments(logger);
 
     // Log the environment that the extension (and all VS Code) will be using
     const customEnv = getEvaluatedCustomEnv();
 
     if (customEnv && Object.keys(customEnv).length > 0) {
-        mainLogChannel.appendLine('Setting environment variables:');
+        logger.info('Setting environment variables:');
         for (const varName in customEnv) {
             const varValue: string = customEnv[varName];
-            mainLogChannel.appendLine(`${varName}=${varValue}`);
+            logger.info(`${varName}=${varValue}`);
         }
+    } else {
+        logger.debug('No custom environment variables set in %s', getCustomEnvSettingName());
     }
 
     // Set the custom environment into the current node process. This must be
     // done before calling assertSupportedEnvironments in order to set the ALS
     // environment variable if provided.
     setCustomEnvironment();
 
-    assertSupportedEnvironments(mainLogChannel);
+    assertSupportedEnvironments(logger);
 
     // Create the Ada and GPR clients.
     contextClients = new ContextClients(context);
@@ -72,6 +152,7 @@ export async function activate(context: vscode.ExtensionContext): Promise<void>
     contextClients.adaClient.registerFeature(new ALSClientFeatures());
 
     contextClients.start();
+
     context.subscriptions.push(contextClients);
 
     context.subscriptions.push(
@@ -91,8 +172,56 @@ export async function activate(context: vscode.ExtensionContext): Promise<void>
     initializeDebugging(context);
 
     registerCommands(context, contextClients);
+}
+
+function setUpLogging() {
+    // Create an output channel for the extension. There are dedicated channels
+    // for the Ada and Gpr language servers, and this one is a general channel
+    // for non-LSP features of the extension.
+    mainOutputChannel = vscode.window.createOutputChannel('Ada Extension');
 
-    mainLogChannel.appendLine('Started Ada extension');
+    /*
+     * This is a printing formatter that converts log entries to a string. It
+     * used both for logging to the output channel and to the console.
+     */
+    const printfFormatter = format.printf((info) => {
+        // eslint-disable-next-line @typescript-eslint/restrict-template-expressions
+        return `${info.timestamp} [${info.label}] ${info.level.toUpperCase()} ${info.message} ${
+            // eslint-disable-next-line @typescript-eslint/restrict-template-expressions
+            info.stack ?? ''
+        }`;
+    });
+
+    /*
+     * Add a transport to direct log messages to the main
+     * `vscode.OutputChannel`. Set the log level to 'info' to include 'error',
+     * 'warn' and 'info'. See winston documentation for log levels:
+     * https://github.com/winstonjs/winston#logging-levels
+     *
+     * TODO consider making the log level configurable through a verbosity
+     * extension setting
+     */
+    logger.add(
+        new VSCodeOutputChannelTransport(mainOutputChannel, {
+            format: printfFormatter,
+            level: 'info',
+        })
+    );
+
+    if (startedInDebugMode()) {
+        // In debug mode, print log messages to the console with colors. Use
+        // level 'debug' for more verbosity.
+        logger.add(
+            new transports.Console({
+                format: format.combine(
+                    printfFormatter,
+                    // Colorization must be applied after the finalizing printf formatter
+                    format.colorize({ all: true })
+                ),
+                level: 'debug',
+            })
+        );
+    }
 }
 
 export async function deactivate() {

integration/vscode/ada/src/extension.ts

@@ -19,7 +19,8 @@ import { platform } from 'os';
 import * as path from 'path';
 import * as vscode from 'vscode';
 import { ExecuteCommandRequest, LanguageClient } from 'vscode-languageclient/node';
-import { contextClients } from './extension';
+import winston from 'winston';
+import { contextClients, logger } from './extension';
 
 /**
  * Substitue any variable reference present in the given string. VS Code
@@ -113,6 +114,16 @@ export function substituteVariables(str: string, recursive = false): string {
 */
 
 export function getCustomEnv() {
+    const env_config_name = getCustomEnvSettingName();
+
+    const custom_env = vscode.workspace
+        .getConfiguration()
+        .get<{ [name: string]: string }>(env_config_name);
+
+    return custom_env;
+}
+
+export function getCustomEnvSettingName() {
     const user_platform = platform();
     let env_config_name = 'terminal.integrated.env';
 
@@ -126,12 +137,7 @@ export function getCustomEnv() {
         default:
             env_config_name += '.linux';
     }
-
-    const custom_env = vscode.workspace
-        .getConfiguration()
-        .get<{ [name: string]: string }>(env_config_name);
-
-    return custom_env;
+    return env_config_name;
 }
 
 export function getEvaluatedCustomEnv() {
@@ -169,7 +175,7 @@ export function setCustomEnvironment() {
     }
 }
 
-export function assertSupportedEnvironments(mainChannel: vscode.OutputChannel) {
+export function assertSupportedEnvironments(mainChannel: winston.Logger) {
     if (process.env.ALS) {
         // The User provided an external ALS executable. Do not perform any
         // platform support checks because we may be on an unsupported platform
@@ -198,11 +204,15 @@ export function assertSupportedEnvironments(mainChannel: vscode.OutputChannel) {
             `architecture '${process.arch}' and platform '${process.platform}'`;
         logErrorAndThrow(msg, mainChannel);
     }
+
+    logger.debug(
+        `Asserted compatibility with runtime environment: ${process.arch}, ${process.platform}`
+    );
 }
 
-export function logErrorAndThrow(msg: string, channel: vscode.OutputChannel) {
+export function logErrorAndThrow(msg: string, logger: winston.Logger) {
     void vscode.window.showErrorMessage(msg);
-    channel.appendLine('[Error] ' + msg);
+    logger.error(msg);
     throw new Error(msg);
 }
 
@@ -306,3 +316,15 @@ export class AdaMain {
         return vscode.workspace.asRelativePath(this.execFullPath);
     }
 }
+
+/**
+ *
+ * @returns true if the Node process was started with debug command line arguments
+ */
+export function startedInDebugMode() {
+    const args = process.execArgv;
+    if (args) {
+        return args.some((arg) => /^--(debug(-brk)?|inspect-brk)=?/.test(arg));
+    }
+    return false;
+}