Add tracing span macro calls to the language server for better debugging

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(|| {

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<Session>, url: &Url) -> Vec<CodeLens> {
+    let _p = tracing::trace_span!("code_lens").entered();
     let url_path = PathBuf::from(url.path());
 
     // Construct code lenses for runnable functions

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<Vec<TextEdit>, 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(),

sway-lsp/src/capabilities/highlight.rs

@@ -7,6 +7,7 @@ pub fn get_highlights(
     url: &Url,
     position: Position,
 ) -> Option<Vec<DocumentHighlight>> {
+    let _p = tracing::trace_span!("get_highlights").entered();
     session.token_ranges(url, position).map(|ranges| {
         ranges
             .into_iter()

sway-lsp/src/capabilities/inlay_hints.rs

@@ -29,6 +29,7 @@ pub fn inlay_hints(
     range: &Range,
     config: &InlayHintsConfig,
 ) -> Option<Vec<lsp_types::InlayHint>> {
+    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

sway-lsp/src/capabilities/rename.rs

@@ -20,6 +20,7 @@ pub fn rename(
     url: &Url,
     position: Position,
 ) -> Result<WorkspaceEdit, LanguageServerError> {
+    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()

sway-lsp/src/capabilities/semantic_tokens.rs

@@ -27,6 +27,7 @@ pub fn semantic_tokens_range(
     url: &Url,
     range: &Range,
 ) -> Option<SemanticTokensRangeResult> {
+    let _p = tracing::trace_span!("semantic_tokens_range").entered();
     let tokens: Vec<_> = session
         .token_map()
         .tokens_for_file(url)

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<Vec<Range>> {
+        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<GotoDefinitionResponse> {
+        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<Vec<CompletionItem>> {
+        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<Vec<SymbolInformation>> {
+        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<BuildPlan, LanguageServerError> {
+    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<LspConfig>,
     experimental: sway_core::ExperimentalFlags,
 ) -> Result<Vec<(Option<Programs>, 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<Session>,
 ) -> Result<Option<CompileResults>, 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<Session>,
     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.

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 {

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");
     }
 

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