language-servers/ruff
1
0
Fork 0
mirror of https://github.com/astral-sh/ruff.git synced 2025-09-30 13:51:37 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 3

Improve logging system using logLevel, avoid trace value (#15232)

Browse source 
## Summary

Refer to the VS Code PR
(https://github.com/astral-sh/ruff-vscode/pull/659) for details on the
change.

This PR changes the following:

1. Add tracing span for both request (request id and method name) and
notification (method name) handler
2. Remove the `RUFF_TRACE` environment variable. This was being used to
turn on / off logging for the server
3. Similarly, remove reading the `trace` value from the initialization
options
4. Remove handling the `$/setTrace` notification
5. Remove the specialized `TraceLogWriter` used for Zed and VS Code
(https://github.com/astral-sh/ruff/pull/12564)

Regarding the (5) for the Zed editor, the reason that was implemented
was because there was no way of looking at the stderr messages in the
editor which has been changed. Now, it captures the stderr as part of
the "Server Logs".
(82492d74a8/crates/language_tools/src/lsp_log.rs (L548-L552))

### Question

Regarding (1), I think having just a simple trace level message should
be good for now as the spans are not hierarchical. This could be tackled
with #12744. The difference between the two:

<details><summary>Using <code>tracing::trace</code></summary>
<p>

```
   0.019243416s DEBUG ThreadId(08) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.026398750s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.026802125s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
   0.026930666s TRACE ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
   0.026962333s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (1)
   0.027042875s TRACE ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (2)
   0.027097500s TRACE ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (3)
   0.027107458s DEBUG ruff:worker:0 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.027123541s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   0.027514875s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   0.285689833s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (4)
  45.741101666s TRACE     ruff:main ruff_server::server::api: Received notification "textDocument/didClose"
  47.108745500s TRACE     ruff:main ruff_server::server::api: Received notification "textDocument/didOpen"
  47.109802041s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/diagnostic" (5)
  47.109926958s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/codeAction" (6)
  47.110027791s DEBUG ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  51.863679125s TRACE     ruff:main ruff_server::server::api: Received request "textDocument/hover" (7)
```

</p>
</details> 

<details><summary>Using <code>tracing::trace_span</code></summary>
<p>

Only logging the enter event:

```
   0.018638750s DEBUG ThreadId(11) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.025895791s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.026378791s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.026531208s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.026567583s TRACE ruff:main request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.026652541s TRACE ruff:main request{id=2 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.026711041s DEBUG ruff:worker:2 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   0.026729166s DEBUG ruff:worker:1 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.027023083s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   5.197554750s TRACE     ruff:main notification{method="textDocument/didClose"}: ruff_server::server::api: enter
   6.534458000s TRACE     ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   6.535027958s TRACE     ruff:main request{id=3 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   6.535271166s DEBUG ruff:worker:3 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/organize_imports.py
   6.544240583s TRACE     ruff:main request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.049692458s TRACE     ruff:main request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.508142541s TRACE     ruff:main request{id=6 method="textDocument/hover"}: ruff_server::server::api: enter
   7.872421958s TRACE     ruff:main request{id=7 method="textDocument/hover"}: ruff_server::server::api: enter
   8.024498583s TRACE     ruff:main request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter
  13.895063666s TRACE     ruff:main request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter
  14.774706083s TRACE     ruff:main request{id=10 method="textDocument/hover"}: ruff_server::server::api: enter
  16.058918958s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
  16.060562208s TRACE     ruff:main request{id=11 method="textDocument/diagnostic"}: ruff_server::server::api: enter
  16.061109083s DEBUG ruff:worker:8 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  21.561742875s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
  21.563573791s TRACE     ruff:main request{id=12 method="textDocument/diagnostic"}: ruff_server::server::api: enter
  21.564206750s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  21.826691375s TRACE     ruff:main request{id=13 method="textDocument/codeAction"}: ruff_server::server::api: enter
  22.091080125s TRACE     ruff:main request{id=14 method="textDocument/codeAction"}: ruff_server::server::api: enter
```

</p>
</details> 


**Todo**

- [x] Update documentation (I'll be adding a troubleshooting section
under "Editors" as a follow-up which is for all editors)
- [x] Check for backwards compatibility. I don't think this should break
backwards compatibility as it's mainly targeted towards improving the
debugging experience.

~**Before I go on to updating the documentation, I'd appreciate initial
review on the chosen approach.**~

resolves: #14959 

## Test Plan

Refer to the test plan in
https://github.com/astral-sh/ruff-vscode/pull/659.

Example logs at `debug` level:

```
   0.010770083s DEBUG ThreadId(15) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.018101916s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.018559916s DEBUG ruff:worker:4 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.018992375s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
  23.408802375s DEBUG ruff:worker:11 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
  24.329127416s DEBUG  ruff:worker:6 ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
```

Example logs at `trace` level:

```
   0.010296375s DEBUG ThreadId(13) ruff_server::session::index::ruff_settings: Ignored path via `exclude`: /Users/dhruv/playground/ruff/.vscode
   0.017422583s  INFO main ruff_server::session::index: Registering workspace: /Users/dhruv/playground/ruff
   0.018034458s TRACE ruff:main notification{method="textDocument/didOpen"}: ruff_server::server::api: enter
   0.018199708s TRACE ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   0.018251167s DEBUG ruff:worker:0 request{id=1 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   0.018528708s  INFO     ruff:main ruff_server::server: Configuration file watcher successfully registered
   1.611798417s TRACE ruff:worker:1 request{id=2 method="textDocument/codeAction"}: ruff_server::server::api: enter
   1.861757542s TRACE ruff:worker:4 request{id=3 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.027361792s TRACE ruff:worker:2 request{id=4 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.851361500s TRACE ruff:worker:5 request{id=5 method="textDocument/codeAction"}: ruff_server::server::api: enter
   7.901690875s TRACE     ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
   7.903063167s TRACE ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   7.903183500s DEBUG ruff:worker:10 request{id=6 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   8.702385292s TRACE      ruff:main notification{method="textDocument/didChange"}: ruff_server::server::api: enter
   8.704106625s TRACE  ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::server::api: enter
   8.704304875s DEBUG  ruff:worker:3 request{id=7 method="textDocument/diagnostic"}: ruff_server::resolve: Included path via `include`: /Users/dhruv/playground/ruff/lsp/play.py
   8.966853458s TRACE  ruff:worker:9 request{id=8 method="textDocument/codeAction"}: ruff_server::server::api: enter
   9.229622792s TRACE  ruff:worker:6 request{id=9 method="textDocument/codeAction"}: ruff_server::server::api: enter
  10.513111583s TRACE  ruff:worker:7 request{id=10 method="textDocument/codeAction"}: ruff_server::server::api: enter
```
This commit is contained in:
Dhruv Manilawala 2025-01-08 18:18:00 +05:30 • committed by GitHub
parent 9a27b37a91
commit 1447553bc2
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
17 changed files with 257 additions and 540 deletions
Download patch file Download diff file Expand all files Collapse all files

2
crates/red_knot_server/src/lib.rs
View file

@ -11,10 +11,10 @@ use crate::server::Server;
mod message;
mod edit;
mod logging;
mod server;
mod session;
mod system;
mod trace;
pub(crate) const SERVER_NAME: &str = "red-knot";
pub(crate) const DIAGNOSTIC_NAME: &str = "Red Knot";

114
crates/red_knot_server/src/logging.rs Normal file
View file

@ -0,0 +1,114 @@
//! The logging system for `red_knot server`.
//!
//! Log messages are controlled by the `logLevel` setting which defaults to `"info"`. Log messages
//! are written 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 serde::Deserialize;
use std::{path::PathBuf, str::FromStr, sync::Arc};
use tracing::level_filters::LevelFilter;
use tracing_subscriber::{
fmt::{time::Uptime, writer::BoxMakeWriter},
layer::SubscriberExt,
Layer,
};
pub(crate) fn init_logging(log_level: LogLevel, log_file: Option<&std::path::Path>) {
let log_file = log_file
.map(|path| {
// this expands `logFile` so that tildes and environment variables
// are replaced with their values, if possible.
if let Some(expanded) = shellexpand::full(&path.to_string_lossy())
.ok()
.and_then(|path| PathBuf::from_str(&path).ok())
{
expanded
} else {
path.to_path_buf()
}
})
.and_then(|path| {
std::fs::OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.map_err(|err| {
#[allow(clippy::print_stderr)]
{
eprintln!(
"Failed to open file at {} for logging: {err}",
path.display()
);
}
})
.ok()
});
let logger = match log_file {
Some(file) => BoxMakeWriter::new(Arc::new(file)),
None => BoxMakeWriter::new(std::io::stderr),
};
let subscriber = tracing_subscriber::Registry::default().with(
tracing_subscriber::fmt::layer()
.with_timer(Uptime::default())
.with_thread_names(true)
.with_ansi(false)
.with_writer(logger)
.with_filter(LogLevelFilter { filter: log_level }),
);
tracing::subscriber::set_global_default(subscriber)
.expect("should be able to set global default subscriber");
}
/// The log level for the server as provided by the client during initialization.
///
/// The default log level is `info`.
#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)]
#[serde(rename_all = "lowercase")]
pub(crate) enum LogLevel {
Error,
Warn,
#[default]
Info,
Debug,
Trace,
}
impl LogLevel {
fn trace_level(self) -> tracing::Level {
match self {
Self::Error => tracing::Level::ERROR,
Self::Warn => tracing::Level::WARN,
Self::Info => tracing::Level::INFO,
Self::Debug => tracing::Level::DEBUG,
Self::Trace => tracing::Level::TRACE,
}
}
}
/// Filters out traces which have a log level lower than the `logLevel` set by the client.
struct LogLevelFilter {
filter: LogLevel,
}
impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
fn enabled(
&self,
meta: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
let filter = if meta.target().starts_with("red_knot") {
self.filter.trace_level()
} else {
tracing::Level::INFO
};
meta.level() <= &filter
}
fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
Some(LevelFilter::from_level(self.filter.trace_level()))
}
}

13
crates/red_knot_server/src/server.rs
View file

@ -51,10 +51,6 @@ 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 {
@ -66,14 +62,9 @@ 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),
crate::logging::init_logging(
global_settings.tracing.log_level.unwrap_or_default(),
global_settings.tracing.log_file.as_deref(),
init_params.client_info.as_ref(),
);
let mut workspace_for_url = |url: Url| {

3
crates/red_knot_server/src/server/api.rs
View file

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

2
crates/red_knot_server/src/server/api/notifications.rs
View file

@ -3,11 +3,9 @@ mod did_close;
mod did_close_notebook;
mod did_open;
mod did_open_notebook;
mod set_trace;
pub(super) use did_change::DidChangeTextDocumentHandler;
pub(super) use did_close::DidCloseTextDocumentHandler;
pub(super) use did_close_notebook::DidCloseNotebookHandler;
pub(super) use did_open::DidOpenTextDocumentHandler;
pub(super) use did_open_notebook::DidOpenNotebookHandler;
pub(super) use set_trace::SetTraceHandler;

25
crates/red_knot_server/src/server/api/notifications/set_trace.rs
View file

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

2
crates/red_knot_server/src/session/settings.rs
View file

@ -24,7 +24,7 @@ pub struct ClientSettings {
#[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_level: Option<crate::logging::LogLevel>,
/// Path to the log file - tildes and environment variables are supported.
pub(crate) log_file: Option<PathBuf>,
}

221
crates/red_knot_server/src/trace.rs
View file

@ -1,221 +0,0 @@
//! The tracing system for `ruff server`.
//!
//! Traces are controlled by the `logLevel` setting, along with the
//! trace level set through the LSP. On VS Code, the trace level can
//! also be set with `ruff.trace.server`. A trace level of `messages` or
//! `verbose` will enable tracing - otherwise, no traces will be shown.
//!
//! `logLevel` can be used to configure the level of tracing that is shown.
//! By default, `logLevel` is set to `"info"`.
//!
//! The server also supports the `RUFF_TRACE` environment variable, which will
//! override the trace value provided by the LSP client. Use this if there's no good way
//! to set the trace value through your editor's configuration.
//!
//! 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::{LogTrace, Notification as _},
ClientInfo, TraceValue,
};
use serde::Deserialize;
use std::{
io::{Error as IoError, ErrorKind, Write},
path::PathBuf,
str::FromStr,
sync::{Arc, Mutex, OnceLock},
};
use tracing::level_filters::LevelFilter;
use tracing_subscriber::{
fmt::{time::Uptime, writer::BoxMakeWriter, MakeWriter},
layer::SubscriberExt,
Layer,
};
use crate::server::ClientSender;
const TRACE_ENV_KEY: &str = "RUFF_TRACE";
static LOGGING_SENDER: OnceLock<ClientSender> = OnceLock::new();
static TRACE_VALUE: Mutex<lsp_types::TraceValue> = Mutex::new(lsp_types::TraceValue::Off);
pub(crate) fn set_trace_value(trace_value: TraceValue) {
let mut global_trace_value = TRACE_VALUE
.lock()
.expect("trace value mutex should be available");
*global_trace_value = trace_value;
}
// A tracing writer that uses LSPs logTrace method.
struct TraceLogWriter;
impl Write for TraceLogWriter {
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?;
LOGGING_SENDER
.get()
.expect("logging sender should be initialized at this point")
.send(Message::Notification(Notification {
method: LogTrace::METHOD.to_owned(),
params: serde_json::json!({
"message": message
}),
}))
.map_err(|e| IoError::new(ErrorKind::Other, e))?;
Ok(buf.len())
}
fn flush(&mut self) -> std::io::Result<()> {
Ok(())
}
}
impl<'a> MakeWriter<'a> for TraceLogWriter {
type Writer = Self;
fn make_writer(&'a self) -> Self::Writer {
Self
}
}
pub(crate) fn init_tracing(
sender: ClientSender,
log_level: LogLevel,
log_file: Option<&std::path::Path>,
client: Option<&ClientInfo>,
) {
LOGGING_SENDER
.set(sender)
.expect("logging sender should only be initialized once");
let log_file = log_file
.map(|path| {
// this expands `logFile` so that tildes and environment variables
// are replaced with their values, if possible.
if let Some(expanded) = shellexpand::full(&path.to_string_lossy())
.ok()
.and_then(|path| PathBuf::from_str(&path).ok())
{
expanded
} else {
path.to_path_buf()
}
})
.and_then(|path| {
std::fs::OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.map_err(|err| {
#[allow(clippy::print_stderr)]
{
eprintln!(
"Failed to open file at {} for logging: {err}",
path.display()
);
}
})
.ok()
});
let logger = match log_file {
Some(file) => BoxMakeWriter::new(Arc::new(file)),
None => {
if client.is_some_and(|client| {
client.name.starts_with("Zed") || client.name.starts_with("Visual Studio Code")
}) {
BoxMakeWriter::new(TraceLogWriter)
} else {
BoxMakeWriter::new(std::io::stderr)
}
}
};
let subscriber = tracing_subscriber::Registry::default().with(
tracing_subscriber::fmt::layer()
.with_timer(Uptime::default())
.with_thread_names(true)
.with_ansi(false)
.with_writer(logger)
.with_filter(TraceLevelFilter)
.with_filter(LogLevelFilter { filter: log_level }),
);
tracing::subscriber::set_global_default(subscriber)
.expect("should be able to set global default subscriber");
}
#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)]
#[serde(rename_all = "lowercase")]
pub(crate) enum LogLevel {
#[default]
Error,
Warn,
Info,
Debug,
Trace,
}
impl LogLevel {
fn trace_level(self) -> tracing::Level {
match self {
Self::Error => tracing::Level::ERROR,
Self::Warn => tracing::Level::WARN,
Self::Info => tracing::Level::INFO,
Self::Debug => tracing::Level::DEBUG,
Self::Trace => tracing::Level::TRACE,
}
}
}
/// Filters out traces which have a log level lower than the `logLevel` set by the client.
struct LogLevelFilter {
filter: LogLevel,
}
/// Filters out traces if the trace value set by the client is `off`.
struct TraceLevelFilter;
impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
fn enabled(
&self,
meta: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
let filter = if meta.target().starts_with("ruff") {
self.filter.trace_level()
} else {
tracing::Level::INFO
};
meta.level() <= &filter
}
fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
Some(LevelFilter::from_level(self.filter.trace_level()))
}
}
impl<S> tracing_subscriber::layer::Filter<S> for TraceLevelFilter {
fn enabled(
&self,
_: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
trace_value() != lsp_types::TraceValue::Off
}
}
#[inline]
fn trace_value() -> lsp_types::TraceValue {
std::env::var(TRACE_ENV_KEY)
.ok()
.and_then(|trace| serde_json::from_value(serde_json::Value::String(trace)).ok())
.unwrap_or_else(|| {
*TRACE_VALUE
.lock()
.expect("trace value mutex should be available")
})
}

