re-work to use logging infrastructure

cli/logger.rs

@@ -0,0 +1,100 @@
+// Copyright 2018-2021 the Deno authors. All rights reserved. MIT license.
+
+use std::io::Write;
+use std::sync::atomic::AtomicBool;
+use std::sync::atomic::Ordering;
+use std::sync::Arc;
+
+struct CliLogger {
+  logger: env_logger::Logger,
+  lsp_debug_flag: Arc<AtomicBool>,
+}
+
+impl CliLogger {
+  pub fn new(
+    logger: env_logger::Logger,
+    lsp_debug_flag: Arc<AtomicBool>,
+  ) -> Self {
+    Self {
+      logger,
+      lsp_debug_flag,
+    }
+  }
+
+  pub fn filter(&self) -> log::LevelFilter {
+    self.logger.filter()
+  }
+}
+
+impl log::Log for CliLogger {
+  fn enabled(&self, metadata: &log::Metadata) -> bool {
+    if metadata.target() == "deno::lsp::performance"
+      && metadata.level() == log::Level::Debug
+    {
+      self.lsp_debug_flag.load(Ordering::Relaxed)
+    } else {
+      self.logger.enabled(metadata)
+    }
+  }
+
+  fn log(&self, record: &log::Record) {
+    if self.enabled(record.metadata()) {
+      self.logger.log(record);
+    }
+  }
+
+  fn flush(&self) {
+    self.logger.flush();
+  }
+}
+
+pub(crate) fn init(
+  maybe_level: Option<log::Level>,
+  lsp_debug_flag: Arc<AtomicBool>,
+) {
+  let log_level = maybe_level.unwrap_or(log::Level::Info);
+  let logger = env_logger::Builder::from_env(
+    env_logger::Env::default()
+      .default_filter_or(log_level.to_level_filter().to_string()),
+  )
+  // https://github.com/denoland/deno/issues/6641
+  .filter_module("rustyline", log::LevelFilter::Off)
+  // wgpu crates (gfx_backend), have a lot of useless INFO and WARN logs
+  .filter_module("wgpu", log::LevelFilter::Error)
+  .filter_module("gfx", log::LevelFilter::Error)
+  // used to make available the lsp_debug which is then filtered out at runtime
+  // in the cli logger
+  .filter_module("deno::lsp::performance", log::LevelFilter::Debug)
+  .format(|buf, record| {
+    let mut target = record.target().to_string();
+    if let Some(line_no) = record.line() {
+      target.push(':');
+      target.push_str(&line_no.to_string());
+    }
+    if record.level() <= log::Level::Info
+      || (record.target() == "deno::lsp::performance"
+        && record.level() == log::Level::Debug)
+    {
+      // Print ERROR, WARN, INFO and lsp_debug logs as they are
+      writeln!(buf, "{}", record.args())
+    } else {
+      // Add prefix to DEBUG or TRACE logs
+      writeln!(
+        buf,
+        "{} RS - {} - {}",
+        record.level(),
+        target,
+        record.args()
+      )
+    }
+  })
+  .build();
+
+  let cli_logger = CliLogger::new(logger, lsp_debug_flag);
+  let max_level = cli_logger.filter();
+  let r = log::set_boxed_logger(Box::new(cli_logger));
+  if r.is_ok() {
+    log::set_max_level(max_level);
+  }
+  r.expect("Could not install logger.");
+}

cli/lsp/language_server.rs

@@ -25,6 +25,8 @@ use std::collections::HashMap;
 use std::env;
 use std::path::PathBuf;
 use std::rc::Rc;
+use std::sync::atomic::AtomicBool;
+use std::sync::atomic::Ordering;
 use std::sync::Arc;
 use tokio::fs;
 
