log: Add tracing events through core for future debugability.

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<usize> = 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();

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 {
+        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 {
+        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();
         }
     }

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<HookResponse> {
     match serde_json::from_str::<HookResponse>(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

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)
 }
 

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<Item>, 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<serde_json::Value>) {
+        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<serde_json::Value>) {
+        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<usize>) {
+        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();
     }
 }

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<M: MutableMenu> MenuRunner<M> {
     /// 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<M: MutableMenu> MenuRunner<M> {
     /// 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<M: MutableMenu> MenuRunner<M> {
             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<M: MutableMenu> MenuRunner<M> {
     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<M: MutableMenu> MenuRunner<M> {
             }
             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<M: MutableMenu> MenuRunner<M> {
                 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<M: MutableMenu> MenuRunner<M> {
                 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<M: MutableMenu> MenuRunner<M> {
         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<M: MutableMenu> MenuRunner<M> {
                     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<M: MutableMenu> MenuRunner<M> {
                     let values: Vec<Value> =
                         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<M: MutableMenu> MenuRunner<M> {
                     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<M: MutableMenu> MenuRunner<M> {
                     return Ok(MenuResult::Cancelled);
                 }
                 ActionOutcome::Closed => {
+                    info!("menu closed by hook");
                     self.emit_hook(HookEvent::Close);
 
                     let _ = self.event_tx.send(MenuEvent::Cancelled);

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();