ruff server: Tracing system now respects log level and trace level,…

… with options to log to a file (#11747)

## Summary

Fixes #10968.
Fixes #11545.

The server's tracing system has been rewritten from the ground up. The
server now has trace level and log level settings which restrict the
tracing events and spans that get logged.

* A `logLevel` setting has been added, which lets a user set the log
level. By default, it is set to `"info"`.
* A `logFile` setting has also been added, which lets the user supply an
optional file to send tracing output (it does not have to exist as a
file yet). By default, if this is unset, tracing output will be sent to
`stderr`.
* A `$/setTrace` handler has also been added, and we also set the trace
level from the initialization options. For editors without direct
support for tracing, the environment variable `RUFF_TRACE` can override
the trace level.
* Small changes have been made to how we display tracing output. We no
longer use `tracing-tree`, and instead use
`tracing_subscriber::fmt::Layer` to format output. Thread names are now
included in traces, and I've made some adjustment to thread worker names
to be more useful.

## Test Plan

In VS Code, with `ruff.trace.server` set to its default value, no logs
from Ruff should appear.

After changing `ruff.trace.server` to either `messages` or `verbose`,
you should see log messages at `info` level or higher appear in Ruff's
output:
<img width="1005" alt="Screenshot 2024-06-10 at 10 35 04 AM"
src="https://github.com/astral-sh/ruff/assets/19577865/6050d107-9815-4bd2-96d0-e86f096a57f5">

In Helix, by default, no logs from Ruff should appear.

To set the trace level in Helix, you'll need to modify your language
configuration as follows:
```toml
[language-server.ruff]
command = "/Users/jane/astral/ruff/target/debug/ruff"
args = ["server", "--preview"]
environment = { "RUFF_TRACE" = "messages" }
```

After doing this, logs of `info` level or higher should be visible in
Helix:
<img width="1216" alt="Screenshot 2024-06-10 at 10 39 26 AM"
src="https://github.com/astral-sh/ruff/assets/19577865/8ff88692-d3f7-4fd1-941e-86fb338fcdcc">

You can use `:log-open` to quickly open the Helix log file.

In Neovim, by default, no logs from Ruff should appear.

To set the trace level in Neovim, you'll need to modify your
configuration as follows:
```lua
require('lspconfig').ruff.setup {
  cmd = {"/path/to/debug/executable", "server", "--preview"},
  cmd_env = { RUFF_TRACE = "messages" }
}
```

You should see logs appear in `:LspLog` that look like the following:
<img width="1490" alt="Screenshot 2024-06-11 at 11 24 01 AM"
src="https://github.com/astral-sh/ruff/assets/19577865/576cd5fa-03cf-477a-b879-b29a9a1200ff">

You can adjust `logLevel` and `logFile` in `settings`:
```lua
require('lspconfig').ruff.setup {
  cmd = {"/path/to/debug/executable", "server", "--preview"},
  cmd_env = { RUFF_TRACE = "messages" },
  settings = {
    logLevel = "debug",
    logFile = "your/log/file/path/log.txt"
  }
}
```

The `logLevel` and `logFile` can also be set in Helix like so:
```toml
[language-server.ruff.config.settings]
logLevel = "debug"
logFile = "your/log/file/path/log.txt"
```

Even if this log file does not exist, it should now be created and
written to after running the server:

<img width="1148" alt="Screenshot 2024-06-10 at 10 43 44 AM"
src="https://github.com/astral-sh/ruff/assets/19577865/ab533cf7-d5ac-4178-97f1-e56da17450dd">

crates/ruff/Cargo.toml

@@ -53,8 +53,6 @@ tempfile = { workspace = true }
 thiserror = { workspace = true }
 toml = { workspace = true }
 tracing = { workspace = true, features = ["log"] }
-tracing-subscriber = { workspace = true, features = ["registry"] }
-tracing-tree = { workspace = true }
 walkdir = { workspace = true }
 wild = { workspace = true }
 

crates/ruff/src/commands/server.rs

@@ -2,78 +2,15 @@ use std::num::NonZeroUsize;
 
 use crate::ExitStatus;
 use anyhow::Result;
-use ruff_linter::logging::LogLevel;
 use ruff_server::Server;
-use tracing::{level_filters::LevelFilter, metadata::Level, subscriber::Interest, Metadata};
-use tracing_subscriber::{
-    layer::{Context, Filter, SubscriberExt},
-    Layer, Registry,
-};
-use tracing_tree::time::Uptime;
 
-pub(crate) fn run_server(
-    preview: bool,
-    worker_threads: NonZeroUsize,
-    log_level: LogLevel,
-) -> Result<ExitStatus> {
+pub(crate) fn run_server(preview: bool, worker_threads: NonZeroUsize) -> Result<ExitStatus> {
     if !preview {
         tracing::error!("--preview needs to be provided as a command line argument while the server is still unstable.\nFor example: `ruff server --preview`");
         return Ok(ExitStatus::Error);
     }
-    let trace_level = if log_level == LogLevel::Verbose {
-        Level::TRACE
-    } else {
-        Level::DEBUG
-    };
-
-    let subscriber = Registry::default().with(
-        tracing_tree::HierarchicalLayer::default()
-            .with_indent_lines(true)
-            .with_indent_amount(2)
-            .with_bracketed_fields(true)
-            .with_targets(true)
-            .with_writer(|| Box::new(std::io::stderr()))
-            .with_timer(Uptime::default())
-            .with_filter(LoggingFilter { trace_level }),
-    );
-
-    tracing::subscriber::set_global_default(subscriber)?;
 
     let server = Server::new(worker_threads)?;
 
     server.run().map(|()| ExitStatus::Success)
 }
-
-struct LoggingFilter {
-    trace_level: Level,
-}
-
-impl LoggingFilter {
-    fn is_enabled(&self, meta: &Metadata<'_>) -> bool {
-        let filter = if meta.target().starts_with("ruff") {
-            self.trace_level
-        } else {
-            Level::INFO
-        };
-
-        meta.level() <= &filter
-    }
-}
-
-impl<S> Filter<S> for LoggingFilter {
-    fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool {
-        self.is_enabled(meta)
-    }
-
-    fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest {
-        if self.is_enabled(meta) {
-            Interest::always()
-        } else {
-            Interest::never()
-        }
-    }
-
-    fn max_level_hint(&self) -> Option<LevelFilter> {
-        Some(LevelFilter::from_level(self.trace_level))
-    }
-}

crates/ruff/src/lib.rs

@@ -201,7 +201,7 @@ pub fn run(
         }
         Command::Check(args) => check(args, global_options),
         Command::Format(args) => format(args, global_options),
-        Command::Server(args) => server(args, global_options.log_level()),
+        Command::Server(args) => server(args),
     }
 }
 