2
crates/ruff_server/src/lib.rs
View file

@ -12,10 +12,10 @@ mod edit;
mod fix;
mod format;
mod lint;
mod logging;
mod resolve;
mod server;
mod session;
mod trace;
pub(crate) const SERVER_NAME: &str = "ruff";
pub(crate) const DIAGNOSTIC_NAME: &str = "Ruff";

115
crates/ruff_server/src/logging.rs Normal file
View file

@ -0,0 +1,115 @@
//! The logging system for `ruff server`.
//!
//! Log messages are controlled by the `logLevel` setting which defaults to `"info"`. Log messages
//! are written 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 serde::Deserialize;
use std::{path::PathBuf, str::FromStr, sync::Arc};
use tracing::level_filters::LevelFilter;
use tracing_subscriber::{
fmt::{format::FmtSpan, time::Uptime, writer::BoxMakeWriter},
layer::SubscriberExt,
Layer,
};
pub(crate) fn init_logging(log_level: LogLevel, log_file: Option<&std::path::Path>) {
let log_file = log_file
.map(|path| {
// this expands `logFile` so that tildes and environment variables
// are replaced with their values, if possible.
if let Some(expanded) = shellexpand::full(&path.to_string_lossy())
.ok()
.and_then(|path| PathBuf::from_str(&path).ok())
{
expanded
} else {
path.to_path_buf()
}
})
.and_then(|path| {
std::fs::OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.map_err(|err| {
#[allow(clippy::print_stderr)]
{
eprintln!(
"Failed to open file at {} for logging: {err}",
path.display()
);
}
})
.ok()
});
let logger = match log_file {
Some(file) => BoxMakeWriter::new(Arc::new(file)),
None => BoxMakeWriter::new(std::io::stderr),
};
let subscriber = tracing_subscriber::Registry::default().with(
tracing_subscriber::fmt::layer()
.with_timer(Uptime::default())
.with_thread_names(true)
.with_ansi(false)
.with_writer(logger)
.with_span_events(FmtSpan::ENTER)
.with_filter(LogLevelFilter { filter: log_level }),
);
tracing::subscriber::set_global_default(subscriber)
.expect("should be able to set global default subscriber");
}
/// The log level for the server as provided by the client during initialization.
///
/// The default log level is `info`.
#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)]
#[serde(rename_all = "lowercase")]
pub(crate) enum LogLevel {
Error,
Warn,
#[default]
Info,
Debug,
Trace,
}
impl LogLevel {
fn trace_level(self) -> tracing::Level {
match self {
Self::Error => tracing::Level::ERROR,
Self::Warn => tracing::Level::WARN,
Self::Info => tracing::Level::INFO,
Self::Debug => tracing::Level::DEBUG,
Self::Trace => tracing::Level::TRACE,
}
}
}
/// Filters out traces which have a log level lower than the `logLevel` set by the client.
struct LogLevelFilter {
filter: LogLevel,
}
impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
fn enabled(
&self,
meta: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
let filter = if meta.target().starts_with("ruff") {
self.filter.trace_level()
} else {
tracing::Level::INFO
};
meta.level() <= &filter
}
fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
Some(LevelFilter::from_level(self.filter.trace_level()))
}
}

