mirror of
https://github.com/astral-sh/ruff
synced 2026-01-23 06:20:55 -05:00
## 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
```
278 lines
10 KiB
Rust
278 lines
10 KiB
Rust
use crate::{server::schedule::Task, session::Session};
|
|
use lsp_server as server;
|
|
|
|
mod diagnostics;
|
|
mod notifications;
|
|
mod requests;
|
|
mod traits;
|
|
|
|
use notifications as notification;
|
|
use requests as request;
|
|
|
|
use self::traits::{NotificationHandler, RequestHandler};
|
|
|
|
use super::{client::Responder, schedule::BackgroundSchedule, Result};
|
|
|
|
/// Defines the `document_url` method for implementers of [`traits::Notification`] and [`traits::Request`],
|
|
/// given the parameter type used by the implementer.
|
|
macro_rules! define_document_url {
|
|
($params:ident: &$p:ty) => {
|
|
fn document_url($params: &$p) -> std::borrow::Cow<lsp_types::Url> {
|
|
std::borrow::Cow::Borrowed(&$params.text_document.uri)
|
|
}
|
|
};
|
|
}
|
|
|
|
use define_document_url;
|
|
|
|
pub(super) fn request<'a>(req: server::Request) -> Task<'a> {
|
|
let id = req.id.clone();
|
|
|
|
match req.method.as_str() {
|
|
request::CodeActions::METHOD => background_request_task::<request::CodeActions>(
|
|
req,
|
|
BackgroundSchedule::LatencySensitive,
|
|
),
|
|
request::CodeActionResolve::METHOD => {
|
|
background_request_task::<request::CodeActionResolve>(req, BackgroundSchedule::Worker)
|
|
}
|
|
request::DocumentDiagnostic::METHOD => {
|
|
background_request_task::<request::DocumentDiagnostic>(
|
|
req,
|
|
BackgroundSchedule::LatencySensitive,
|
|
)
|
|
}
|
|
request::ExecuteCommand::METHOD => local_request_task::<request::ExecuteCommand>(req),
|
|
request::Format::METHOD => {
|
|
background_request_task::<request::Format>(req, BackgroundSchedule::Fmt)
|
|
}
|
|
request::FormatRange::METHOD => {
|
|
background_request_task::<request::FormatRange>(req, BackgroundSchedule::Fmt)
|
|
}
|
|
request::Hover::METHOD => {
|
|
background_request_task::<request::Hover>(req, BackgroundSchedule::Worker)
|
|
}
|
|
method => {
|
|
tracing::warn!("Received request {method} which does not have a handler");
|
|
return Task::nothing();
|
|
}
|
|
}
|
|
.unwrap_or_else(|err| {
|
|
tracing::error!("Encountered error when routing request with ID {id}: {err}");
|
|
show_err_msg!(
|
|
"Ruff failed to handle a request from the editor. Check the logs for more details."
|
|
);
|
|
let result: Result<()> = Err(err);
|
|
Task::immediate(id, result)
|
|
})
|
|
}
|
|
|
|
pub(super) fn notification<'a>(notif: server::Notification) -> Task<'a> {
|
|
match notif.method.as_str() {
|
|
notification::Cancel::METHOD => local_notification_task::<notification::Cancel>(notif),
|
|
notification::DidChange::METHOD => {
|
|
local_notification_task::<notification::DidChange>(notif)
|
|
}
|
|
notification::DidChangeConfiguration::METHOD => {
|
|
local_notification_task::<notification::DidChangeConfiguration>(notif)
|
|
}
|
|
notification::DidChangeWatchedFiles::METHOD => {
|
|
local_notification_task::<notification::DidChangeWatchedFiles>(notif)
|
|
}
|
|
notification::DidChangeWorkspace::METHOD => {
|
|
local_notification_task::<notification::DidChangeWorkspace>(notif)
|
|
}
|
|
notification::DidClose::METHOD => local_notification_task::<notification::DidClose>(notif),
|
|
notification::DidOpen::METHOD => local_notification_task::<notification::DidOpen>(notif),
|
|
notification::DidOpenNotebook::METHOD => {
|
|
local_notification_task::<notification::DidOpenNotebook>(notif)
|
|
}
|
|
notification::DidChangeNotebook::METHOD => {
|
|
local_notification_task::<notification::DidChangeNotebook>(notif)
|
|
}
|
|
notification::DidCloseNotebook::METHOD => {
|
|
local_notification_task::<notification::DidCloseNotebook>(notif)
|
|
}
|
|
method => {
|
|
tracing::warn!("Received notification {method} which does not have a handler.");
|
|
return Task::nothing();
|
|
}
|
|
}
|
|
.unwrap_or_else(|err| {
|
|
tracing::error!("Encountered error when routing notification: {err}");
|
|
show_err_msg!("Ruff failed to handle a notification from the editor. Check the logs for more details.");
|
|
Task::nothing()
|
|
})
|
|
}
|
|
|
|
fn local_request_task<'a, R: traits::SyncRequestHandler>(
|
|
req: server::Request,
|
|
) -> 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);
|
|
}))
|
|
}
|
|
|
|
fn background_request_task<'a, R: traits::BackgroundDocumentRequestHandler>(
|
|
req: server::Request,
|
|
schedule: BackgroundSchedule,
|
|
) -> super::Result<Task<'a>> {
|
|
let (id, params) = cast_request::<R>(req)?;
|
|
Ok(Task::background(schedule, move |session: &Session| {
|
|
// TODO(jane): we should log an error if we can't take a snapshot.
|
|
let Some(snapshot) = session.take_snapshot(R::document_url(¶ms).into_owned()) else {
|
|
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);
|
|
})
|
|
}))
|
|
}
|
|
|
|
fn local_notification_task<'a, N: traits::SyncNotificationHandler>(
|
|
notif: server::Notification,
|
|
) -> 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.");
|
|
}
|
|
}))
|
|
}
|
|
|
|
#[allow(dead_code)]
|
|
fn background_notification_thread<'a, N: traits::BackgroundDocumentNotificationHandler>(
|
|
req: server::Notification,
|
|
schedule: BackgroundSchedule,
|
|
) -> super::Result<Task<'a>> {
|
|
let (id, params) = cast_notification::<N>(req)?;
|
|
Ok(Task::background(schedule, move |session: &Session| {
|
|
// TODO(jane): we should log an error if we can't take a snapshot.
|
|
let Some(snapshot) = session.take_snapshot(N::document_url(¶ms).into_owned()) else {
|
|
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.");
|
|
}
|
|
})
|
|
}))
|
|
}
|
|
|
|
/// Tries to cast a serialized request from the server into
|
|
/// a parameter type for a specific request handler.
|
|
/// It is *highly* recommended to not override this function in your
|
|
/// implementation.
|
|
fn cast_request<Req>(
|
|
request: server::Request,
|
|
) -> super::Result<(
|
|
server::RequestId,
|
|
<<Req as RequestHandler>::RequestType as lsp_types::request::Request>::Params,
|
|
)>
|
|
where
|
|
Req: traits::RequestHandler,
|
|
{
|
|
request
|
|
.extract(Req::METHOD)
|
|
.map_err(|err| match err {
|
|
json_err @ server::ExtractError::JsonError { .. } => {
|
|
anyhow::anyhow!("JSON parsing failure:\n{json_err}")
|
|
}
|
|
server::ExtractError::MethodMismatch(_) => {
|
|
unreachable!("A method mismatch should not be possible here unless you've used a different handler (`Req`) \
|
|
than the one whose method name was matched against earlier.")
|
|
}
|
|
})
|
|
.with_failure_code(server::ErrorCode::InternalError)
|
|
}
|
|
|
|
/// Sends back a response to the server using a [`Responder`].
|
|
fn respond<Req>(
|
|
id: server::RequestId,
|
|
result: crate::server::Result<
|
|
<<Req as traits::RequestHandler>::RequestType as lsp_types::request::Request>::Result,
|
|
>,
|
|
responder: &Responder,
|
|
) where
|
|
Req: traits::RequestHandler,
|
|
{
|
|
if let Err(err) = &result {
|
|
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) {
|
|
tracing::error!("Failed to send response: {err}");
|
|
}
|
|
}
|
|
|
|
/// Tries to cast a serialized request from the server into
|
|
/// a parameter type for a specific request handler.
|
|
fn cast_notification<N>(
|
|
notification: server::Notification,
|
|
) -> super::Result<
|
|
(
|
|
&'static str,
|
|
<<N as traits::NotificationHandler>::NotificationType as lsp_types::notification::Notification>::Params,
|
|
)> where N: traits::NotificationHandler{
|
|
Ok((
|
|
N::METHOD,
|
|
notification
|
|
.extract(N::METHOD)
|
|
.map_err(|err| match err {
|
|
json_err @ server::ExtractError::JsonError { .. } => {
|
|
anyhow::anyhow!("JSON parsing failure:\n{json_err}")
|
|
}
|
|
server::ExtractError::MethodMismatch(_) => {
|
|
unreachable!("A method mismatch should not be possible here unless you've used a different handler (`N`) \
|
|
than the one whose method name was matched against earlier.")
|
|
}
|
|
})
|
|
.with_failure_code(server::ErrorCode::InternalError)?,
|
|
))
|
|
}
|
|
|
|
pub(crate) struct Error {
|
|
pub(crate) code: server::ErrorCode,
|
|
pub(crate) error: anyhow::Error,
|
|
}
|
|
|
|
/// A trait to convert result types into the server result type, [`super::Result`].
|
|
trait LSPResult<T> {
|
|
fn with_failure_code(self, code: server::ErrorCode) -> super::Result<T>;
|
|
}
|
|
|
|
impl<T, E: Into<anyhow::Error>> LSPResult<T> for core::result::Result<T, E> {
|
|
fn with_failure_code(self, code: server::ErrorCode) -> super::Result<T> {
|
|
self.map_err(|err| Error::new(err.into(), code))
|
|
}
|
|
}
|
|
|
|
impl Error {
|
|
pub(crate) fn new(err: anyhow::Error, code: server::ErrorCode) -> Self {
|
|
Self { code, error: err }
|
|
}
|
|
}
|
|
|
|
// Right now, we treat the error code as invisible data that won't
|
|
// be printed.
|
|
impl std::fmt::Debug for Error {
|
|
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
|
|
self.error.fmt(f)
|
|
}
|
|
}
|
|
|
|
impl std::fmt::Display for Error {
|
|
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
|
|
self.error.fmt(f)
|
|
}
|
|
}
|