@@ -215,7 +215,7 @@ fn format(args: FormatCommand, global_options: GlobalConfigArgs) -> Result<ExitS
     }
 }
 
-fn server(args: ServerCommand, log_level: LogLevel) -> Result<ExitStatus> {
+fn server(args: ServerCommand) -> Result<ExitStatus> {
     let ServerCommand { preview } = args;
 
     let four = NonZeroUsize::new(4).unwrap();
@@ -224,7 +224,7 @@ fn server(args: ServerCommand, log_level: LogLevel) -> Result<ExitStatus> {
     let worker_threads = std::thread::available_parallelism()
         .unwrap_or(four)
         .max(four);
-    commands::server::run_server(preview, worker_threads, log_level)
+    commands::server::run_server(preview, worker_threads)
 }
 
 pub fn check(args: CheckCommand, global_options: GlobalConfigArgs) -> Result<ExitStatus> {

crates/ruff_server/Cargo.toml

@@ -38,6 +38,7 @@ serde = { workspace = true }
 serde_json = { workspace = true }
 shellexpand = { workspace = true }
 tracing = { workspace = true }
+tracing-subscriber = { workspace = true }
 walkdir = { workspace = true }
 
 [dev-dependencies]

crates/ruff_server/src/lib.rs

@@ -4,14 +4,16 @@ pub use edit::{PositionEncoding, TextDocument};
 use lsp_types::CodeActionKind;
 pub use server::Server;
 
+#[macro_use]
+mod message;
+
 mod edit;
 mod fix;
 mod format;
 mod lint;
-#[macro_use]
-mod message;
 mod server;
 mod session;
+mod trace;
 
 pub(crate) const SERVER_NAME: &str = "ruff";
 pub(crate) const DIAGNOSTIC_NAME: &str = "Ruff";

crates/ruff_server/src/message.rs

@@ -33,6 +33,12 @@ pub(crate) fn init_messenger(client_sender: ClientSender) {
 
         let backtrace = std::backtrace::Backtrace::force_capture();
         tracing::error!("{panic_info}\n{backtrace}");
+        #[allow(clippy::print_stderr)]
+        {
+            // we also need to print to stderr directly in case tracing hasn't
+            // been initialized.
+            eprintln!("{panic_info}\n{backtrace}");
+        }
     }));
 }
 

crates/ruff_server/src/server.rs

@@ -63,6 +63,10 @@ impl Server {
             crate::version(),
         )?;
 