@@ -89,6 +91,7 @@ pub(crate) struct Inner {
   client: Client,
   /// Configuration information.
   config: Config,
+  debug_flag: Arc<AtomicBool>,
   diagnostics_server: diagnostics::DiagnosticsServer,
   /// The "in-memory" documents in the editor which can be updated and changed.
   documents: DocumentCache,
@@ -118,13 +121,16 @@ pub(crate) struct Inner {
 }
 
 impl LanguageServer {
-  pub fn new(client: Client) -> Self {
-    Self(Arc::new(tokio::sync::Mutex::new(Inner::new(client))))
+  pub fn new(client: Client, lsp_debug_flag: Arc<AtomicBool>) -> Self {
+    Self(Arc::new(tokio::sync::Mutex::new(Inner::new(
+      client,
+      lsp_debug_flag,
+    ))))
   }
 }
 
 impl Inner {
-  fn new(client: Client) -> Self {
+  fn new(client: Client, debug_flag: Arc<AtomicBool>) -> Self {
     let maybe_custom_root = env::var("DENO_DIR").map(String::into).ok();
     let dir = deno_dir::DenoDir::new(maybe_custom_root)
       .expect("could not access DENO_DIR");
@@ -141,6 +147,7 @@ impl Inner {
       assets: Default::default(),
       client,
       config: Default::default(),
+      debug_flag,
       diagnostics_server,
       documents: Default::default(),
       maybe_config_uri: Default::default(),
@@ -351,10 +358,16 @@ impl Inner {
     Ok(())
   }
 
-  pub fn update_performance(&mut self) {
+  pub fn update_debug_flag(&self) -> bool {
     self
-      .performance
-      .do_logging(self.config.settings.internal_debug);
+      .debug_flag
+      .compare_exchange(
+        !self.config.settings.internal_debug,
+        self.config.settings.internal_debug,
+        Ordering::Acquire,
+        Ordering::Relaxed,
+      )
+      .is_ok()
   }
 
   async fn update_registries(&mut self) -> Result<(), AnyError> {
@@ -510,7 +523,7 @@ impl Inner {
       config.update_capabilities(&params.capabilities);
     }
 
-    self.update_performance();
+    self.update_debug_flag();
     if let Err(err) = self.update_tsconfig().await {
       warn!("Updating tsconfig has errored: {}", err);
     }
@@ -678,7 +691,7 @@ impl Inner {
       if let Err(err) = self.config.update(config) {
         error!("failed to update settings: {}", err);
       }
-      self.update_performance();
+      self.update_debug_flag();
       if let Err(err) = self.update_import_map().await {
         self
           .client
@@ -2611,7 +2624,9 @@ mod tests {
 
   impl LspTestHarness {
     pub fn new(requests: Vec<LspTestHarnessRequest>) -> Self {
-      let (service, _) = LspService::new(LanguageServer::new);
+      let lsp_debug_flag = Arc::new(AtomicBool::new(false));
+      let (service, _) =
+        LspService::new(|client| LanguageServer::new(client, lsp_debug_flag));
       let service = Spawn::new(service);
       Self { requests, service }
     }

cli/lsp/mod.rs

@@ -3,6 +3,8 @@
 use deno_core::error::AnyError;
 use lspower::LspService;
 use lspower::Server;
+use std::sync::atomic::AtomicBool;
+use std::sync::Arc;
 
 mod analysis;
 mod capabilities;
@@ -20,12 +22,13 @@ mod text;
 mod tsc;
 mod urls;
 
-pub async fn start() -> Result<(), AnyError> {
+pub async fn start(lsp_debug_flag: Arc<AtomicBool>) -> Result<(), AnyError> {
   let stdin = tokio::io::stdin();
   let stdout = tokio::io::stdout();
 
-  let (service, messages) =
-    LspService::new(language_server::LanguageServer::new);
+  let (service, messages) = LspService::new(|client| {
+    language_server::LanguageServer::new(client, lsp_debug_flag)
+  });
   Server::new(stdin, stdout)
     .interleave(messages)
     .serve(service)

cli/lsp/performance.rs

@@ -3,7 +3,7 @@
 use deno_core::serde::Deserialize;
 use deno_core::serde::Serialize;
 use deno_core::serde_json::json;
-use log::info;
+use log::debug;
 use std::cmp;
 use std::collections::HashMap;
 use std::collections::VecDeque;
@@ -74,7 +74,6 @@ impl From<PerformanceMark> for PerformanceMeasure {
 #[derive(Debug, Clone)]
 pub struct Performance {
   counts: Arc<Mutex<HashMap<String, u32>>>,
-  logging_enabled: bool,
   max_size: usize,
   measures: Arc<Mutex<VecDeque<PerformanceMeasure>>>,
 }
@@ -83,7 +82,6 @@ impl Default for Performance {
   fn default() -> Self {
     Self {
       counts: Default::default(),
-      logging_enabled: false,
       max_size: 1_000,
       measures: Default::default(),
     }
@@ -133,10 +131,6 @@ impl Performance {
       .collect()
   }
 
-  pub fn do_logging(&mut self, enable: bool) {
-    self.logging_enabled = enable;
-  }
-
   /// Marks the start of a measurement which returns a performance mark
   /// structure, which is then passed to `.measure()` to finalize the duration
   /// and add it to the internal buffer.
@@ -149,22 +143,20 @@ impl Performance {
     let mut counts = self.counts.lock().unwrap();
     let count = counts.entry(name.to_string()).or_insert(0);
     *count += 1;
-    if self.logging_enabled {
-      let msg = if let Some(args) = maybe_args {
-        json!({
-          "type": "mark",
-          "name": name,
-          "count": count,
-          "args": args,
-        })
-      } else {
-        json!({
-          "type": "mark",
-          "name": name,
-        })
-      };
-      info!("{},", msg);
-    }
+    let msg = if let Some(args) = maybe_args {
+      json!({
+        "type": "mark",
+        "name": name,
+        "count": count,
+        "args": args,
+      })
+    } else {
+      json!({
+        "type": "mark",
+        "name": name,
+      })
+    };
+    debug!("{},", msg);
     PerformanceMark {
       name: name.to_string(),
       count: *count,
@@ -177,17 +169,15 @@ impl Performance {
   /// measurement to the internal buffer.
   pub fn measure(&self, mark: PerformanceMark) -> Duration {
     let measure = PerformanceMeasure::from(mark);
-    if self.logging_enabled {
-      info!(
-        "{},",
-        json!({
-          "type": "measure",
-          "name": measure.name,
-          "count": measure.count,
-          "duration": measure.duration.as_millis() as u32,
-        })
-      );
-    }
+    debug!(
+      "{},",
+      json!({
+        "type": "measure",
+        "name": measure.name,
+        "count": measure.count,
+        "duration": measure.duration.as_millis() as u32,
+      })
+    );
     let duration = measure.duration;
     let mut measures = self.measures.lock().unwrap();
     measures.push_front(measure);