Auto merge of rust-lang#17722 - joshka:jm/logs, r=Veykril

feat: use vscode log format for client logs

This change updates the log format to use the vscode log format instead
of the custom log format, by replacing the `OutputChannel` with a
`LogOutputChannel` and using the `debug`, `info`, `warn`, and `error`
methods on it. This has the following benefits:

- Each log level now has its own color and the timestamp is in a more
  standard format
- Inspect output (e.g. the log of the config object) is now colored
- Error stack traces are now shown in the output
- The log level is now controlled on the output tab by clicking the gear
  icon and selecting "Debug" or by passing the `--log` parameter to
  vscode. The `trace.extension` setting has been marked as deprecated.

Motivation:
The large uncolored unformatted log output with a large config object logged whenever it changes has always dominated the logs. This subjectively has made it that looking to see what the client is doing has always been a bit disappointing. That said, there's only 17 log messages total in the client. Hopefully by making the logs more visually useful this will encourage adding more appropriate debug level messages in future.

Incidentally, it might be worth only logging the config change message at a debug level instead of an info level to reduce the noise.

Author: bors

.vscode/launch.json

@@ -18,7 +18,8 @@
       "args": [
         // "--user-data-dir=${workspaceFolder}/target/code",
         "--disable-extensions",
-        "--extensionDevelopmentPath=${workspaceFolder}/editors/code"
+        "--extensionDevelopmentPath=${workspaceFolder}/editors/code",
+        "--log rust-lang.rust-analyzer:debug"
       ],
       "outFiles": [
         "${workspaceFolder}/editors/code/out/**/*.js"
@@ -36,7 +37,8 @@
       "runtimeExecutable": "${execPath}",
       "args": [
         "--disable-extensions",
-        "--extensionDevelopmentPath=${workspaceFolder}/editors/code"
+        "--extensionDevelopmentPath=${workspaceFolder}/editors/code",
+        "--log rust-lang.rust-analyzer:debug"
       ],
       "outFiles": [
         "${workspaceFolder}/editors/code/out/**/*.js"
@@ -57,7 +59,8 @@
       "runtimeExecutable": "${execPath}",
       "args": [
         "--disable-extensions",
-        "--extensionDevelopmentPath=${workspaceFolder}/editors/code"
+        "--extensionDevelopmentPath=${workspaceFolder}/editors/code",
+        "--log rust-lang.rust-analyzer:debug"
       ],
       "outFiles": [
         "${workspaceFolder}/editors/code/out/**/*.js"
@@ -79,7 +82,8 @@
       "runtimeExecutable": "${execPath}",
       "args": [
         "--disable-extension", "rust-lang.rust-analyzer",
-        "--extensionDevelopmentPath=${workspaceFolder}/editors/code"
+        "--extensionDevelopmentPath=${workspaceFolder}/editors/code",
+        "--log rust-lang.rust-analyzer:debug"
       ],
       "outFiles": [
         "${workspaceFolder}/editors/code/out/**/*.js"

editors/code/package.json

@@ -483,6 +483,7 @@
                     },
                     "rust-analyzer.trace.extension": {
                         "description": "Enable logging of VS Code extensions itself.",
+                        "markdownDeprecationMessage": "Log level is now controlled by the [Developer: Set Log Level...](command:workbench.action.setLogLevel) command.You can set the log level for the current session and also the default log level from there. This is also available by clicking the gear icon on the OUTPUT tab when Rust Analyzer Client is visible or by passing the --log rust-lang.rust-analyzer:debug parameter to VS Code.",
                         "type": "boolean",
                         "default": false
                     }

editors/code/src/bootstrap.ts

@@ -117,9 +117,11 @@ export function isValidExecutable(path: string, extraEnv: Env): boolean {
         env: { ...process.env, ...extraEnv },
     });
 
-    const printOutput = res.error ? log.warn : log.info;
-    printOutput(path, "--version:", res);
-
+    if (res.error) {
+        log.warn(path, "--version:", res);
+    } else {
+        log.info(path, "--version:", res);
+    }
     return res.status === 0;
 }
 

editors/code/src/config.ts

@@ -41,7 +41,6 @@ export class Config {
     }
 
     private refreshLogging() {
-        log.setEnabled(this.traceExtension ?? false);
         log.info(
             "Extension version:",
             vscode.extensions.getExtension(this.extensionId)!.packageJSON.version,
@@ -253,10 +252,6 @@ export class Config {
         await this.cfg.update("checkOnSave", !(value || false), target || null, overrideInLanguage);
     }
 
-    get traceExtension() {
-        return this.get<boolean>("trace.extension");
-    }
-
     get discoverProjectRunner(): string | undefined {
         return this.get<string | undefined>("discoverProjectRunner");
     }

editors/code/src/ctx.ts

@@ -249,7 +249,8 @@ export class Ctx implements RustAnalyzerExtensionApi {
 
             message +=
                 'See the logs in "OUTPUT > Rust Analyzer Client" (should open automatically). ';
-            message += 'To enable verbose logs use { "rust-analyzer.trace.extension": true }';
+            message +=
+                'To enable verbose logs, click the gear icon in the "OUTPUT" tab and select "Debug".';
 
             log.error("Bootstrap error", err);
             throw new Error(message);

editors/code/src/util.ts

@@ -17,49 +17,48 @@ export type Env = {
     [name: string]: string;
 };
 
-export const log = new (class {
-    private enabled = true;
-    private readonly output = vscode.window.createOutputChannel("Rust Analyzer Client");
+class Log {
+    private readonly output = vscode.window.createOutputChannel("Rust Analyzer Client", {
+        log: true,
+    });
 
-    setEnabled(yes: boolean): void {
-        log.enabled = yes;
+    trace(...messages: [unknown, ...unknown[]]): void {
+        this.output.trace(this.stringify(messages));
     }
 
-    // Hint: the type [T, ...T[]] means a non-empty array
-    debug(...msg: [unknown, ...unknown[]]): void {
-        if (!log.enabled) return;
-        log.write("DEBUG", ...msg);
+    debug(...messages: [unknown, ...unknown[]]): void {
+        this.output.debug(this.stringify(messages));
     }
 
-    info(...msg: [unknown, ...unknown[]]): void {
-        log.write("INFO", ...msg);
+    info(...messages: [unknown, ...unknown[]]): void {
+        this.output.info(this.stringify(messages));
     }
 
-    warn(...msg: [unknown, ...unknown[]]): void {
-        debugger;
-        log.write("WARN", ...msg);
+    warn(...messages: [unknown, ...unknown[]]): void {
+        this.output.warn(this.stringify(messages));
     }
 
-    error(...msg: [unknown, ...unknown[]]): void {
-        debugger;
-        log.write("ERROR", ...msg);
-        log.output.show(true);
+    error(...messages: [unknown, ...unknown[]]): void {
+        this.output.error(this.stringify(messages));
+        this.output.show(true);
     }
 
-    private write(label: string, ...messageParts: unknown[]): void {
-        const message = messageParts.map(log.stringify).join(" ");
-        const dateTime = new Date().toLocaleString();
-        log.output.appendLine(`${label} [${dateTime}]: ${message}`);
+    private stringify(messages: unknown[]): string {
+        return messages
+            .map((message) => {
+                if (typeof message === "string") {
+                    return message;
+                }
+                if (message instanceof Error) {
+                    return message.stack || message.message;
+                }
+                return inspect(message, { depth: 6, colors: false });
+            })
+            .join(" ");
     }
+}
 
-    private stringify(val: unknown): string {
-        if (typeof val === "string") return val;
-        return inspect(val, {
-            colors: false,
-            depth: 6, // heuristic
-        });
-    }
-})();
+export const log = new Log();
 
 export function sleep(ms: number) {
     return new Promise((resolve) => setTimeout(resolve, ms));
@@ -135,7 +134,7 @@ export function execute(command: string, options: ExecOptions): Promise<string>
     return new Promise((resolve, reject) => {
         exec(command, options, (err, stdout, stderr) => {
             if (err) {
-                log.error(err);
+                log.error("error:", err);
                 reject(err);
                 return;
             }