Merge #5229

5229: Improve client logging (use output channel and more log levels) r=matklad a=Veetaha

The improvements:
* Separate output channel allows viewing the logs belonging to only our extension (without the intervention of other vscode extensions)
* All the objects in the output channel are always expanded so users only need to `Ctrl + A and Ctrl + C` to copy the entire output to send us and nothing more (e.g. currently users need to expand the object which is not obvious for them and we may lose the logs this way, see two comments: #5009 (comment)
* More log levels allows us to be more granular in disabling only optional verbose debug-level output and leave the logs for us as developers to understand the context of user issues.
* For `log.error(...)` invocations we reveal `Rust Analyzer Client` channel automatically so that users don't have to do any additional actions to get the logs output window visible

Demo:
![image](https://user-images.githubusercontent.com/36276403/86535275-d7795f80-bee7-11ea-8c30-135c83c1bc7d.png)



Co-authored-by: Veetaha <[email protected]>

Author: bors[bot]

editors/code/src/config.ts

@@ -39,10 +39,10 @@ export class Config {
 
     private refreshLogging() {
         log.setEnabled(this.traceExtension);
-        log.debug(
-            "Extension version:", this.package.version,
-            "using configuration:", this.cfg
-        );
+        log.info("Extension version:", this.package.version);
+
+        const cfg = Object.entries(this.cfg).filter(([_, val]) => !(val instanceof Function));
+        log.info("Using configuration", Object.fromEntries(cfg));
     }
 
     private async onDidChangeConfiguration(event: vscode.ConfigurationChangeEvent) {

editors/code/src/main.ts

@@ -59,8 +59,8 @@ async function tryActivate(context: vscode.ExtensionContext) {
             message += "you should close them and reload this window to retry. ";
         }
 
-        message += 'Open "Help > Toggle Developer Tools > Console" to see the logs ';
-        message += '(enable verbose logs with "rust-analyzer.trace.extension")';
+        message += 'See the logs in "OUTPUT > Rust Analyzer Client" (should open automatically). ';
+        message += 'To enable verbose logs use { "rust-analyzer.trace.extension": true }';
 
         log.error("Bootstrap error", err);
         throw new Error(message);
@@ -214,7 +214,7 @@ async function bootstrapServer(config: Config, state: PersistentState): Promise<
         );
     }
 
-    log.debug("Using server binary at", path);
+    log.info("Using server binary at", path);
 
     if (!isValidExecutable(path)) {
         throw new Error(`Failed to execute ${path} --version`);

editors/code/src/persistent_state.ts

@@ -4,7 +4,7 @@ import { log } from './util';
 export class PersistentState {
     constructor(private readonly globalState: vscode.Memento) {
         const { lastCheck, releaseId, serverVersion } = this;
-        log.debug("PersistentState: ", { lastCheck, releaseId, serverVersion });
+        log.info("PersistentState:", { lastCheck, releaseId, serverVersion });
     }
 
     /**

editors/code/src/util.ts

@@ -1,7 +1,9 @@
 import * as lc from "vscode-languageclient";
+import * as fs from "fs";
 import * as vscode from "vscode";
 import { strict as nativeAssert } from "assert";
 import { spawnSync } from "child_process";
+import { inspect } from "util";
 
 export function assert(condition: boolean, explanation: string): asserts condition {
     try {
@@ -14,21 +16,46 @@ export function assert(condition: boolean, explanation: string): asserts conditi
 
 export const log = new class {
     private enabled = true;
+    private readonly output = vscode.window.createOutputChannel("Rust Analyzer Client");
 
     setEnabled(yes: boolean): void {
         log.enabled = yes;
     }
 
-    debug(message?: any, ...optionalParams: any[]): void {
+    // Hint: the type [T, ...T[]] means a non-empty array
+    debug(...msg: [unknown, ...unknown[]]): void {
         if (!log.enabled) return;
-        // eslint-disable-next-line no-console
-        console.log(message, ...optionalParams);
+        log.write("DEBUG", ...msg);
+        log.output.toString();
     }
 
-    error(message?: any, ...optionalParams: any[]): void {
+    info(...msg: [unknown, ...unknown[]]): void {
+        log.write("INFO", ...msg);
+    }
+
+    warn(...msg: [unknown, ...unknown[]]): void {
+        debugger;
+        log.write("WARN", ...msg);
+    }
+
+    error(...msg: [unknown, ...unknown[]]): void {
         debugger;
-        // eslint-disable-next-line no-console
-        console.error(message, ...optionalParams);
+        log.write("ERROR", ...msg);
+        log.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(val: unknown): string {
+        if (typeof val === "string") return val;
+        return inspect(val, {
+            colors: false,
+            depth: 6, // heuristic
+        });
     }
 };
 
@@ -46,7 +73,7 @@ export async function sendRequestWithRetry<TParam, TRet>(
             );
         } catch (error) {
             if (delay === null) {
-                log.error("LSP request timed out", { method: reqType.method, param, error });
+                log.warn("LSP request timed out", { method: reqType.method, param, error });
                 throw error;
             }
 
@@ -55,7 +82,7 @@ export async function sendRequestWithRetry<TParam, TRet>(
             }
 
             if (error.code !== lc.ErrorCodes.ContentModified) {
-                log.error("LSP request failed", { method: reqType.method, param, error });
+                log.warn("LSP request failed", { method: reqType.method, param, error });
                 throw error;
             }
 
@@ -87,11 +114,15 @@ export function isRustEditor(editor: vscode.TextEditor): editor is RustEditor {
 export function isValidExecutable(path: string): boolean {
     log.debug("Checking availability of a binary at", path);
 
+    if (!fs.existsSync(path)) return false;
+
     const res = spawnSync(path, ["--version"], { encoding: 'utf8' });
 
-    log.debug(res, "--version output:", res.output);
+    const isSuccess = res.status === 0;
+    const printOutput = isSuccess ? log.debug : log.warn;
+    printOutput(path, "--version:", res);
 
-    return res.status === 0;
+    return isSuccess;
 }
 
 /** Sets ['when'](https://code.visualstudio.com/docs/getstarted/keybindings#_when-clause-contexts) clause contexts */