[LSP] Replace logging with tracing (FuelLabs#2925)

Related FuelLabs#2286

Replacing the tower_lsp logging with calls to the `tracing` lib.

Added an option to `init_tracing_subscriber` to allow all tracing logs
to be piped through stderr instead of split between stderr/stdio.
Because the main thread in the LSP uses stdio to communicate with the
LSP client, tracing logs must go through stderr.

<img width="1018" alt="image"
src="https://user-images.githubusercontent.com/47993817/193706774-2868ee6a-f62d-4a6e-b137-4aff09214536.png">

Co-authored-by: Joshua Batty <[email protected]>

forc-util/src/lib.rs

@@ -391,22 +391,30 @@ 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;
+struct StdioTracingWriter {
+    writer_mode: TracingWriterMode,
+}
 impl<'a> MakeWriter<'a> for StdioTracingWriter {
     type Writer = Box<dyn io::Write>;
 
     fn make_writer(&'a self) -> Self::Writer {
-        // We must have an implementation of `make_writer` that makes
-        // a "default" writer without any configuring metadata. Let's
-        // just return stdout in that case.
-        Box::new(io::stdout())
+        if self.writer_mode == TracingWriterMode::Stderr {
+            Box::new(io::stderr())
+        } else {
+            // We must have an implementation of `make_writer` that makes
+            // a "default" writer without any configuring metadata. Let's
+            // just return stdout in that case.
+            Box::new(io::stdout())
+        }
     }
 
     fn make_writer_for(&'a self, meta: &Metadata<'_>) -> Self::Writer {
         // Here's where we can implement our special behavior. We'll
         // check if the metadata's verbosity level is WARN or ERROR,
         // and return stderr in that case.
-        if meta.level() <= &Level::WARN {
+        if self.writer_mode == TracingWriterMode::Stderr
+            || (self.writer_mode == TracingWriterMode::Stdio && meta.level() <= &Level::WARN)
+        {
             return Box::new(io::stderr());
         }
 
@@ -415,11 +423,22 @@ impl<'a> MakeWriter<'a> for StdioTracingWriter {
     }
 }
 
+#[derive(PartialEq, Eq)]
+pub enum TracingWriterMode {
+    /// Write ERROR and WARN to stderr and everything else to stdout.
+    Stdio,
+    /// Write everything to stdout.
+    Stdout,
+    /// Write everything to stderr.
+    Stderr,
+}
+
 #[derive(Default)]
 pub struct TracingSubscriberOptions {
     pub verbosity: Option<u8>,
     pub silent: Option<bool>,
     pub log_level: Option<LevelFilter>,
+    pub writer_mode: Option<TracingWriterMode>,
 }
 
 /// A subscriber built from default `tracing_subscriber::fmt::SubscriberBuilder` such that it would match directly using `println!` throughout the repo.
@@ -457,7 +476,9 @@ pub fn init_tracing_subscriber(options: TracingSubscriberOptions) {
         .with_line_number(false)
         .without_time()
         .with_target(false)
-        .with_writer(StdioTracingWriter);
+        .with_writer(StdioTracingWriter {
+            writer_mode: options.writer_mode.unwrap_or(TracingWriterMode::Stdio),
+        });
 
     // If log level, verbosity, or silent mode is set, it overrides the RUST_LOG setting
     if let Some(level_filter) = level_filter {

forc/src/cli/mod.rs

@@ -79,6 +79,7 @@ pub async fn run_cli() -> Result<()> {
         verbosity: Some(opt.verbose),
         silent: Some(opt.silent),
         log_level: opt.log_level,
+        ..Default::default()
     };
 
     init_tracing_subscriber(tracing_options);

sway-lsp/Cargo.toml

@@ -12,6 +12,7 @@ description = "LSP server for Sway."
 anyhow = "1.0.41"
 dashmap = "5.4"
 forc-pkg = { version = "0.27.0", path = "../forc-pkg" }
+forc-util = { version = "0.27.0", path = "../forc-util" }
 notify = "5.0.0"
 notify-debouncer-mini = { version = "0.2.0" }
 parking_lot = "0.12.1"

sway-lsp/src/lib.rs

@@ -1,4 +1,6 @@
 #![recursion_limit = "256"]
+
+use forc_util::{init_tracing_subscriber, TracingSubscriberOptions, TracingWriterMode};
 use tower_lsp::{LspService, Server};
 
 mod capabilities;
@@ -9,8 +11,16 @@ mod server;
 pub mod test_utils;
 pub mod utils;
 use server::Backend;
+use tracing::metadata::LevelFilter;
 
 pub async fn start() {
+    let tracing_options = TracingSubscriberOptions {
+        log_level: Some(LevelFilter::DEBUG), // TODO: Set this based on IDE config
+        writer_mode: Some(TracingWriterMode::Stderr),
+        ..Default::default()
+    };
+    init_tracing_subscriber(tracing_options);
+
     let stdin = tokio::io::stdin();
     let stdout = tokio::io::stdout();
 

sway-lsp/src/server.rs

@@ -58,20 +58,12 @@ impl Backend {
         Ok((uri, session))
     }
 
-    async fn log_info_message(&self, message: &str) {
-        self.client.log_message(MessageType::INFO, message).await;
-    }
-
-    async fn log_error_message(&self, message: &str) {
-        self.client.log_message(MessageType::ERROR, message).await;
-    }
-
     async fn parse_project(&self, uri: Url, workspace_uri: Url, session: Arc<Session>) {
         // pass in the temp Url into parse_project, we can now get the updated AST's back.
         let diagnostics = match session.parse_project(&uri) {
             Ok(diagnostics) => diagnostics,
             Err(err) => {
-                self.log_error_message(err.to_string().as_str()).await;
+                tracing::error!("{}", err.to_string().as_str());
                 if let LanguageServerError::FailedToParse { diagnostics } = err {
                     diagnostics
                 } else {
@@ -186,10 +178,7 @@ impl Backend {
 #[tower_lsp::async_trait]
 impl LanguageServer for Backend {
     async fn initialize(&self, params: InitializeParams) -> jsonrpc::Result<InitializeResult> {
-        eprintln!("InitializeParams = {:#?}", params);
-        self.client
-            .log_message(MessageType::INFO, "Initializing the Sway Language Server")
-            .await;
+        tracing::info!("Initializing the Sway Language Server");
 
         if let Some(initialization_options) = &params.initialization_options {
             let mut config = self.config.write();
@@ -207,13 +196,11 @@ impl LanguageServer for Backend {
 
     // LSP-Server Lifecycle
     async fn initialized(&self, _: InitializedParams) {
-        self.log_info_message("Sway Language Server Initialized")
-            .await;
+        tracing::info!("Sway Language Server Initialized");
     }
 
     async fn shutdown(&self) -> jsonrpc::Result<()> {
-        self.log_info_message("Shutting Down the Sway Language Server")
-            .await;
+        tracing::info!("Shutting Down the Sway Language Server");
 
         let _ = self.sessions.iter().map(|item| {
             let session = item.value();

sway-lsp/src/utils/debug.rs

@@ -65,7 +65,7 @@ pub(crate) fn debug_print_ident_and_token(ident: &Ident, token: &Token) {
     let pos = ident.span().start_pos().line_col();
     let line_num = pos.0 as u32;
 
-    tracing::info!(
+    tracing::debug!(
         "line num = {:?} | name: = {:?} | ast_node_type = {:?} | type_id = {:?}",
         line_num,
         ident.as_str(),