From c8cde019dc280a1b64c962bd4764d224cbf6fbb9 Mon Sep 17 00:00:00 2001 From: Joshua Batty Date: Tue, 16 Jul 2024 01:25:41 +1000 Subject: [PATCH] Add tracing span macro calls to the language server for better debugging (#6238) ## Description closes #6220 ## Checklist - [x] I have linked to any relevant issues. - [x] I have commented my code, particularly in hard-to-understand areas. - [x] I have updated the documentation where relevant (API docs, the reference, and the Sway book). - [x] If my change requires substantial documentation changes, I have [requested support from the DevRel team](https://github.com/FuelLabs/devrel-requests/issues/new/choose) - [x] I have added tests that prove my fix is effective or that my feature works. - [x] I have added (or requested a maintainer to add) the necessary `Breaking*` or `New Feature` labels where relevant. - [x] I have done my best to ensure that my PR adheres to [the Fuel Labs Code Review Standards](https://github.com/FuelLabs/rfcs/blob/master/text/code-standards/external-contributors.md). - [x] I have requested a review from the relevant team or maintainers. --- forc-tracing/src/lib.rs | 10 +++++----- sway-lsp/src/capabilities/code_lens.rs | 1 + sway-lsp/src/capabilities/formatting.rs | 1 + sway-lsp/src/capabilities/highlight.rs | 1 + sway-lsp/src/capabilities/inlay_hints.rs | 1 + sway-lsp/src/capabilities/rename.rs | 1 + sway-lsp/src/capabilities/semantic_tokens.rs | 1 + sway-lsp/src/core/session.rs | 10 ++++++++++ sway-lsp/src/handlers/request.rs | 16 +++++++++------- sway-lsp/src/server.rs | 1 + sway-lsp/src/server_state.rs | 1 + 11 files changed, 32 insertions(+), 12 deletions(-) diff --git a/forc-tracing/src/lib.rs b/forc-tracing/src/lib.rs index 0141aa7bf64..656cb14ca14 100644 --- a/forc-tracing/src/lib.rs +++ b/forc-tracing/src/lib.rs @@ -4,9 +4,10 @@ use ansi_term::Colour; use std::str; use std::{env, io}; use tracing::{Level, Metadata}; -use tracing_subscriber::{ +pub use tracing_subscriber::{ + self, filter::{EnvFilter, LevelFilter}, - fmt::MakeWriter, + fmt::{format::FmtSpan, MakeWriter}, }; const ACTION_COLUMN_WIDTH: usize = 12; @@ -83,8 +84,8 @@ const LOG_FILTER: &str = "RUST_LOG"; // This allows us to write ERROR and WARN level logs to stderr and everything else to stdout. // https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/trait.MakeWriter.html -struct StdioTracingWriter { - writer_mode: TracingWriterMode, +pub struct StdioTracingWriter { + pub writer_mode: TracingWriterMode, } impl<'a> MakeWriter<'a> for StdioTracingWriter { @@ -142,7 +143,6 @@ pub fn init_tracing_subscriber(options: TracingSubscriberOptions) { Some(_) => EnvFilter::try_from_default_env().expect("Invalid `RUST_LOG` provided"), None => EnvFilter::new("info"), }; - let level_filter = options .log_level .or_else(|| { diff --git a/sway-lsp/src/capabilities/code_lens.rs b/sway-lsp/src/capabilities/code_lens.rs index d4c92c52648..f8a81e3476c 100644 --- a/sway-lsp/src/capabilities/code_lens.rs +++ b/sway-lsp/src/capabilities/code_lens.rs @@ -5,6 +5,7 @@ use lsp_types::{CodeLens, Url}; use crate::core::session::Session; pub fn code_lens(session: &Arc, url: &Url) -> Vec { + let _p = tracing::trace_span!("code_lens").entered(); let url_path = PathBuf::from(url.path()); // Construct code lenses for runnable functions diff --git a/sway-lsp/src/capabilities/formatting.rs b/sway-lsp/src/capabilities/formatting.rs index 9214da23ae3..e4b1596991b 100644 --- a/sway-lsp/src/capabilities/formatting.rs +++ b/sway-lsp/src/capabilities/formatting.rs @@ -7,6 +7,7 @@ use std::sync::Arc; use swayfmt::Formatter; pub fn format_text(documents: &Documents, url: &Url) -> Result, LanguageServerError> { + let _p = tracing::trace_span!("format_text").entered(); let document = documents.try_get(url.path()).try_unwrap().ok_or_else(|| { DocumentError::DocumentNotFound { path: url.path().to_string(), diff --git a/sway-lsp/src/capabilities/highlight.rs b/sway-lsp/src/capabilities/highlight.rs index f6eef7f4fb3..7236bb8a7e7 100644 --- a/sway-lsp/src/capabilities/highlight.rs +++ b/sway-lsp/src/capabilities/highlight.rs @@ -7,6 +7,7 @@ pub fn get_highlights( url: &Url, position: Position, ) -> Option> { + let _p = tracing::trace_span!("get_highlights").entered(); session.token_ranges(url, position).map(|ranges| { ranges .into_iter() diff --git a/sway-lsp/src/capabilities/inlay_hints.rs b/sway-lsp/src/capabilities/inlay_hints.rs index b95f3455312..f6bdb95a128 100644 --- a/sway-lsp/src/capabilities/inlay_hints.rs +++ b/sway-lsp/src/capabilities/inlay_hints.rs @@ -29,6 +29,7 @@ pub fn inlay_hints( range: &Range, config: &InlayHintsConfig, ) -> Option> { + let _p = tracing::trace_span!("inlay_hints").entered(); // 1. Loop through all our tokens and filter out all tokens that aren't TypedVariableDeclaration tokens // 2. Also filter out all tokens that have a span that fall outside of the provided range // 3. Filter out all variable tokens that have a type_ascription diff --git a/sway-lsp/src/capabilities/rename.rs b/sway-lsp/src/capabilities/rename.rs index c00d9374f94..6070fd992c9 100644 --- a/sway-lsp/src/capabilities/rename.rs +++ b/sway-lsp/src/capabilities/rename.rs @@ -20,6 +20,7 @@ pub fn rename( url: &Url, position: Position, ) -> Result { + let _p = tracing::trace_span!("rename").entered(); // Make sure the new name is not a keyword or a literal int type if sway_parse::RESERVED_KEYWORDS.contains(&new_name) || sway_parse::parse_int_suffix(&new_name).is_some() diff --git a/sway-lsp/src/capabilities/semantic_tokens.rs b/sway-lsp/src/capabilities/semantic_tokens.rs index 05cd9e41474..30b2fc16564 100644 --- a/sway-lsp/src/capabilities/semantic_tokens.rs +++ b/sway-lsp/src/capabilities/semantic_tokens.rs @@ -27,6 +27,7 @@ pub fn semantic_tokens_range( url: &Url, range: &Range, ) -> Option { + let _p = tracing::trace_span!("semantic_tokens_range").entered(); let tokens: Vec<_> = session .token_map() .tokens_for_file(url) diff --git a/sway-lsp/src/core/session.rs b/sway-lsp/src/core/session.rs index 749168d1538..e0fe109c43a 100644 --- a/sway-lsp/src/core/session.rs +++ b/sway-lsp/src/core/session.rs @@ -122,6 +122,7 @@ impl Session { /// Clean up memory in the [TypeEngine] and [DeclEngine] for the user's workspace. pub fn garbage_collect(&self, engines: &mut Engines) -> Result<(), LanguageServerError> { + let _p = tracing::trace_span!("garbage_collect").entered(); let path = self.sync.temp_dir()?; let program_id = { engines.se().get_program_id(&path) }; if let Some(program_id) = program_id { @@ -131,6 +132,7 @@ impl Session { } pub fn token_ranges(&self, url: &Url, position: Position) -> Option> { + let _p = tracing::trace_span!("token_ranges").entered(); let mut token_ranges: Vec<_> = self .token_map .tokens_for_file(url) @@ -150,6 +152,7 @@ impl Session { uri: &Url, position: Position, ) -> Option { + let _p = tracing::trace_span!("token_definition_response").entered(); self.token_map .token_at_position(uri, position) .and_then(|item| item.value().declared_token_ident(&self.engines.read())) @@ -171,6 +174,7 @@ impl Session { position: Position, trigger_char: &str, ) -> Option> { + let _p = tracing::trace_span!("completion_items").entered(); let shifted_position = Position { line: position.line, character: position.character - trigger_char.len() as u32 - 1, @@ -205,6 +209,7 @@ impl Session { } pub fn symbol_information(&self, url: &Url) -> Option> { + let _p = tracing::trace_span!("symbol_information").entered(); let tokens = self.token_map.tokens_for_file(url); self.sync .to_workspace_url(url.clone()) @@ -224,6 +229,7 @@ impl Session { /// Create a [BuildPlan] from the given [Url] appropriate for the language server. pub(crate) fn build_plan(uri: &Url) -> Result { + let _p = tracing::trace_span!("build_plan").entered(); let manifest_dir = PathBuf::from(uri.path()); let manifest = ManifestFile::from_dir(manifest_dir).map_err(|_| DocumentError::ManifestFileNotFound { @@ -254,6 +260,7 @@ pub fn compile( lsp_mode: Option, experimental: sway_core::ExperimentalFlags, ) -> Result, Handler)>, LanguageServerError> { + let _p = tracing::trace_span!("compile").entered(); let build_plan = build_plan(uri)?; let tests_enabled = true; pkg::check( @@ -276,6 +283,7 @@ pub fn traverse( engines_clone: &Engines, session: Arc, ) -> Result, LanguageServerError> { + let _p = tracing::trace_span!("traverse").entered(); session.token_map.clear(); session.metrics.clear(); let mut diagnostics: CompileResults = (Vec::default(), Vec::default()); @@ -373,6 +381,7 @@ pub fn parse_project( session: Arc, experimental: sway_core::ExperimentalFlags, ) -> Result<(), LanguageServerError> { + let _p = tracing::trace_span!("parse_project").entered(); let results = compile( uri, engines, @@ -448,6 +457,7 @@ fn create_runnables( decl_engine: &DeclEngine, source_engine: &SourceEngine, ) { + let _p = tracing::trace_span!("create_runnables").entered(); // Insert runnable test functions. for (decl, _) in typed_program.test_fns(decl_engine) { // Get the span of the first attribute if it exists, otherwise use the span of the function name. diff --git a/sway-lsp/src/handlers/request.rs b/sway-lsp/src/handlers/request.rs index dd94d823959..f4b821fb599 100644 --- a/sway-lsp/src/handlers/request.rs +++ b/sway-lsp/src/handlers/request.rs @@ -4,7 +4,7 @@ use crate::{ capabilities, core::session::build_plan, lsp_ext, server_state::ServerState, utils::debug, }; -use forc_tracing::{init_tracing_subscriber, TracingSubscriberOptions, TracingWriterMode}; +use forc_tracing::{tracing_subscriber, FmtSpan, StdioTracingWriter, TracingWriterMode}; use lsp_types::{ CodeLens, CompletionResponse, DocumentFormattingParams, DocumentSymbolResponse, InitializeResult, InlayHint, InlayHintParams, PrepareRenameResponse, RenameParams, @@ -40,12 +40,14 @@ pub fn handle_initialize( // Initializing tracing library based on the user's config let config = state.config.read(); if config.logging.level != LevelFilter::OFF { - let tracing_options = TracingSubscriberOptions { - log_level: Some(config.logging.level), - writer_mode: Some(TracingWriterMode::Stderr), - ..Default::default() - }; - init_tracing_subscriber(tracing_options); + tracing_subscriber::fmt::Subscriber::builder() + .with_ansi(false) + .with_max_level(config.logging.level) + .with_span_events(FmtSpan::CLOSE) + .with_writer(StdioTracingWriter { + writer_mode: TracingWriterMode::Stderr, + }) + .init(); } tracing::info!("Initializing the Sway Language Server"); Ok(InitializeResult { diff --git a/sway-lsp/src/server.rs b/sway-lsp/src/server.rs index 9f044e64b89..34314c89381 100644 --- a/sway-lsp/src/server.rs +++ b/sway-lsp/src/server.rs @@ -28,6 +28,7 @@ impl LanguageServer for ServerState { } async fn initialized(&self, _: InitializedParams) { + let _p = tracing::trace_span!("parse_text").entered(); tracing::info!("Sway Language Server Initialized"); } diff --git a/sway-lsp/src/server_state.rs b/sway-lsp/src/server_state.rs index f744adc8847..2f614e93072 100644 --- a/sway-lsp/src/server_state.rs +++ b/sway-lsp/src/server_state.rs @@ -264,6 +264,7 @@ impl ServerState { } pub fn shutdown_server(&self) -> jsonrpc::Result<()> { + let _p = tracing::trace_span!("shutdown_server").entered(); tracing::info!("Shutting Down the Sway Language Server"); // Drain pending compilation requests