From c6d80a9650021fe1373f36b7adada6a9f3fac913 Mon Sep 17 00:00:00 2001 From: "J. Champagne" Date: Sat, 14 Mar 2026 11:56:01 -0400 Subject: [PATCH] log: Add tracing events through core for future debugability. --- crates/pikl-core/src/query/pipeline.rs | 9 ++++++ crates/pikl-core/src/runtime/debounce.rs | 33 +++++++++++++++------ crates/pikl-core/src/runtime/hook.rs | 5 +++- crates/pikl-core/src/runtime/input.rs | 2 ++ crates/pikl-core/src/runtime/json_menu.rs | 7 +++++ crates/pikl-core/src/runtime/menu.rs | 35 ++++++++++++++++++++++- crates/pikl/src/main.rs | 4 ++- 7 files changed, 83 insertions(+), 12 deletions(-) diff --git a/crates/pikl-core/src/query/pipeline.rs b/crates/pikl-core/src/query/pipeline.rs index 7cbc482..9c6bc3e 100644 --- a/crates/pikl-core/src/query/pipeline.rs +++ b/crates/pikl-core/src/query/pipeline.rs @@ -4,6 +4,7 @@ //! caching: unchanged stages keep their results. use serde_json::Value; +use tracing::{debug, trace}; use super::filter::{Filter, FuzzyFilter}; use super::strategy::{self, FilterKind}; @@ -135,11 +136,15 @@ impl FilterPipeline { /// Evaluate all dirty stages in order. Each stage filters /// against the previous stage's cached_indices. fn evaluate(&mut self) { + let _span = tracing::trace_span!("pipeline_evaluate").entered(); for stage_idx in 0..self.stages.len() { if !self.stages[stage_idx].dirty { + trace!(stage_idx, dirty = false, "skipping clean stage"); continue; } + trace!(stage_idx, dirty = true, kind = ?self.stages[stage_idx].kind, "evaluating stage"); + let input_indices: Vec = if stage_idx == 0 { self.items.iter().map(|(idx, _)| *idx).collect() } else { @@ -174,6 +179,7 @@ impl FilterPipeline { } }; + trace!(stage_idx, matched = result.len(), "stage complete"); self.stages[stage_idx].cached_indices = result; self.stages[stage_idx].dirty = false; } @@ -275,6 +281,7 @@ impl FilterPipeline { /// items. Used after replace_all or remove_by_indices /// to rebuild the pipeline from scratch. pub fn rebuild(&mut self, items: &[(usize, &str)]) { + debug!(item_count = items.len(), "pipeline rebuilt"); self.items.clear(); self.item_values.clear(); self.stages.clear(); @@ -288,6 +295,7 @@ impl FilterPipeline { /// Clear all items and stages, then re-push with values. /// Used when field filters need access to item JSON. pub fn rebuild_with_values(&mut self, items: &[(usize, &str, &Value)]) { + debug!(item_count = items.len(), "pipeline rebuilt"); self.items.clear(); self.item_values.clear(); self.stages.clear(); @@ -325,6 +333,7 @@ impl Filter for FilterPipeline { fn set_query(&mut self, query: &str) { self.last_raw_query = query.to_string(); let segments = split_pipeline(query); + debug!(query = %query, stage_count = segments.len(), "pipeline query set"); // Reconcile stages with new segments let mut new_len = segments.len(); diff --git a/crates/pikl-core/src/runtime/debounce.rs b/crates/pikl-core/src/runtime/debounce.rs index 4828e90..5b5b1df 100644 --- a/crates/pikl-core/src/runtime/debounce.rs +++ b/crates/pikl-core/src/runtime/debounce.rs @@ -8,6 +8,7 @@ use std::time::Duration; use tokio::sync::mpsc; use tokio::task::JoinHandle; +use tracing::Instrument; use crate::event::Action; use crate::hook::{HookEvent, HookEventKind, HookHandler, HookResponse}; @@ -76,6 +77,8 @@ impl DebouncedDispatcher { .cloned() .unwrap_or(DebounceMode::None); + tracing::debug!(event_kind = ?kind, mode = ?mode, "dispatching hook event"); + match mode { DebounceMode::None => { self.fire_now(event); @@ -95,11 +98,15 @@ impl DebouncedDispatcher { fn fire_now(&self, event: HookEvent) { let handler = Arc::clone(&self.handler); - tokio::spawn(async move { - if let Err(e) = handler.handle(event) { - tracing::warn!(error = %e, "hook handler error"); + let span = tracing::debug_span!("hook_fire", event_kind = ?event.kind()); + tokio::spawn( + async move { + if let Err(e) = handler.handle(event) { + tracing::warn!(error = %e, "hook handler error"); + } } - }); + .instrument(span), + ); } fn fire_debounced(&mut self, event: HookEvent, delay: Duration, cancel: bool) { @@ -108,19 +115,27 @@ impl DebouncedDispatcher { self.cancel_in_flight(kind); } + let delay_ms = delay.as_millis() as u64; + tracing::debug!(delay_ms, cancel_stale = cancel, "debounced hook scheduled"); + let handler = Arc::clone(&self.handler); - let handle = tokio::spawn(async move { - tokio::time::sleep(delay).await; - if let Err(e) = handler.handle(event) { - tracing::warn!(error = %e, "hook handler error"); + let span = tracing::debug_span!("hook_fire", event_kind = ?kind); + let handle = tokio::spawn( + async move { + tokio::time::sleep(delay).await; + if let Err(e) = handler.handle(event) { + tracing::warn!(error = %e, "hook handler error"); + } } - }); + .instrument(span), + ); self.in_flight.insert(kind, handle); } fn cancel_in_flight(&mut self, kind: HookEventKind) { if let Some(handle) = self.in_flight.remove(&kind) { + tracing::debug!(event_kind = ?kind, "cancelled in-flight hook"); handle.abort(); } } diff --git a/crates/pikl-core/src/runtime/hook.rs b/crates/pikl-core/src/runtime/hook.rs index 03a75f3..eb3135e 100644 --- a/crates/pikl-core/src/runtime/hook.rs +++ b/crates/pikl-core/src/runtime/hook.rs @@ -81,7 +81,10 @@ pub trait HookHandler: Send + Sync { /// tracing. pub fn parse_hook_response(line: &str) -> Option { match serde_json::from_str::(line) { - Ok(resp) => Some(resp), + Ok(resp) => { + tracing::debug!(response = ?resp, "parsed hook response"); + Some(resp) + } Err(e) => { tracing::warn!(line, error = %e, "failed to parse hook response"); None diff --git a/crates/pikl-core/src/runtime/input.rs b/crates/pikl-core/src/runtime/input.rs index 62a78d9..d9881b2 100644 --- a/crates/pikl-core/src/runtime/input.rs +++ b/crates/pikl-core/src/runtime/input.rs @@ -34,6 +34,7 @@ pub fn read_items_sync( } items.push(parse_line(&line, label_key)); } + tracing::debug!(count = items.len(), "items read"); Ok(items) } @@ -51,6 +52,7 @@ pub async fn read_items( } items.push(parse_line(&line, label_key)); } + tracing::debug!(count = items.len(), "items read"); Ok(items) } diff --git a/crates/pikl-core/src/runtime/json_menu.rs b/crates/pikl-core/src/runtime/json_menu.rs index f118a95..1e266c5 100644 --- a/crates/pikl-core/src/runtime/json_menu.rs +++ b/crates/pikl-core/src/runtime/json_menu.rs @@ -24,6 +24,8 @@ pub struct JsonMenu { impl JsonMenu { /// Create a new JSON menu with the given items and label key. pub fn new(items: Vec, label_key: String) -> Self { + let item_count = items.len(); + tracing::debug!(item_count, label_key = %label_key, "json menu created"); let mut filter = FilterPipeline::new(); for (i, item) in items.iter().enumerate() { filter.push_with_value(i, item.label(), &item.value); @@ -139,6 +141,7 @@ impl Menu for JsonMenu { impl MutableMenu for JsonMenu { fn add_raw(&mut self, values: Vec) { + let count = values.len(); for value in values { let idx = self.items.len(); let item = Item::new(value, &self.label_key); @@ -146,9 +149,11 @@ impl MutableMenu for JsonMenu { self.filter.push_with_value(idx, &text, &item.value); self.items.push(item); } + tracing::debug!(count, new_total = self.items.len(), "adding items to menu"); } fn replace_all(&mut self, values: Vec) { + tracing::debug!(count = values.len(), "replacing all menu items"); self.items = values .into_iter() .map(|v| Item::new(v, &self.label_key)) @@ -157,6 +162,7 @@ impl MutableMenu for JsonMenu { } fn remove_by_indices(&mut self, indices: Vec) { + let count = indices.len(); // Sort descending to remove from the end first, // preserving earlier indices. let mut sorted = indices; @@ -167,6 +173,7 @@ impl MutableMenu for JsonMenu { self.items.remove(idx); } } + tracing::debug!(count, remaining = self.items.len(), "items removed from menu"); self.rebuild_pipeline(); } } diff --git a/crates/pikl-core/src/runtime/menu.rs b/crates/pikl-core/src/runtime/menu.rs index e5ee1f8..a6db73f 100644 --- a/crates/pikl-core/src/runtime/menu.rs +++ b/crates/pikl-core/src/runtime/menu.rs @@ -6,6 +6,7 @@ use std::sync::Arc; use tokio::sync::{broadcast, mpsc}; +use tracing::{debug, info, trace}; use crate::debounce::{hook_response_to_action, DebouncedDispatcher}; use crate::error::PiklError; @@ -101,8 +102,19 @@ impl MenuRunner { /// Re-run the filter against all items with the current /// filter text. Updates the viewport with the new count. fn run_filter(&mut self) { + let start = std::time::Instant::now(); self.menu.apply_filter(&self.filter_text); - self.viewport.set_filtered_count(self.menu.filtered_count()); + let matched = self.menu.filtered_count(); + let total = self.menu.total(); + let duration_us = start.elapsed().as_micros() as u64; + debug!( + filter = %self.filter_text, + matched, + total, + duration_us, + "filter applied" + ); + self.viewport.set_filtered_count(matched); } /// Build a [`ViewState`] snapshot from the current filter @@ -144,12 +156,18 @@ impl MenuRunner { /// Send the current view state to all subscribers. fn broadcast_state(&mut self) { let vs = self.build_view_state(); + trace!( + generation = vs.generation, + filtered = vs.total_filtered, + "state broadcast" + ); let _ = self.event_tx.send(MenuEvent::StateChanged(vs)); } /// Emit a hook event through the dispatcher, if one is set. fn emit_hook(&mut self, event: HookEvent) { if let Some(dispatcher) = &mut self.dispatcher { + debug!(hook_event = ?event.kind(), "hook dispatched"); dispatcher.dispatch(event); } } @@ -168,6 +186,7 @@ impl MenuRunner { if let Some(value) = self.menu.serialize_filtered(current).cloned() && let Some(orig_idx) = current_orig { + trace!(cursor = current, original_index = orig_idx, "hover changed"); self.emit_hook(HookEvent::Hover { item: value, index: orig_idx, @@ -181,6 +200,7 @@ impl MenuRunner { pub fn apply_action(&mut self, action: Action) -> ActionOutcome { match action { Action::UpdateFilter(text) => { + debug!(filter = %text, "filter updated"); self.filter_text = Arc::from(text); self.run_filter(); ActionOutcome::Broadcast @@ -237,6 +257,7 @@ impl MenuRunner { } Action::Cancel => ActionOutcome::Cancelled, Action::Resize { height } => { + trace!(height, "viewport resized"); self.viewport.set_height(height as usize); ActionOutcome::Broadcast } @@ -249,15 +270,18 @@ impl MenuRunner { ActionOutcome::Broadcast } Action::SetMode(m) => { + debug!(mode = ?m, "mode changed"); self.mode = m; ActionOutcome::Broadcast } Action::AddItems(values) => { + debug!(count = values.len(), "items added"); self.menu.add_raw(values); self.run_filter(); ActionOutcome::Broadcast } Action::ReplaceItems(values) => { + debug!(count = values.len(), "items replaced"); // Smart cursor: try to keep selection on the same original item. let cursor = self.viewport.cursor(); let old_value = self.menu.serialize_filtered(cursor).cloned(); @@ -282,6 +306,7 @@ impl MenuRunner { ActionOutcome::Broadcast } Action::RemoveItems(indices) => { + debug!(count = indices.len(), "items removed"); self.menu.remove_by_indices(indices); self.run_filter(); self.viewport.clamp(); @@ -319,6 +344,10 @@ impl MenuRunner { self.run_filter(); self.broadcast_state(); + let total_items = self.menu.total(); + let filtered = self.menu.filtered_count(); + info!(total_items, filtered, "menu opened"); + // Emit Open event self.emit_hook(HookEvent::Open); @@ -339,6 +368,7 @@ impl MenuRunner { self.check_cursor_hover(); } ActionOutcome::Selected { value, index } => { + info!(index, "item selected"); // Emit Select event self.emit_hook(HookEvent::Select { item: value.clone(), @@ -354,6 +384,7 @@ impl MenuRunner { let values: Vec = items.iter().map(|(v, _)| v.clone()).collect(); let count = values.len(); + info!(count, "quicklist returned"); self.emit_hook(HookEvent::Quicklist { items: values.clone(), count, @@ -366,6 +397,7 @@ impl MenuRunner { return Ok(MenuResult::Quicklist { items }); } ActionOutcome::Cancelled => { + info!("menu cancelled"); self.emit_hook(HookEvent::Cancel); self.emit_hook(HookEvent::Close); @@ -373,6 +405,7 @@ impl MenuRunner { return Ok(MenuResult::Cancelled); } ActionOutcome::Closed => { + info!("menu closed by hook"); self.emit_hook(HookEvent::Close); let _ = self.event_tx.send(MenuEvent::Cancelled); diff --git a/crates/pikl/src/main.rs b/crates/pikl/src/main.rs index 5f5ac1c..68d3c01 100644 --- a/crates/pikl/src/main.rs +++ b/crates/pikl/src/main.rs @@ -123,7 +123,9 @@ struct Cli { fn main() { // Initialize tracing from RUST_LOG env var - tracing_subscriber::fmt::init(); + tracing_subscriber::fmt() + .with_writer(std::io::stderr) + .init(); let cli = Cli::parse();