From a7b142945b4da3caca1cc55d1005999e9dee34fa Mon Sep 17 00:00:00 2001 From: Andrew Phillips Date: Mon, 25 Aug 2025 15:43:56 -0300 Subject: [PATCH] feat: add debugging to item service Co-authored-by: aider (openai/andrew/openrouter/anthropic/claude-sonnet-4) --- src/services/item_service.rs | 59 +++++++++++++++++++++++++++++++++--- 1 file changed, 55 insertions(+), 4 deletions(-) diff --git a/src/services/item_service.rs b/src/services/item_service.rs index 73a24f8..1ce1cff 100644 --- a/src/services/item_service.rs +++ b/src/services/item_service.rs @@ -8,6 +8,7 @@ use crate::db::{self, Meta}; use crate::compression_engine::{get_compression_engine, CompressionType}; use crate::modes::common::settings_compression_type; use clap::Command; +use log::debug; use rusqlite::Connection; use std::collections::HashMap; use std::fs; @@ -22,6 +23,7 @@ pub struct ItemService { impl ItemService { pub fn new(data_path: PathBuf) -> Self { + debug!("ITEM_SERVICE: Creating new ItemService with data_path: {:?}", data_path); Self { data_path, compression_service: CompressionService::new(), @@ -30,13 +32,18 @@ impl ItemService { } pub fn get_item(&self, conn: &Connection, id: i64) -> Result { + debug!("ITEM_SERVICE: Getting item with id: {}", id); let item = db::get_item(conn, id)?.ok_or(CoreError::ItemNotFound(id))?; + debug!("ITEM_SERVICE: Found item: {:?}", item); let tags = db::get_item_tags(conn, &item)?; + debug!("ITEM_SERVICE: Found {} tags for item {}", tags.len(), id); let meta = db::get_item_meta(conn, &item)?; + debug!("ITEM_SERVICE: Found {} meta entries for item {}", meta.len(), id); Ok(ItemWithMeta { item, tags, meta }) } pub fn get_item_content(&self, conn: &Connection, id: i64) -> Result { + debug!("ITEM_SERVICE: Getting item content for id: {}", id); let item_with_meta = self.get_item(conn, id)?; let item_id = item_with_meta.item.id.ok_or_else(|| CoreError::InvalidInput("Item missing ID".to_string()))?; @@ -46,10 +53,12 @@ impl ItemService { let mut item_path = self.data_path.clone(); item_path.push(item_id.to_string()); + debug!("ITEM_SERVICE: Reading content from path: {:?}", item_path); let content = self .compression_service .get_item_content(item_path, &item_with_meta.item.compression)?; + debug!("ITEM_SERVICE: Read {} bytes of content for item {}", content.len(), id); Ok(ItemWithContent { item_with_meta, @@ -58,25 +67,40 @@ impl ItemService { } pub fn find_item(&self, conn: &Connection, ids: &[i64], tags: &[String], meta: &HashMap) -> Result { - let item_maybe = match (ids.is_empty(), tags.is_empty() && meta.is_empty()) { - (false, _) => db::get_item(conn, ids[0])?, - (true, true) => db::get_item_last(conn)?, - (true, false) => db::get_item_matching(conn, &tags.to_vec(), meta)? + debug!("ITEM_SERVICE: Finding item with ids: {:?}, tags: {:?}, meta: {:?}", ids, tags, meta); + let item_maybe = match (ids.is_empty(), tags.is_empty() && meta.is_empty()) { + (false, _) => { + debug!("ITEM_SERVICE: Finding by ID: {}", ids[0]); + db::get_item(conn, ids[0])? + }, + (true, true) => { + debug!("ITEM_SERVICE: Finding last item"); + db::get_item_last(conn)? + }, + (true, false) => { + debug!("ITEM_SERVICE: Finding by tags/meta"); + db::get_item_matching(conn, &tags.to_vec(), meta)? + } }; let item = item_maybe.ok_or(CoreError::ItemNotFoundGeneric)?; + debug!("ITEM_SERVICE: Found matching item: {:?}", item); let item_id = item.id.ok_or_else(|| CoreError::InvalidInput("Item missing ID".to_string()))?; self.get_item(conn, item_id) } pub fn list_items(&self, conn: &Connection, tags: &[String], meta: &HashMap) -> Result, CoreError> { + debug!("ITEM_SERVICE: Listing items with tags: {:?}, meta: {:?}", tags, meta); let items = db::get_items_matching(conn, &tags.to_vec(), meta)?; + debug!("ITEM_SERVICE: Found {} matching items", items.len()); let item_ids: Vec = items.iter().filter_map(|item| item.id).collect(); if item_ids.is_empty() { + debug!("ITEM_SERVICE: No items found, returning empty list"); return Ok(Vec::new()); } + debug!("ITEM_SERVICE: Getting tags and meta for {} items", item_ids.len()); let tags_map = db::get_tags_for_items(conn, &item_ids)?; let meta_map_db = db::get_meta_for_items(conn, &item_ids)?; @@ -90,22 +114,27 @@ impl ItemService { result.push(ItemWithMeta { item, tags, meta }); } + debug!("ITEM_SERVICE: Returning {} items with full metadata", result.len()); Ok(result) } pub fn delete_item(&self, conn: &mut Connection, id: i64) -> Result<(), CoreError> { + debug!("ITEM_SERVICE: Deleting item with id: {}", id); if id <= 0 { return Err(CoreError::InvalidInput(format!("Invalid item ID: {}", id))); } let item = db::get_item(conn, id)?.ok_or(CoreError::ItemNotFound(id))?; + debug!("ITEM_SERVICE: Found item to delete: {:?}", item); let mut item_path = self.data_path.clone(); item_path.push(id.to_string()); + debug!("ITEM_SERVICE: Deleting file at path: {:?}", item_path); let tx = conn.transaction()?; db::delete_item(&tx, item)?; fs::remove_file(&item_path).or_else(|e| if e.kind() == std::io::ErrorKind::NotFound { Ok(()) } else { Err(e) })?; tx.commit()?; + debug!("ITEM_SERVICE: Successfully deleted item {}", id); Ok(()) } @@ -118,11 +147,14 @@ impl ItemService { tags: &mut Vec, conn: &mut Connection, ) -> Result { + debug!("ITEM_SERVICE: Starting save_item with tags: {:?}", tags); if tags.is_empty() { tags.push("none".to_string()); + debug!("ITEM_SERVICE: No tags provided, using default 'none' tag"); } let compression_type = settings_compression_type(cmd, settings); + debug!("ITEM_SERVICE: Using compression type: {:?}", compression_type); let compression_engine = get_compression_engine(compression_type.clone())?; let tx = conn.transaction()?; @@ -132,24 +164,30 @@ impl ItemService { { item = db::create_item(&tx, compression_type.clone())?; item_id = item.id.unwrap(); + debug!("ITEM_SERVICE: Created new item with id: {}", item_id); db::set_item_tags(&tx, item.clone(), tags)?; + debug!("ITEM_SERVICE: Set tags for item {}", item_id); let item_meta = self.meta_service.collect_initial_meta(); + debug!("ITEM_SERVICE: Collected {} initial meta entries", item_meta.len()); for (k, v) in item_meta.iter() { db::add_meta(&tx, item_id, k, v)?; } } let mut plugins = self.meta_service.get_plugins(cmd, settings); + debug!("ITEM_SERVICE: Got {} meta plugins", plugins.len()); self.meta_service.initialize_plugins(&mut plugins, &tx, item_id); let mut item_path = self.data_path.clone(); item_path.push(item_id.to_string()); + debug!("ITEM_SERVICE: Writing item to path: {:?}", item_path); let mut item_out = compression_engine.create(item_path.clone())?; let mut buffer = [0; 8192]; let mut total_bytes = 0; + debug!("ITEM_SERVICE: Starting to read and process input data"); loop { let n = input.read(&mut buffer)?; if n == 0 { break; } @@ -158,16 +196,19 @@ impl ItemService { item_out.write_all(&buffer[..n])?; self.meta_service.process_chunk(&mut plugins, &buffer[..n], &tx); } + debug!("ITEM_SERVICE: Processed {} bytes total", total_bytes); item_out.flush()?; drop(item_out); + debug!("ITEM_SERVICE: Finalizing meta plugins"); self.meta_service.finalize_plugins(&mut plugins, &tx); item.size = Some(total_bytes); db::update_item(&tx, item.clone())?; tx.commit()?; + debug!("ITEM_SERVICE: Transaction committed successfully"); if !settings.quiet { if std::io::stderr().is_terminal() { @@ -192,6 +233,7 @@ impl ItemService { } } + debug!("ITEM_SERVICE: Getting final item with metadata"); self.get_item(conn, item_id) } @@ -202,6 +244,8 @@ impl ItemService { metadata: &HashMap, conn: &mut Connection, ) -> Result { + debug!("ITEM_SERVICE: Starting save_item_from_mcp with {} bytes, {} tags, {} metadata entries", + content.len(), tags.len(), metadata.len()); let compression_type = CompressionType::LZ4; let compression_engine = get_compression_engine(compression_type.clone())?; @@ -212,20 +256,24 @@ impl ItemService { { item = db::create_item(&tx, compression_type.clone())?; item_id = item.id.unwrap(); + debug!("ITEM_SERVICE: Created MCP item with id: {}", item_id); // Add tags for tag in tags { db::add_tag(&tx, item_id, tag)?; } + debug!("ITEM_SERVICE: Added {} tags to MCP item", tags.len()); // Add custom metadata for (key, value) in metadata { db::add_meta(&tx, item_id, key, value)?; } + debug!("ITEM_SERVICE: Added {} custom metadata entries to MCP item", metadata.len()); } let mut item_path = self.data_path.clone(); item_path.push(item_id.to_string()); + debug!("ITEM_SERVICE: Writing MCP item to path: {:?}", item_path); let mut writer = compression_engine.create(item_path.clone())?; writer.write_all(content)?; @@ -245,17 +293,20 @@ impl ItemService { let mut plugins: Vec> = plugin_types.iter().map(|p| get_meta_plugin(p.clone())).collect(); + debug!("ITEM_SERVICE: Created {} meta plugins for MCP item", plugins.len()); self.meta_service .initialize_plugins(&mut plugins, &tx, item_id); self.meta_service .process_chunk(&mut plugins, content, &tx); self.meta_service.finalize_plugins(&mut plugins, &tx); + debug!("ITEM_SERVICE: Processed MCP item through meta plugins"); item.size = Some(content.len() as i64); db::update_item(&tx, item.clone())?; tx.commit()?; + debug!("ITEM_SERVICE: MCP item transaction committed successfully"); self.get_item(conn, item_id) }