+        if let Some(trace) = init_params.trace {
+            crate::trace::set_trace_value(trace);
+        }
+
         crate::message::init_messenger(connection.make_sender());
 
         let AllSettings {
@@ -74,6 +78,15 @@ impl Server {
                 .unwrap_or_else(|| serde_json::Value::Object(serde_json::Map::default())),
         );
 
+        crate::trace::init_tracing(
+            connection.make_sender(),
+            global_settings
+                .tracing
+                .log_level
+                .unwrap_or(crate::trace::LogLevel::Info),
+            global_settings.tracing.log_file.as_deref(),
+        );
+
         let mut workspace_for_url = |url: lsp_types::Url| {
             let Some(workspace_settings) = workspace_settings.as_mut() else {
                 return (url, ClientSettings::default());

crates/ruff_server/src/server/api.rs

@@ -93,6 +93,9 @@ pub(super) fn notification<'a>(notif: server::Notification) -> Task<'a> {
         notification::DidCloseNotebook::METHOD => {
             local_notification_task::<notification::DidCloseNotebook>(notif)
         }
+        notification::SetTrace::METHOD => {
+            local_notification_task::<notification::SetTrace>(notif)
+        }
         method => {
             tracing::warn!("Received notification {method} which does not have a handler.");
             return Task::nothing();

crates/ruff_server/src/server/api/notifications.rs

@@ -8,6 +8,7 @@ mod did_close;
 mod did_close_notebook;
 mod did_open;
 mod did_open_notebook;
+mod set_trace;
 
 use super::traits::{NotificationHandler, SyncNotificationHandler};
 pub(super) use cancel::Cancel;
@@ -20,3 +21,4 @@ pub(super) use did_close::DidClose;
 pub(super) use did_close_notebook::DidCloseNotebook;
 pub(super) use did_open::DidOpen;
 pub(super) use did_open_notebook::DidOpenNotebook;
+pub(super) use set_trace::SetTrace;

crates/ruff_server/src/server/api/notifications/set_trace.rs

@@ -0,0 +1,23 @@
+use crate::server::client::{Notifier, Requester};
+use crate::server::Result;
+use crate::session::Session;
+use lsp_types as types;
+use lsp_types::notification as notif;
+
+pub(crate) struct SetTrace;
+
+impl super::NotificationHandler for SetTrace {
+    type NotificationType = notif::SetTrace;
+}
+
+impl super::SyncNotificationHandler for SetTrace {
+    fn run(
+        _session: &mut Session,
+        _notifier: Notifier,
+        _requester: &mut Requester,
+        params: types::SetTraceParams,
+    ) -> Result<()> {
+        crate::trace::set_trace_value(params.value);
+        Ok(())
+    }
+}

crates/ruff_server/src/server/schedule/thread/pool.rs

@@ -56,10 +56,10 @@ impl Pool {
         let extant_tasks = Arc::new(AtomicUsize::new(0));
 
         let mut handles = Vec::with_capacity(threads);
-        for _ in 0..threads {
+        for i in 0..threads {
             let handle = Builder::new(INITIAL_PRIORITY)
                 .stack_size(STACK_SIZE)
-                .name("Worker".into())
+                .name(format!("ruff:worker:{i}"))
                 .spawn({
                     let extant_tasks = Arc::clone(&extant_tasks);
                     let job_receiver: Receiver<Job> = job_receiver.clone();

crates/ruff_server/src/session/settings.rs

@@ -70,6 +70,20 @@ pub(crate) struct ClientSettings {
     exclude: Option<Vec<String>>,
     line_length: Option<LineLength>,
     configuration_preference: Option<ConfigurationPreference>,
+    // These settings are only needed for tracing, and are only read from the global configuration.
+    // These will not be in the resolved settings.
+    #[serde(flatten)]
+    pub(crate) tracing: TracingSettings,
+}
+
+/// Settings needed to initialize tracing. These will only be
+/// read from the global configuration.
+#[derive(Debug, Deserialize, Default)]
+#[cfg_attr(test, derive(PartialEq, Eq))]
+#[serde(rename_all = "camelCase")]
+pub(crate) struct TracingSettings {
+    pub(crate) log_level: Option<crate::trace::LogLevel>,
+    pub(crate) log_file: Option<PathBuf>,
 }
 
 /// This is a direct representation of the workspace settings schema,
@@ -424,6 +438,10 @@ mod tests {
                 exclude: None,
                 line_length: None,
                 configuration_preference: None,
+                tracing: TracingSettings {
+                    log_level: None,
+                    log_file: None,
+                },
             },
             workspace_settings: [
                 WorkspaceSettings {
@@ -472,6 +490,10 @@ mod tests {
                         exclude: None,
                         line_length: None,
                         configuration_preference: None,
+                        tracing: TracingSettings {
+                            log_level: None,
+                            log_file: None,
+                        },
                     },
                     workspace: Url {
                         scheme: "file",
@@ -533,6 +555,10 @@ mod tests {
                         exclude: None,
                         line_length: None,
                         configuration_preference: None,
+                        tracing: TracingSettings {
+                            log_level: None,
+                            log_file: None,
+                        },
                     },
                     workspace: Url {
                         scheme: "file",
@@ -588,7 +614,7 @@ mod tests {
                     exclude: None,
                     line_length: None,
                     configuration_preference: ConfigurationPreference::default(),
-                }
+                },
             }
         );
         let path =
@@ -619,7 +645,7 @@ mod tests {
                     exclude: None,
                     line_length: None,
                     configuration_preference: ConfigurationPreference::EditorFirst,
-                }
+                },
             }
         );
     }
@@ -673,6 +699,12 @@ mod tests {
                     ),
                 ),
                 configuration_preference: None,
+                tracing: TracingSettings {
+                    log_level: Some(
+                        Warn,
+                    ),
+                    log_file: None,
+                },
             },
         }
         "###);
@@ -703,7 +735,7 @@ mod tests {
                     exclude: Some(vec!["third_party".into()]),
                     line_length: Some(LineLength::try_from(80).unwrap()),
                     configuration_preference: ConfigurationPreference::EditorFirst,
-                }
+                },
             }
         );
     }