feat(dev): add tracing feature

9 files changed, 157 insertions, 8 deletions

diff --git a/.gitignore b/.gitignore
index 0e71e34..cf6aef5 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,2 +1,3 @@
 /target
 .direnv/
+.zjstatus.log
diff --git a/Cargo.lock b/Cargo.lock
index f95f39e..b12971d 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -2109,6 +2109,16 @@ dependencies = [
 ]
 
 [[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
+[[package]]
 name = "num-derive"
 version = "0.3.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2223,6 +2233,12 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e2355d85b9a3786f481747ced0e0ff2ba35213a1f9bd406ed906554d7af805a1"
 
 [[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
+[[package]]
 name = "owo-colors"
 version = "3.5.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -2990,6 +3006,15 @@ dependencies = [
 ]
 
 [[package]]
+name = "sharded-slab"
+version = "0.1.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
+dependencies = [
+ "lazy_static",
+]
+
+[[package]]
 name = "shellexpand"
 version = "3.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -3413,6 +3438,16 @@ dependencies = [
 ]
 
 [[package]]
+name = "thread_local"
+version = "1.1.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+]
+
+[[package]]
 name = "time"
 version = "0.2.27"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -3511,6 +3546,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
 dependencies = [
  "once_cell",
+ "valuable",
 ]
 
 [[package]]
@@ -3524,6 +3560,31 @@ dependencies = [
 ]
 
 [[package]]
+name = "tracing-log"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
+dependencies = [
+ "log",
+ "once_cell",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
+dependencies = [
+ "nu-ansi-term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
+]
+
+[[package]]
 name = "typemap-ors"
 version = "1.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -3646,6 +3707,12 @@ dependencies = [
 ]
 
 [[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
+[[package]]
 name = "value-bag"
 version = "1.7.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -4150,6 +4217,8 @@ dependencies = [
  "criterion",
  "lazy_static",
  "regex",
+ "tracing",
+ "tracing-subscriber",
  "uuid",
  "zellij-tile",
 ]
diff --git a/Cargo.toml b/Cargo.toml
index 907c4a9..f0956a1 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -13,6 +13,7 @@ bench = false
 
 [features]
 bench = []
+tracing = []
 
 [dependencies]
 zellij-tile = "0.39.0"
@@ -25,9 +26,13 @@ uuid = { version = "1.6.1", features = ["v4"] }
 lazy_static = "1.4.0"
 cached = { version = "0.46.1", features = ["wasm"] }
 console = "0.15.8"
+tracing-subscriber = "0.3.18"
+tracing = "0.1.40"
 
 [dev-dependencies]
-criterion = { version = "0.5.1", default-features = false, features = ["html_reports"] }
+criterion = { version = "0.5.1", default-features = false, features = [
+    "html_reports",
+] }
 
 [[bench]]
 name = "benches"
diff --git a/justfile b/justfile
index cb5afe3..fed5f4b 100644
--- a/justfile
+++ b/justfile
@@ -6,7 +6,7 @@ bench:
     | xargs -I{} wasmtime --dir $PWD/target::target {} --bench --color=always
 
 build:
-  cargo build
+  cargo build --features tracing
 
 run: build
   zellij -l ./plugin-dev-workspace.kdl -s zjstatus-dev
diff --git a/src/bin/zjstatus.rs b/src/bin/zjstatus.rs
index 07c38a0..1f0de0e 100644
--- a/src/bin/zjstatus.rs
+++ b/src/bin/zjstatus.rs
@@ -8,10 +8,13 @@ use widgets::{
     tabs::TabsWidget,
     widget::Widget,
 };
+
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
+
 use zellij_tile::prelude::*;
 
 use chrono::Local;
-use std::{collections::BTreeMap, sync::Arc, usize};
+use std::{collections::BTreeMap, fs::File, sync::Arc, usize};
 use uuid::Uuid;
 
 use zjstatus::{
@@ -31,8 +34,25 @@ struct State {
 #[cfg(not(test))]
 register_plugin!(State);
 
+#[cfg(feature = "tracing")]
+fn init_tracing() {
+    let file = File::create(".zjstatus.log");
+    let file = match file {
+        Ok(file) => file,
+        Err(error) => panic!("Error: {:?}", error),
+    };
+    let debug_log = tracing_subscriber::fmt::layer().with_writer(Arc::new(file));
+
+    tracing_subscriber::registry().with(debug_log).init();
+
+    tracing::info!("tracing initialized");
+}
+
 impl ZellijPlugin for State {
     fn load(&mut self, configuration: BTreeMap<String, String>) {
+        #[cfg(feature = "tracing")]
+        init_tracing();
+
         // we need the ReadApplicationState permission to receive the ModeUpdate and TabUpdate
         // events
         // we need the RunCommands permission to run "cargo test" in a floating window
@@ -41,6 +61,7 @@ impl ZellijPlugin for State {
             PermissionType::ChangeApplicationState,
             PermissionType::RunCommands,
         ]);
+
         subscribe(&[
             EventType::Mouse,
             EventType::ModeUpdate,
@@ -70,11 +91,16 @@ impl ZellijPlugin for State {
         };
     }
 
+    #[tracing::instrument(skip_all, fields(event_type))]
     fn update(&mut self, event: Event) -> bool {
         let mut should_render = false;
         match event {
             Event::Mouse(mouse_info) => {
+                tracing::Span::current().record("event_type", "Event::Mouse");
+                tracing::debug!(mouse = ?mouse_info);
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
 
@@ -85,7 +111,11 @@ impl ZellijPlugin for State {
                 );
             }
             Event::ModeUpdate(mode_info) => {
+                tracing::Span::current().record("event_type", "Event::ModeUpdate");
+                tracing::debug!(mode = ?mode_info.mode);
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
 
@@ -94,7 +124,11 @@ impl ZellijPlugin for State {
                 should_render = true;
             }
             Event::PaneUpdate(pane_info) => {
+                tracing::Span::current().record("event_type", "Event::PaneUpdate");
+                tracing::debug!(pane_count = ?pane_info.panes.len());
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
 
@@ -111,12 +145,23 @@ impl ZellijPlugin for State {
 
                 should_render = true;
             }
-            Event::PermissionRequestResult(_result) => {
+            Event::PermissionRequestResult(result) => {
+                tracing::Span::current().record("event_type", "Event::PermissionRequestResult");
+                tracing::debug!(result = ?result);
                 set_selectable(false);
                 self.got_permissions = true;
             }
             Event::RunCommandResult(exit_code, stdout, stderr, context) => {
+                tracing::Span::current().record("event_type", "Event::RunCommandResult");
+                tracing::debug!(
+                    exit_code = ?exit_code,
+                    stdout = ?String::from_utf8(stdout.clone()),
+                    stderr = ?String::from_utf8(stderr.clone()),
+                    context = ?context
+                );
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
                 self.state.cache_mask = UpdateEventMask::Command as u8;
@@ -144,7 +189,10 @@ impl ZellijPlugin for State {
                 }
             }
             Event::SessionUpdate(session_info, _) => {
+                tracing::Span::current().record("event_type", "Event::SessionUpdate");
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
 
@@ -166,7 +214,11 @@ impl ZellijPlugin for State {
                 should_render = true;
             }
             Event::TabUpdate(tab_info) => {
+                tracing::Span::current().record("event_type", "Event::TabUpdate");
+                tracing::debug!(tab_count = ?tab_info.len());
+
                 if !self.got_permissions {
+                    tracing::info!("no permissions");
                     return false;
                 }
 
@@ -216,5 +268,7 @@ fn register_widgets(configuration: &BTreeMap<String, String>) -> BTreeMap<String
     );
     widget_map.insert("tabs".to_owned(), Arc::new(TabsWidget::new(configuration)));
 
+    tracing::debug!("registered widgets: {:?}", widget_map.keys());
+
     widget_map
 }
diff --git a/src/border.rs b/src/border.rs
index c3f0419..f1720db 100644
--- a/src/border.rs
+++ b/src/border.rs
@@ -4,13 +4,14 @@ use crate::render::FormattedPart;
 
 const DEFAULT_CHAR: &str = "─";
 
-#[derive(Default, PartialEq)]
+#[derive(Default, PartialEq, Debug)]
 pub enum BorderPosition {
     #[default]
     Top,
     Bottom,
 }
 
+#[derive(Debug)]
 pub struct BorderConfig {
     pub enabled: bool,
     pub char: String,
diff --git a/src/config.rs b/src/config.rs
index 7b2ac47..ec1efed 100644
--- a/src/config.rs
+++ b/src/config.rs
@@ -44,7 +44,7 @@ pub fn event_mask_from_widget_name(name: &str) -> u8 {
     }
 }
 
-#[derive(Default)]
+#[derive(Default, Debug)]
 pub struct ModuleConfig {
     pub left_parts_config: String,
     pub left_parts: Vec<FormattedPart>,
@@ -326,6 +326,7 @@ impl ModuleConfig {
         )
     }
 
+    #[tracing::instrument(skip_all)]
     fn get_spacer_left(&self, output_left: &str, output_center: &str, cols: usize) -> String {
         let text_count = console::measure_text_width(output_left)
             + (console::measure_text_width(output_center) as f32 / 2.0).floor() as usize;
@@ -336,10 +337,11 @@ impl ModuleConfig {
         // count of 0 on tab creation
         let space_count = center_pos.saturating_sub(text_count);
 
-        eprintln!("space_count: {:?}", space_count);
+        tracing::debug!("space_count: {:?}", space_count);
         self.format_space.format_string(&" ".repeat(space_count))
     }
 
+    #[tracing::instrument(skip_all)]
     fn get_spacer_right(&self, output_right: &str, output_center: &str, cols: usize) -> String {
         let text_count = console::measure_text_width(output_right)
             + (console::measure_text_width(output_center) as f32 / 2.0).ceil() as usize;
@@ -350,6 +352,7 @@ impl ModuleConfig {
         // count of 0 on tab creation
         let space_count = center_pos.saturating_sub(text_count);
 
+        tracing::debug!("space_count: {:?}", space_count);
         self.format_space.format_string(&" ".repeat(space_count))
     }
 
diff --git a/src/render.rs b/src/render.rs
index c407a6a..cef70d4 100644
--- a/src/render.rs
+++ b/src/render.rs
@@ -121,15 +121,19 @@ impl FormattedPart {
         )
     }
 
+    #[tracing::instrument(skip_all)]
     pub fn format_string_with_widgets(
         &mut self,
         widgets: &BTreeMap<String, Arc<dyn Widget>>,
         state: &ZellijState,
     ) -> String {
         let skip_cache = self.cache_mask & UpdateEventMask::Always as u8 != 0;
+        
         if !skip_cache && self.cache_mask & state.cache_mask == 0 && !self.cache.is_empty() {
+            tracing::debug!(msg = "hit",  typ = "format_string", format = self.content);
             return self.cached_content.to_owned();
         }
+        tracing::debug!(msg = "miss",  typ = "format_string", format = self.content);
 
         let mut output = self.content.clone();
 
@@ -143,12 +147,22 @@ impl FormattedPart {
             }
 
             let widget_mask = event_mask_from_widget_name(widget_key_name);
-            if !skip_cache && widget_mask & state.cache_mask == 0 {
+            let skip_widget_cache = widget_mask & UpdateEventMask::Always as u8 != 0;
+            if !skip_widget_cache && widget_mask & state.cache_mask == 0 {
                 if let Some(res) = self.cache.get(widget_key) {
+                    tracing::debug!(msg = "hit",  typ = "widget", widget = widget_key);
                     output = output.replace(match_name, res);
                     continue;
                 }
             }
+            
+            tracing::debug!(
+                msg = "miss",  
+                typ = "widget", 
+                widget = widget_key, 
+                mask = widget_mask & state.cache_mask,
+                skip_cache = skip_cache,
+            );
 
             let result = match widgets.get(widget_key_name) {
                 Some(widget) => widget.process(widget_key, state),
diff --git a/src/widgets/command.rs b/src/widgets/command.rs
index b842559..05bc94a 100644
--- a/src/widgets/command.rs
+++ b/src/widgets/command.rs
@@ -121,6 +121,7 @@ fn render_dynamic_formatted_content(content: &str) -> String {
         .join("")
 }
 
+#[tracing::instrument(skip(command_config, state))]
 fn run_command_if_needed(command_config: CommandConfig, name: &str, state: &ZellijState) {
     let ts = Local::now();
     let last_run = get_timestamp_from_event_or_default(name, state, command_config.interval);
@@ -135,6 +136,7 @@ fn run_command_if_needed(command_config: CommandConfig, name: &str, state: &Zell
 
         #[allow(unused_variables)]
         let command = commandline_parser(&command_config.command);
+        tracing::debug!("Running command: {:?}", command);
         #[cfg(not(feature = "bench"))]
         run_command(
             &command.iter().map(|x| x.as_str()).collect::<Vec<&str>>(),