14
crates/ruff_server/src/server.rs
View file

@ -73,16 +73,11 @@ 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 InitializeParams {
initialization_options,
workspace_folders,
client_info,
..
} = init_params;
@ -98,14 +93,9 @@ impl Server {
workspace_settings,
} = all_settings;
crate::trace::init_tracing(
connection.make_sender(),
global_settings
.tracing
.log_level
.unwrap_or(crate::trace::LogLevel::Info),
crate::logging::init_logging(
global_settings.tracing.log_level.unwrap_or_default(),
global_settings.tracing.log_file.as_deref(),
client_info.as_ref(),
);
let workspaces = Workspaces::from_workspace_folders(

9
crates/ruff_server/src/server/api.rs
View file

@ -93,9 +93,6 @@ 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();
@ -113,6 +110,7 @@ fn local_request_task<'a, R: traits::SyncRequestHandler>(
) -> super::Result<Task<'a>> {
let (id, params) = cast_request::<R>(req)?;
Ok(Task::local(|session, notifier, requester, responder| {
let _span = tracing::trace_span!("request", %id, method = R::METHOD).entered();
let result = R::run(session, notifier, requester, params);
respond::<R>(id, result, &responder);
}))
@ -129,6 +127,7 @@ fn background_request_task<'a, R: traits::BackgroundDocumentRequestHandler>(
return Box::new(|_, _| {});
};
Box::new(move |notifier, responder| {
let _span = tracing::trace_span!("request", %id, method = R::METHOD).entered();
let result = R::run_with_snapshot(snapshot, notifier, params);
respond::<R>(id, result, &responder);
})
@ -140,6 +139,7 @@ fn local_notification_task<'a, N: traits::SyncNotificationHandler>(
) -> super::Result<Task<'a>> {
let (id, params) = cast_notification::<N>(notif)?;
Ok(Task::local(move |session, notifier, requester, _| {
let _span = tracing::trace_span!("notification", method = N::METHOD).entered();
if let Err(err) = N::run(session, notifier, requester, params) {
tracing::error!("An error occurred while running {id}: {err}");
show_err_msg!("Ruff encountered a problem. Check the logs for more details.");
@ -159,6 +159,7 @@ fn background_notification_thread<'a, N: traits::BackgroundDocumentNotificationH
return Box::new(|_, _| {});
};
Box::new(move |notifier, _| {
let _span = tracing::trace_span!("notification", method = N::METHOD).entered();
if let Err(err) = N::run_with_snapshot(snapshot, notifier, params) {
tracing::error!("An error occurred while running {id}: {err}");
show_err_msg!("Ruff encountered a problem. Check the logs for more details.");
@ -205,7 +206,7 @@ fn respond<Req>(
Req: traits::RequestHandler,
{
if let Err(err) = &result {
tracing::error!("An error occurred with result ID {id}: {err}");
tracing::error!("An error occurred with request ID {id}: {err}");
show_err_msg!("Ruff encountered a problem. Check the logs for more details.");
}
if let Err(err) = responder.respond(id, result) {

2
crates/ruff_server/src/server/api/notifications.rs
View file

@ -8,7 +8,6 @@ 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;
@ -21,4 +20,3 @@ 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;

23
crates/ruff_server/src/server/api/notifications/set_trace.rs
View file

@ -1,23 +0,0 @@
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(())
}
}

2
crates/ruff_server/src/session/settings.rs
View file

@ -104,7 +104,7 @@ impl ClientSettings {
#[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_level: Option<crate::logging::LogLevel>,
/// Path to the log file - tildes and environment variables are supported.
pub(crate) log_file: Option<PathBuf>,
}

221
crates/ruff_server/src/trace.rs
View file

@ -1,221 +0,0 @@
//! The tracing system for `ruff server`.
//!
//! Traces are controlled by the `logLevel` setting, along with the
//! trace level set through the LSP. On VS Code, the trace level can
//! also be set with `ruff.trace.server`. A trace level of `messages` or
//! `verbose` will enable tracing - otherwise, no traces will be shown.
//!
//! `logLevel` can be used to configure the level of tracing that is shown.
//! By default, `logLevel` is set to `"info"`.
//!
//! The server also supports the `RUFF_TRACE` environment variable, which will
//! override the trace value provided by the LSP client. Use this if there's no good way
//! to set the trace value through your editor's configuration.
//!
//! 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::{LogTrace, Notification as _},
ClientInfo, TraceValue,
};
use serde::Deserialize;
use std::{
io::{Error as IoError, ErrorKind, Write},
path::PathBuf,
str::FromStr,
sync::{Arc, Mutex, OnceLock},
};
use tracing::level_filters::LevelFilter;
use tracing_subscriber::{
fmt::{time::Uptime, writer::BoxMakeWriter, MakeWriter},
layer::SubscriberExt,
Layer,
};
use crate::server::ClientSender;
const TRACE_ENV_KEY: &str = "RUFF_TRACE";
static LOGGING_SENDER: OnceLock<ClientSender> = OnceLock::new();
static TRACE_VALUE: Mutex<lsp_types::TraceValue> = Mutex::new(lsp_types::TraceValue::Off);
pub(crate) fn set_trace_value(trace_value: TraceValue) {
let mut global_trace_value = TRACE_VALUE
.lock()
.expect("trace value mutex should be available");
*global_trace_value = trace_value;
}
// A tracing writer that uses LSPs logTrace method.
struct TraceLogWriter;
impl Write for TraceLogWriter {
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?;
LOGGING_SENDER
.get()
.expect("logging sender should be initialized at this point")
.send(Message::Notification(Notification {
method: LogTrace::METHOD.to_owned(),
params: serde_json::json!({
"message": message
}),
}))
.map_err(|e| IoError::new(ErrorKind::Other, e))?;
Ok(buf.len())
}
fn flush(&mut self) -> std::io::Result<()> {
Ok(())
}
}
impl<'a> MakeWriter<'a> for TraceLogWriter {
type Writer = Self;
fn make_writer(&'a self) -> Self::Writer {
Self
}
}
pub(crate) fn init_tracing(
sender: ClientSender,
log_level: LogLevel,
log_file: Option<&std::path::Path>,
client: Option<&ClientInfo>,
) {
LOGGING_SENDER
.set(sender)
.expect("logging sender should only be initialized once");
let log_file = log_file
.map(|path| {
// this expands `logFile` so that tildes and environment variables
// are replaced with their values, if possible.
if let Some(expanded) = shellexpand::full(&path.to_string_lossy())
.ok()
.and_then(|path| PathBuf::from_str(&path).ok())
{
expanded
} else {
path.to_path_buf()
}
})
.and_then(|path| {
std::fs::OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.map_err(|err| {
#[allow(clippy::print_stderr)]
{
eprintln!(
"Failed to open file at {} for logging: {err}",
path.display()
);
}
})
.ok()
});
let logger = match log_file {
Some(file) => BoxMakeWriter::new(Arc::new(file)),
None => {
if client.is_some_and(|client| {
client.name.starts_with("Zed") || client.name.starts_with("Visual Studio Code")
}) {
BoxMakeWriter::new(TraceLogWriter)
} else {
BoxMakeWriter::new(std::io::stderr)
}
}
};
let subscriber = tracing_subscriber::Registry::default().with(
tracing_subscriber::fmt::layer()
.with_timer(Uptime::default())
.with_thread_names(true)
.with_ansi(false)
.with_writer(logger)
.with_filter(TraceLevelFilter)
.with_filter(LogLevelFilter { filter: log_level }),
);
tracing::subscriber::set_global_default(subscriber)
.expect("should be able to set global default subscriber");
}
#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)]
#[serde(rename_all = "lowercase")]
pub(crate) enum LogLevel {
#[default]
Error,
Warn,
Info,
Debug,
Trace,
}
impl LogLevel {
fn trace_level(self) -> tracing::Level {
match self {
Self::Error => tracing::Level::ERROR,
Self::Warn => tracing::Level::WARN,
Self::Info => tracing::Level::INFO,
Self::Debug => tracing::Level::DEBUG,
Self::Trace => tracing::Level::TRACE,
}
}
}
/// Filters out traces which have a log level lower than the `logLevel` set by the client.
struct LogLevelFilter {
filter: LogLevel,
}
/// Filters out traces if the trace value set by the client is `off`.
struct TraceLevelFilter;
impl<S> tracing_subscriber::layer::Filter<S> for LogLevelFilter {
fn enabled(
&self,
meta: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
let filter = if meta.target().starts_with("ruff") {
self.filter.trace_level()
} else {
tracing::Level::INFO
};
meta.level() <= &filter
}
fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
Some(LevelFilter::from_level(self.filter.trace_level()))
}
}
impl<S> tracing_subscriber::layer::Filter<S> for TraceLevelFilter {
fn enabled(
&self,
_: &tracing::Metadata<'_>,
_: &tracing_subscriber::layer::Context<'_, S>,
) -> bool {
trace_value() != lsp_types::TraceValue::Off
}
}
#[inline]
fn trace_value() -> lsp_types::TraceValue {
std::env::var(TRACE_ENV_KEY)
.ok()
.and_then(|trace| serde_json::from_value(serde_json::Value::String(trace)).ok())
.unwrap_or_else(|| {
*TRACE_VALUE
.lock()
.expect("trace value mutex should be available")
})
}

27
docs/editors/setup.md
View file

@ -92,13 +92,11 @@ require('lspconfig').pyright.setup {
}
```
By default, Ruff will not show any logs. To enable logging in Neovim, you'll need to set the
[`trace`](https://neovim.io/doc/user/lsp.html#vim.lsp.ClientConfig) setting to either `messages` or `verbose`, and use the
[`logLevel`](./settings.md#loglevel) setting to change the log level:
By default, the log level for Ruff is set to `info`. To change the log level, you can set the
[`logLevel`](./settings.md#loglevel) setting:
```lua
require('lspconfig').ruff.setup {
trace = 'messages',
init_options = {
settings = {
logLevel = 'debug',
@ -107,10 +105,16 @@ require('lspconfig').ruff.setup {
}
```
By default, this will write logs to stderr which will be available in Neovim's LSP client log file
By default, Ruff will write logs to stderr which will be available in Neovim's LSP client log file
(`:lua vim.print(vim.lsp.get_log_path())`). It's also possible to divert these logs to a separate
file with the [`logFile`](./settings.md#logfile) setting.
To view the trace logs between Neovim and Ruff, set the log level for Neovim's LSP client to `debug`:
```lua
vim.lsp.set_log_level('debug')
```
## Vim
The [`vim-lsp`](https://github.com/prabirshrestha/vim-lsp) plugin can be used to configure the Ruff Language Server in Vim.
@ -274,15 +278,13 @@ preview = false
preview = true
```
By default, Ruff does not log anything to Helix. To enable logging, set the `RUFF_TRACE` environment
variable to either `messages` or `verbose`, and use the [`logLevel`](./settings.md#loglevel) setting to change
the log level:
By default, the log level for Ruff is set to `info`. To change the log level, you can set the
[`logLevel`](./settings.md#loglevel) setting:
```toml
[language-server.ruff]
command = "ruff"
args = ["server"]
environment = { "RUFF_TRACE" = "messages" }
[language-server.ruff.config.settings]
logLevel = "debug"
@ -290,10 +292,11 @@ logLevel = "debug"
You can also divert Ruff's logs to a separate file with the [`logFile`](./settings.md#logfile) setting.
!!! note
To view the trace logs between Helix and Ruff, pass in the `-v` (verbose) flag when starting Helix:
Setting `RUFF_TRACE=verbose` does not enable Helix's verbose mode by itself. You'll need to run
Helix with `-v` for verbose logging.
```sh
hx -v path/to/file.py
```
## Kate