chore: improve logs (#266)

* yes yes and yes

* use bunyan

* add comment

* format

* loglvl comment

* merge

* woops

* import

* ok

* remove log kind env

* default debug

* comment

* add hierarchical layer

Author: juleswritescode

Cargo.lock

@@ -41,17 +41,18 @@ similar                  = "2.6.0"
 smallvec                 = { version = "1.13.2", features = ["union", "const_new", "serde"] }
 strum                    = { version = "0.27.1", features = ["derive"] }
 # this will use tokio if available, otherwise async-std
-sqlx               = { version = "0.8.2", features = ["runtime-tokio", "runtime-async-std", "postgres", "json"] }
-syn                = "1.0.109"
-termcolor          = "1.4.1"
-test-log           = "0.2.17"
-tokio              = { version = "1.40.0", features = ["full"] }
-tower-lsp          = "0.20.0"
-tracing            = { version = "0.1.40", default-features = false, features = ["std"] }
-tracing-subscriber = "0.3.18"
-tree-sitter        = "0.20.10"
-tree_sitter_sql    = { path = "./lib/tree_sitter_sql", version = "0.0.0" }
-unicode-width      = "0.1.12"
+sqlx                     = { version = "0.8.2", features = ["runtime-tokio", "runtime-async-std", "postgres", "json"] }
+syn                      = "1.0.109"
+termcolor                = "1.4.1"
+test-log                 = "0.2.17"
+tokio                    = { version = "1.40.0", features = ["full"] }
+tower-lsp                = "0.20.0"
+tracing                  = { version = "0.1.40", default-features = false, features = ["std"] }
+tracing-bunyan-formatter = { version = "0.3.10 " }
+tracing-subscriber       = "0.3.18"
+tree-sitter              = "0.20.10"
+tree_sitter_sql          = { path = "./lib/tree_sitter_sql", version = "0.0.0" }
+unicode-width            = "0.1.12"
 
 # postgres specific crates
 pgt_analyse                = { path = "./crates/pgt_analyse", version = "0.0.0" }

Cargo.toml

@@ -37,8 +37,9 @@ serde_json               = { workspace = true }
 tokio                    = { workspace = true, features = ["io-std", "io-util", "net", "time", "rt", "sync", "rt-multi-thread", "macros"] }
 tracing                  = { workspace = true }
 tracing-appender         = "0.2.3"
+tracing-bunyan-formatter = { workspace = true }
 tracing-subscriber       = { workspace = true, features = ["env-filter", "json"] }
-tracing-tree             = "0.4.0"
+tracing-tree             = { version = "0.4.0", features = ["time"] }
 
 [target.'cfg(unix)'.dependencies]
 libc  = "0.2.161"

crates/pgt_cli/Cargo.toml

@@ -61,6 +61,7 @@ pub struct CliOptions {
     pub reporter: CliReporter,
 
     #[bpaf(
+        env("PGT_LOG_LEVEL"),
         long("log-level"),
         argument("none|debug|info|warn|error"),
         fallback(LoggingLevel::default()),

crates/pgt_cli/src/cli_options.rs

@@ -11,13 +11,13 @@ use tokio::runtime::Runtime;
 use tracing::subscriber::Interest;
 use tracing::{Instrument, Metadata, debug_span, metadata::LevelFilter};
 use tracing_appender::rolling::Rotation;
+use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
 use tracing_subscriber::{
-    Layer,
     layer::{Context, Filter},
     prelude::*,
     registry,
 };
-use tracing_tree::HierarchicalLayer;
+use tracing_tree::{HierarchicalLayer, time::UtcDateTime};
 
 pub(crate) fn start(
     session: CliSession,
@@ -78,8 +78,10 @@ pub(crate) fn run_server(
     config_path: Option<PathBuf>,
     log_path: Option<PathBuf>,
     log_file_name_prefix: Option<String>,
+    log_level: Option<String>,
+    log_kind: Option<String>,
 ) -> Result<(), CliDiagnostic> {
-    setup_tracing_subscriber(log_path, log_file_name_prefix);
+    setup_tracing_subscriber(log_path, log_file_name_prefix, log_level, log_kind);
 
     let rt = Runtime::new()?;
     let factory = ServerFactory::new(stop_on_disconnect);
@@ -181,28 +183,54 @@ async fn start_lsp_proxy(
 /// is written to log files rotated on a hourly basis (in
 /// `pgt-logs/server.log.yyyy-MM-dd-HH` files inside the system temporary
 /// directory)
-fn setup_tracing_subscriber(log_path: Option<PathBuf>, log_file_name_prefix: Option<String>) {
+fn setup_tracing_subscriber(
+    log_path: Option<PathBuf>,
+    log_file_name_prefix: Option<String>,
+    log_level: Option<String>,
+    log_kind: Option<String>,
+) {
     let pgt_log_path = log_path.unwrap_or(pgt_fs::ensure_cache_dir().join("pgt-logs"));
+
     let appender_builder = tracing_appender::rolling::RollingFileAppender::builder();
+
     let file_appender = appender_builder
         .filename_prefix(log_file_name_prefix.unwrap_or(String::from("server.log")))
         .max_log_files(7)
         .rotation(Rotation::HOURLY)
         .build(pgt_log_path)
         .expect("Failed to start the logger for the daemon.");
 
-    registry()
-        .with(
-            HierarchicalLayer::default()
-                .with_indent_lines(true)
-                .with_indent_amount(2)
-                .with_bracketed_fields(true)
-                .with_targets(true)
-                .with_ansi(false)
-                .with_writer(file_appender)
-                .with_filter(LoggingFilter),
-        )
-        .init();
+    let filter = PgtLoggingFilter::from(log_level);
+
+    let log_kind = log_kind.unwrap_or("hierarchical".into());
+
+    match log_kind.as_str() {
+        "bunyan" => {
+            registry()
+                .with(JsonStorageLayer)
+                .with(
+                    BunyanFormattingLayer::new("pgt_logs".into(), file_appender)
+                        .with_filter(filter),
+                )
+                .init();
+        }
+
+        _ => registry()
+            .with(
+                HierarchicalLayer::default()
+                    .with_indent_lines(true)
+                    .with_indent_amount(2)
+                    .with_bracketed_fields(true)
+                    .with_targets(true)
+                    .with_ansi(false)
+                    .with_timer(UtcDateTime {
+                        higher_precision: false,
+                    })
+                    .with_writer(file_appender)
+                    .with_filter(filter),
+            )
+            .init(),
+    }
 }
 
 pub fn default_pgt_log_path() -> PathBuf {
@@ -212,22 +240,34 @@ pub fn default_pgt_log_path() -> PathBuf {
     }
 }
 
-/// Tracing filter enabling:
-/// - All spans and events at level info or higher
-/// - All spans and events at level debug in crates whose name starts with `pgt`
-struct LoggingFilter;
+/// Tracing Filter with two rules:
+/// For all crates starting with pgt*, use `PGT_LOG_LEVEL` or CLI option or "info" as default
+/// For all other crates, use "info"
+struct PgtLoggingFilter(LevelFilter);
 
-/// Tracing filter used for spans emitted by `pgt*` crates
-const SELF_FILTER: LevelFilter = if cfg!(debug_assertions) {
-    LevelFilter::TRACE
-} else {
-    LevelFilter::DEBUG
-};
+impl From<Option<String>> for PgtLoggingFilter {
+    fn from(value: Option<String>) -> Self {
+        Self(
+            value
+                .map(|lv_filter| match lv_filter.as_str() {
+                    "trace" => LevelFilter::TRACE,
+                    "debug" => LevelFilter::DEBUG,
+                    "info" => LevelFilter::INFO,
+                    "warn" => LevelFilter::WARN,
+                    "error" => LevelFilter::ERROR,
+                    "off" => LevelFilter::OFF,
+
+                    _ => LevelFilter::INFO,
+                })
+                .unwrap_or(LevelFilter::INFO),
+        )
+    }
+}
 
-impl LoggingFilter {
+impl PgtLoggingFilter {
     fn is_enabled(&self, meta: &Metadata<'_>) -> bool {
         let filter = if meta.target().starts_with("pgt") {
-            SELF_FILTER
+            self.0
         } else {
             LevelFilter::INFO
         };
@@ -236,7 +276,7 @@ impl LoggingFilter {
     }
 }
 
-impl<S> Filter<S> for LoggingFilter {
+impl<S> Filter<S> for PgtLoggingFilter {
     fn enabled(&self, meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool {
         self.is_enabled(meta)
     }
@@ -250,6 +290,6 @@ impl<S> Filter<S> for LoggingFilter {
     }
 
     fn max_level_hint(&self) -> Option<LevelFilter> {
-        Some(SELF_FILTER)
+        Some(self.0)
     }
 }

crates/pgt_cli/src/commands/daemon.rs

@@ -151,6 +151,7 @@ pub enum PgtCommand {
             display_fallback
         )]
         log_prefix_name: String,
+
         /// Allows to change the folder where logs are stored.
         #[bpaf(
             env("PGT_LOG_PATH"),
@@ -161,6 +162,24 @@ pub enum PgtCommand {
         )]
         log_path: PathBuf,
 
+        /// Allows to change the log level. Default is debug. This will only affect "pgt*" crates. All others are logged with info level.
+        #[bpaf(
+            env("PGT_LOG_LEVEL"),
+            long("log-level"),
+            argument("trace|debug|info|warn|error|none"),
+            fallback(String::from("debug"))
+        )]
+        log_level: String,
+
+        /// Allows to change the logging format kind. Default is hierarchical.
+        #[bpaf(
+            env("PGT_LOG_KIND"),
+            long("log-kind"),
+            argument("hierarchical|bunyan"),
+            fallback(String::from("hierarchical"))
+        )]
+        log_kind: String,
+
         #[bpaf(long("stop-on-disconnect"), hide_usage)]
         stop_on_disconnect: bool,
         /// Allows to set a custom file path to the configuration file,

crates/pgt_cli/src/commands/mod.rs

@@ -105,11 +105,15 @@ impl<'app> CliSession<'app> {
                 config_path,
                 log_path,
                 log_prefix_name,
+                log_level,
+                log_kind,
             } => commands::daemon::run_server(
                 stop_on_disconnect,
                 config_path,
                 Some(log_path),
                 Some(log_prefix_name),
+                Some(log_level),
+                Some(log_kind),
             ),
             PgtCommand::PrintSocket => commands::daemon::print_socket(),
         };

crates/pgt_cli/src/lib.rs

@@ -11,6 +11,7 @@ pub fn setup_cli_subscriber(level: LoggingLevel, kind: LoggingKind) {
     if level == LoggingLevel::None {
         return;
     }
+
     let format = tracing_subscriber::fmt::layer()
         .with_level(true)
         .with_target(false)