Improve logging system using separate output channels (#659)

## Summary

Related: astral-sh/ruff#15232

The basic idea is that there will be two channels where the logs will
go:
1. Ruff: Here, all the logs for the extension will go
2. Ruff Language Server: Here, all the server log messages will go and
are captured from the stderr. It will also contain the trace
communications between the client and the server when it's enabled.
3. Ruff Language Server Trace: Here, all the communication messages
between the client and the server will go. **This channel is created
lazily when the value of `ruff.trace.server` is changed to "verbose" or
"messages" for the first time.**

(2) is controlled by the `ruff.logLevel` configuration which defaults to
`info`.

(3) is controlled by the `ruff.trace.server` configuration which
defaults to `off` and can be changed to `messages` and `verbose`. The
difference between them is that the former will only log the method name
for both the request and response while the latter will also log the
request parameters and the response result.

### Red Knot

The end goal is to merge the tracing system with Red knot. Currently,
Red knot's tracing system utilizes the `-v`, `-vv` and `-vvv` flags from
the command-line and `RED_KNOT_LOG` environment variable for
configuration. For the red knot server specifically, we will need to
provide an additional configuration parameter like
`ruff.server.extraEnv` which allows user to fine tune the logging using
the mentioned environment variable. The `ruff.logLevel` will by default
pass `RED_KNOT_LOG=<logLevel>` to allow for easy configuration.

### Why not `window/logMessage` ?

The `window/logMessage` request can be used by the server to notify the
client to log a message at a certain log level. There are a few
disadvantages of using this as oppose to just using stderr:
* It needs to go through the RPC which requires serializing and
de-serializing the messages
* The output format depends on how client handles the message
* The trace channel will get populated with "Received notification
'window/logMessage'" lines
* There's no 'debug' and 'trace' message type the LSP protocol although
the next version is going to include debug type

Additionally, putting the message onto stderr also allows us to use a
custom formatter which is what is being done in red knot and would prove
to be beneficial when merging the tracing setup.

<details><summary>For posterity, here's the patch to use
<code>window/logMessage</code>:</summary>
<p>

```diff
diff --git a/crates/ruff_server/src/trace.rs b/crates/ruff_server/src/trace.rs
index 7b367c780..ceedeff21 100644
--- a/crates/ruff_server/src/trace.rs
+++ b/crates/ruff_server/src/trace.rs
@@ -15,6 +15,9 @@
 //! Tracing will write to `stderr` by default, which should appear in the logs for most LSP clients.
 //! A `logFile` path can also be specified in the settings, and output will be directed there instead.
 use core::str;
+use lsp_server::{Message, Notification};
+use lsp_types::notification::{LogMessage, Notification as _};
+use lsp_types::{LogMessageParams, MessageType};
 use serde::Deserialize;
 use std::{
     path::PathBuf,
@@ -22,6 +25,7 @@ use std::{
     sync::{Arc, OnceLock},
 };
 use tracing::level_filters::LevelFilter;
+use tracing_subscriber::fmt::MakeWriter;
 use tracing_subscriber::{
     fmt::{time::Uptime, writer::BoxMakeWriter},
     layer::SubscriberExt,
@@ -73,7 +77,7 @@ pub(crate) fn init_tracing(
 
     let logger = match log_file {
         Some(file) => BoxMakeWriter::new(Arc::new(file)),
-        None => BoxMakeWriter::new(std::io::stderr),
+        None => BoxMakeWriter::new(LogMessageMakeWriter),
     };
     let subscriber = tracing_subscriber::Registry::default().with(
         tracing_subscriber::fmt::layer()
@@ -135,3 +139,61 @@ impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
         Some(LevelFilter::from_level(self.filter.trace_level()))
     }
 }
+
+struct LogMessageMakeWriter;
+
+impl<'a> MakeWriter<'a> for LogMessageMakeWriter {
+    type Writer = LogMessageWriter;
+
+    fn make_writer(&'a self) -> Self::Writer {
+        LogMessageWriter {
+            level: tracing::Level::INFO,
+        }
+    }
+
+    fn make_writer_for(&'a self, meta: &tracing::Metadata<'_>) -> Self::Writer {
+        LogMessageWriter {
+            level: *meta.level(),
+        }
+    }
+}
+
+struct LogMessageWriter {
+    level: tracing::Level,
+}
+
+impl LogMessageWriter {
+    const fn message_type(&self) -> MessageType {
+        match self.level {
+            tracing::Level::ERROR => MessageType::ERROR,
+            tracing::Level::WARN => MessageType::WARNING,
+            tracing::Level::INFO => MessageType::INFO,
+            tracing::Level::DEBUG => MessageType::LOG,
+            tracing::Level::TRACE => MessageType::LOG,
+        }
+    }
+}
+
+impl std::io::Write for LogMessageWriter {
+    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
+        let message = str::from_utf8(buf)
+            .map_err(|e| std::io::Error::new(std::io::ErrorKind::InvalidData, e))?
+            .to_owned();
+        LOGGING_SENDER
+            .get()
+            .expect("logging sender should be initialized at this point")
+            .send(Message::Notification(Notification {
+                method: LogMessage::METHOD.to_owned(),
+                params: serde_json::to_value(LogMessageParams {
+                    typ: self.message_type(),
+                    message,
+                })?,
+            }))
+            .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, e))?;
+        Ok(buf.len())
+    }
+
+    fn flush(&mut self) -> std::io::Result<()> {
+        Ok(())
+    }
+}
```

</p>
</details> 

## Test Plan

Using the following **VS Code** settings:

```json
{
  "ruff.nativeServer": "on",
  "ruff.path": ["/Users/dhruv/work/astral/ruff/target/debug/ruff"],
  "ruff.trace.server": "verbose",
  "ruff.logLevel": "debug"
}
```

The following video showcases the three channels in VS Code:


https://github.com/user-attachments/assets/53396774-9dfb-4c33-9145-67eaf2395936

Using the following **Zed** settings:

```json
{
  "lsp": {
    "ruff": {
      "binary": {
        "path": "/Users/dhruv/work/astral/ruff/target/debug/ruff",
        "arguments": [
          "server"
        ]
      },
      "initialization_options": {
        "settings": {
          "logLevel": "debug"
        }
      }
    }
  }
}
```

The following video showcases that the stderr messages are captured in
the "Server Logs" window and the RPC window provides the raw request and
response messages:


https://github.com/user-attachments/assets/ee36eb4a-133f-46d3-abb9-366c48793f32

For **Neovim**, there's an open issue
(neovim/neovim#16807) to send stderr messages
to a separate file but currently it gets logged as "ERROR" in the main
LSP log file. There doesn't seem to be any way to hook into the stderr
of the Neovim LSP client for us to provide a solution for Ruff users.

.github/workflows/ci.yaml

@@ -12,7 +12,7 @@ jobs:
       fail-fast: false
       matrix:
         python-version: ["3.7", "3.8", "3.9", "3.10", "3.11", "3.12"]
-    runs-on: ubuntu-latest
+    runs-on: ubuntu-22.04
     env:
       UV_SYSTEM_PYTHON: 1
     steps:

README.md

@@ -383,21 +383,48 @@ itself is compatible with Python 3.7 to 3.13.
 ## Troubleshooting
 
 If you encounter any issues with the extension or the language server, please refer to the
-logs in the output panel in VS Code. You can access the logs by running the `Ruff: Show logs`
-command.
+logs in the corresponding output channel in VS Code. The extension logs are in the "Ruff"
+output channel and the language server logs are in the "Ruff Language Server" output channel.
 
-By default, the output panel will only contain logs from the extension. To enable logs from the
-language server, set the `trace.server` setting to `messages` in your `settings.json`:
+To open the output panel, use the `Output: Show Output Channels` command in the command palette
+(`Ctrl+Shift+P` or `Cmd+Shift+P`), then select "Ruff" or "Ruff Language Server". Alternatively,
+you can use the `Ruff: Show client logs` and `Ruff: Show server logs` command to open the "Ruff"
+and "Ruff Language Server" output channel respectively.
+
+The default log level for the extension is `info` which can be changed from the output panel using
+the settings icon in the top right corner of the panel.
+
+The default log level for the language server is `info` which can be changed using the `ruff.logLevel`
+setting in your `settings.json`:
+
+```json
+{
+  "ruff.logLevel": "info"
+}
+```
+
+The language server logs can be directed to a file by setting the `ruff.logFile` setting in
+your `settings.json`:
+
+```json
+{
+  "ruff.logFile": "/path/to/ruff.log"
+}
+```
+
+To capture the LSP messages between the editor and the server, set the `ruff.trace.server`
+setting to either `messages` or `verbose` in your `settings.json`:
 
 ```json
 {
   "ruff.trace.server": "messages"
 }
 ```
 
-The trace value can also be set to `verbose` for more detailed logs. If you're using the Rust-based
-language server, you can use the `ruff.logLevel` setting to control the log level of the server and
-`ruff.logFile` to write logs to a file instead of the output panel.
+This will be visible in the "Ruff Language Server Trace" output channel. The difference between
+`messages` and `verbose` is that `messages` only logs the method name for both the request
+and response, while `verbose` also logs the request parameters sent by the client and the
+response result sent by the server.
 
 The extension also displays certain information in the status bar. This can be pinned to the status
 bar as a permanent item.

package.json

@@ -1,7 +1,7 @@
 {
   "name": "ruff",
   "displayName": "Ruff",
-  "description": "A Visual Studio Code extension with support for the Ruff linter.",
+  "description": "A Visual Studio Code extension with support for the Ruff linter and formatter.",
   "version": "2024.56.0",
   "serverInfo": {
     "name": "Ruff",
@@ -25,6 +25,7 @@
   "keywords": [
     "python",
     "linting",
+    "formatting",
     "ruff"
   ],
   "engines": {
@@ -431,9 +432,14 @@
         "command": "ruff.restart"
       },
       {
-        "title": "Show logs",
+        "title": "Show client logs",
         "category": "Ruff",
         "command": "ruff.showLogs"
+      },
+      {
+        "title": "Show server logs",
+        "category": "Ruff",
+        "command": "ruff.showServerLogs"
       }
     ]
   },

src/common/logger.ts

@@ -0,0 +1,113 @@
+import * as util from "util";
+import * as vscode from "vscode";
+
+class ExtensionLogger {
+  /**
+   * The output channel used to log messages for the extension.
+   */
+  readonly channel = vscode.window.createOutputChannel("Ruff", { log: true });
+
+  /**
+   * Whether the extension is running in a CI environment.
+   */
+  private readonly isCI = process.env.CI === "true";
+
+  /**
+   * Logs messages to the console if the extension is running in a CI environment.
+   */
+  private logForCI(...messages: unknown[]): void {
+    if (this.isCI) {
+      console.log(...messages);
+    }
+  }
+
+  error(...messages: unknown[]): void {
+    this.logForCI(...messages);
+    this.channel.error(util.format(...messages));
+  }
+
+  warn(...messages: unknown[]): void {
+    this.logForCI(...messages);
+    this.channel.warn(util.format(...messages));
+  }
+
+  info(...messages: unknown[]): void {
+    this.logForCI(...messages);
+    this.channel.info(util.format(...messages));
+  }
+
+  debug(...messages: unknown[]): void {
+    this.logForCI(...messages);
+    this.channel.debug(util.format(...messages));
+  }
+
+  trace(...messages: unknown[]): void {
+    this.logForCI(...messages);
+    this.channel.trace(util.format(...messages));
+  }
+}
+
+/**
+ * The logger used by the extension.
+ *
+ * This will log the messages to the "Ruff" output channel, optionally logging them
+ * to the console if the extension is running in a CI environment (e.g., GitHub Actions).
+ *
+ * This should mainly be used for logging messages that are intended for the user.
+ */
+export const logger = new ExtensionLogger();
+
+/**
+ * A VS Code output channel that is lazily created when it is first accessed.
+ *
+ * This is useful when the messages are only logged when the extension is configured
+ * to log them, as it avoids creating an empty output channel.
+ *
+ * This is currently being used to create the trace output channel for the language server
+ * as it is only created when the user enables trace logging.
+ */
+export class LazyOutputChannel implements vscode.OutputChannel {
+  name: string;
+  _channel: vscode.OutputChannel | undefined;
+
+  constructor(name: string) {
+    this.name = name;
+  }
+
+  get channel(): vscode.OutputChannel {
+    if (!this._channel) {
+      this._channel = vscode.window.createOutputChannel(this.name);
+    }
+    return this._channel;
+  }
+
+  append(value: string): void {
+    this.channel.append(value);
+  }
+
+  appendLine(value: string): void {
+    this.channel.appendLine(value);
+  }
+
+  replace(value: string): void {
+    this.channel.replace(value);
+  }
+
+  clear(): void {
+    this._channel?.clear();
+  }
+
+  show(preserveFocus?: boolean): void;
+  show(column?: vscode.ViewColumn, preserveFocus?: boolean): void;
+  show(column?: any, preserveFocus?: any): void {
+    this.channel.show(column, preserveFocus);
+  }
+
+  hide(): void {
+    this._channel?.hide();
+  }
+
+  dispose(): void {
+    this._channel?.dispose();
+  }
+}

src/common/python.ts

@@ -1,5 +1,5 @@
 import { commands, Disposable, Event, EventEmitter, Uri } from "vscode";
-import { traceError, traceLog } from "./log/logging";
+import { logger } from "./logger";
 import { PythonExtension, ResolvedEnvironment } from "@vscode/python-extension";
 
 export interface IInterpreterDetails {
@@ -31,11 +31,11 @@ export async function initializePython(disposables: Disposable[]): Promise<void>
         }),
       );
 
-      traceLog("Waiting for interpreter from python extension.");
+      logger.info("Waiting for interpreter from python extension.");
       onDidChangePythonInterpreterEvent.fire(await getInterpreterDetails());
     }
   } catch (error) {
-    traceError("Error initializing python: ", error);
+    logger.error("Error initializing python: ", error);
   }
 }
 
@@ -72,8 +72,8 @@ export function checkVersion(resolved: ResolvedEnvironment): boolean {
   if (version?.major === 3 && version?.minor >= 7) {
     return true;
   }
-  traceError(`Python version ${version?.major}.${version?.minor} is not supported.`);
-  traceError(`Selected python path: ${resolved.executable.uri?.fsPath}`);
-  traceError("Supported versions are 3.7 and above.");
+  logger.error(`Python version ${version?.major}.${version?.minor} is not supported.`);
+  logger.error(`Selected python path: ${resolved.executable.uri?.fsPath}`);
+  logger.error("Supported versions are 3.7 and above.");
   return false;
 }