diff --git a/src/agent/agent_loop.rs b/src/agent/agent_loop.rs index b945a812..d95f3e46 100644 --- a/src/agent/agent_loop.rs +++ b/src/agent/agent_loop.rs @@ -765,7 +765,7 @@ impl Agent { // Parse submission type first let mut submission = SubmissionParser::parse(&message.content); - tracing::debug!( + tracing::trace!( "[agent_loop] Parsed submission: {:?}", std::any::type_name_of_val(&submission) ); @@ -798,7 +798,7 @@ impl Agent { // Hydrate thread from DB if it's a historical thread not in memory if let Some(ref external_thread_id) = message.thread_id { - tracing::debug!( + tracing::trace!( message_id = %message.id, thread_id = %external_thread_id, "Hydrating thread from DB" @@ -819,7 +819,7 @@ impl Agent { message.thread_id.as_deref(), ) .await; - tracing::info!( + tracing::debug!( message_id = %message.id, thread_id = %thread_id, "Resolved session and thread" @@ -853,7 +853,7 @@ impl Agent { } } - tracing::debug!( + tracing::trace!( "Received message from {} on {} ({} chars)", message.user_id, message.channel, diff --git a/src/agent/dispatcher.rs b/src/agent/dispatcher.rs index 18121086..b791f6d7 100644 --- a/src/agent/dispatcher.rs +++ b/src/agent/dispatcher.rs @@ -90,7 +90,7 @@ impl Agent { crate::skills::SkillTrust::Installed => "INSTALLED", }; - tracing::info!( + tracing::debug!( skill_name = skill.name(), skill_version = skill.version(), trust = %skill.trust, @@ -283,7 +283,7 @@ impl<'a> LoopDelegate for ChatDelegate<'a> { // Apply trust-based tool attenuation if skills are active. let tool_defs = if !self.active_skills.is_empty() { let result = crate::skills::attenuate_tools(&tool_defs, &self.active_skills); - tracing::info!( + tracing::debug!( min_trust = %result.min_trust, tools_available = result.tools.len(), tools_removed = result.removed_tools.len(), diff --git a/src/agent/heartbeat.rs b/src/agent/heartbeat.rs index 4157be1b..15c51b61 100644 --- a/src/agent/heartbeat.rs +++ b/src/agent/heartbeat.rs @@ -189,7 +189,7 @@ impl HeartbeatRunner { // Skip during quiet hours if self.config.is_quiet_hours() { - tracing::debug!("Heartbeat skipped: quiet hours"); + tracing::trace!("Heartbeat skipped: quiet hours"); continue; } @@ -212,7 +212,7 @@ impl HeartbeatRunner { match self.check_heartbeat().await { HeartbeatResult::Ok => { - tracing::debug!("Heartbeat OK"); + tracing::trace!("Heartbeat OK"); self.consecutive_failures = 0; } HeartbeatResult::NeedsAttention(message) => { @@ -221,7 +221,7 @@ impl HeartbeatRunner { self.send_notification(&message).await; } HeartbeatResult::Skipped => { - tracing::debug!("Heartbeat skipped"); + tracing::trace!("Heartbeat skipped"); } HeartbeatResult::Failed(error) => { tracing::error!("Heartbeat failed: {}", error); diff --git a/src/agent/routine_engine.rs b/src/agent/routine_engine.rs index 1bc16b95..b10021ef 100644 --- a/src/agent/routine_engine.rs +++ b/src/agent/routine_engine.rs @@ -32,7 +32,7 @@ use crate::llm::{ ChatMessage, CompletionRequest, FinishReason, LlmProvider, ToolCall, ToolCompletionRequest, }; use crate::safety::SafetyLayer; -use crate::tools::{ApprovalContext, ApprovalRequirement, ToolError, ToolRegistry, redact_params}; +use crate::tools::{ApprovalContext, ApprovalRequirement, ToolError, ToolRegistry}; use crate::workspace::Workspace; enum EventMatcher { @@ -116,7 +116,7 @@ impl RoutineEngine { } let count = cache.len(); *self.event_cache.write().await = cache; - tracing::debug!("Refreshed event cache: {} routines", count); + tracing::trace!("Refreshed event cache: {} routines", count); } Err(e) => { tracing::error!("Failed to refresh event cache: {}", e); @@ -153,13 +153,13 @@ impl RoutineEngine { // Cooldown check if !self.check_cooldown(routine) { - tracing::debug!(routine = %routine.name, "Skipped: cooldown active"); + tracing::trace!(routine = %routine.name, "Skipped: cooldown active"); continue; } // Concurrent run check if !self.check_concurrent(routine).await { - tracing::debug!(routine = %routine.name, "Skipped: max concurrent reached"); + tracing::trace!(routine = %routine.name, "Skipped: max concurrent reached"); continue; } @@ -1013,13 +1013,6 @@ async fn execute_routine_tool( return Err(format!("Invalid tool parameters: {}", details).into()); } - let safe_params = redact_params(&tc.arguments, tool.sensitive_params()); - tracing::debug!( - tool = %tc.name, - params = %safe_params, - "Lightweight routine tool call started" - ); - // Execute with per-tool timeout let timeout = tool.execution_timeout(); let start = std::time::Instant::now(); @@ -1029,12 +1022,14 @@ async fn execute_routine_tool( .await; let elapsed = start.elapsed(); + // Log tool execution result (single consolidated log) match &result { Ok(Ok(_)) => { tracing::debug!( tool = %tc.name, elapsed_ms = elapsed.as_millis() as u64, - "Lightweight routine tool call succeeded" + status = "succeeded", + "Lightweight routine tool execution completed" ); } Ok(Err(e)) => { @@ -1042,7 +1037,8 @@ async fn execute_routine_tool( tool = %tc.name, elapsed_ms = elapsed.as_millis() as u64, error = %e, - "Lightweight routine tool call failed" + status = "failed", + "Lightweight routine tool execution completed" ); } Err(_) => { @@ -1050,7 +1046,8 @@ async fn execute_routine_tool( tool = %tc.name, elapsed_ms = elapsed.as_millis() as u64, timeout_secs = timeout.as_secs(), - "Lightweight routine tool call timed out" + status = "timeout", + "Lightweight routine tool execution completed" ); } } diff --git a/src/agent/self_repair.rs b/src/agent/self_repair.rs index 5ac8e8aa..a67fe23e 100644 --- a/src/agent/self_repair.rs +++ b/src/agent/self_repair.rs @@ -334,22 +334,21 @@ impl RepairTask { // Check for stuck jobs let stuck_jobs = self.repair.detect_stuck_jobs().await; for job in stuck_jobs { - tracing::info!("Attempting to repair stuck job {}", job.job_id); match self.repair.repair_stuck_job(&job).await { Ok(RepairResult::Success { message }) => { - tracing::info!("Repair succeeded: {}", message); + tracing::info!(job = %job.job_id, status = "success", "Stuck job repair completed: {}", message); } Ok(RepairResult::Retry { message }) => { - tracing::warn!("Repair needs retry: {}", message); + tracing::debug!(job = %job.job_id, status = "retry", "Stuck job repair needs retry: {}", message); } Ok(RepairResult::Failed { message }) => { - tracing::error!("Repair failed: {}", message); + tracing::error!(job = %job.job_id, status = "failed", "Stuck job repair failed: {}", message); } Ok(RepairResult::ManualRequired { message }) => { - tracing::warn!("Manual intervention needed: {}", message); + tracing::warn!(job = %job.job_id, status = "manual", "Stuck job repair requires manual intervention: {}", message); } Err(e) => { - tracing::error!("Repair error: {}", e); + tracing::error!(job = %job.job_id, "Stuck job repair error: {}", e); } } } @@ -357,13 +356,12 @@ impl RepairTask { // Check for broken tools let broken_tools = self.repair.detect_broken_tools().await; for tool in broken_tools { - tracing::info!("Attempting to repair broken tool: {}", tool.name); match self.repair.repair_broken_tool(&tool).await { Ok(result) => { - tracing::info!("Tool repair result: {:?}", result); + tracing::debug!(tool = %tool.name, status = "completed", "Tool repair completed: {:?}", result); } Err(e) => { - tracing::error!("Tool repair error: {}", e); + tracing::error!(tool = %tool.name, "Tool repair error: {}", e); } } } diff --git a/src/channels/web/server.rs b/src/channels/web/server.rs index fce6caa5..9c7561a1 100644 --- a/src/channels/web/server.rs +++ b/src/channels/web/server.rs @@ -663,9 +663,9 @@ async fn chat_send_handler( headers: axum::http::HeaderMap, Json(req): Json, ) -> Result<(StatusCode, Json), (StatusCode, String)> { - tracing::debug!( - "[chat_send_handler] Received message: content={:?}, thread_id={:?}", - req.content, + tracing::trace!( + "[chat_send_handler] Received message: content_len={}, thread_id={:?}", + req.content.len(), req.thread_id ); @@ -698,10 +698,10 @@ async fn chat_send_handler( } let msg_id = msg.id; - tracing::debug!( - "[chat_send_handler] Created message id={}, content={:?}, images={}", + tracing::trace!( + "[chat_send_handler] Created message id={}, content_len={}, images={}", msg_id, - req.content, + req.content.len(), req.images.len() ); diff --git a/src/db/libsql_migrations.rs b/src/db/libsql_migrations.rs index 63708235..02c4c9b2 100644 --- a/src/db/libsql_migrations.rs +++ b/src/db/libsql_migrations.rs @@ -653,6 +653,7 @@ END; pub async fn run_incremental(conn: &libsql::Connection) -> Result<(), crate::error::DatabaseError> { use crate::error::DatabaseError; + let mut applied_count = 0; for &(version, name, sql) in INCREMENTAL_MIGRATIONS { // Check if already applied let mut rows = conn @@ -669,8 +670,6 @@ pub async fn run_incremental(conn: &libsql::Connection) -> Result<(), crate::err continue; // Already applied } - tracing::info!(version, name, "libSQL: applying incremental migration"); - // Wrap migration + recording in a transaction for atomicity. // If the process crashes mid-migration, the transaction rolls back // and the migration will be retried on next startup. @@ -702,7 +701,12 @@ pub async fn run_incremental(conn: &libsql::Connection) -> Result<(), crate::err )) })?; - tracing::info!(version, name, "libSQL: migration applied successfully"); + applied_count += 1; + tracing::debug!(version, name, "libSQL: migration applied"); + } + + if applied_count > 0 { + tracing::info!("libSQL: applied {} incremental migrations", applied_count); } Ok(()) diff --git a/src/extensions/manager.rs b/src/extensions/manager.rs index b34810e8..85d1ce74 100644 --- a/src/extensions/manager.rs +++ b/src/extensions/manager.rs @@ -113,6 +113,31 @@ pub struct ExtensionManager { gateway_token: Option, } +/// Sanitize a URL for logging by removing query parameters and credentials. +/// Prevents accidental logging of API keys, OAuth tokens, or other sensitive data in URLs. +fn sanitize_url_for_logging(url: &str) -> String { + // If URL is very short or doesn't look like a URL, just use as-is + if url.len() < 10 || !url.contains("://") { + return url.to_string(); + } + + // Try to parse and remove sensitive components + if let Ok(mut parsed) = url::Url::parse(url) { + // Remove query string and fragment + parsed.set_query(None); + parsed.set_fragment(None); + + // Remove userinfo (username and password) if present + let _ = parsed.set_username(""); + let _ = parsed.set_password(None); + + parsed.to_string() + } else { + // Fallback: strip after ? or # + url.split(['?', '#']).next().unwrap_or(url).to_string() + } +} + impl ExtensionManager { #[allow(clippy::too_many_arguments)] pub fn new( @@ -299,7 +324,8 @@ impl ExtensionManager { url: Option<&str>, kind_hint: Option, ) -> Result { - tracing::info!(extension = %name, url = ?url, kind = ?kind_hint, "Installing extension"); + let sanitized_url = url.map(sanitize_url_for_logging); + tracing::info!(extension = %name, url = ?sanitized_url, kind = ?kind_hint, "Installing extension"); Self::validate_extension_name(name)?; // If we have a registry entry, use it (prefer kind_hint to resolve collisions) @@ -321,7 +347,8 @@ impl ExtensionManager { } } .map_err(|e| { - tracing::error!(extension = %name, url = %url, error = %e, "Extension install from URL failed"); + let sanitized = sanitize_url_for_logging(url); + tracing::error!(extension = %name, url = %sanitized, error = %e, "Extension install from URL failed"); e }); } @@ -1212,10 +1239,11 @@ impl ExtensionManager { .build() .map_err(|e| ExtensionError::DownloadFailed(e.to_string()))?; - tracing::debug!(extension = %name, url = %url, "Downloading WASM extension"); + let sanitized_url = sanitize_url_for_logging(url); + tracing::debug!(extension = %name, url = %sanitized_url, "Downloading WASM extension"); let response = client.get(url).send().await.map_err(|e| { - tracing::error!(extension = %name, url = %url, error = %e, "Download request failed"); + tracing::error!(extension = %name, url = %sanitized_url, error = %e, "Download request failed"); ExtensionError::DownloadFailed(e.to_string()) })?; @@ -1223,7 +1251,7 @@ impl ExtensionManager { let status = response.status(); tracing::error!( extension = %name, - url = %url, + url = %sanitized_url, status = %status, "Download returned non-success HTTP status" ); @@ -4107,4 +4135,96 @@ mod tests { unsafe { std::env::remove_var("_TOKEN") }; unsafe { std::env::remove_var("ICTEST6_TOKEN") }; } + + #[test] + fn test_sanitize_url_with_query_params() { + let url = "https://api.example.com/path?api_key=secret123&token=abc"; + let result = super::sanitize_url_for_logging(url); + assert_eq!(result, "https://api.example.com/path"); + assert!(!result.contains("api_key")); + assert!(!result.contains("secret123")); + assert!(!result.contains("token")); + } + + #[test] + fn test_sanitize_url_with_credentials() { + let url = "https://user:password@api.example.com:8080/path"; + let result = super::sanitize_url_for_logging(url); + assert!(!result.contains("user")); + assert!(!result.contains("password")); + assert!(!result.contains("@")); + assert!(result.contains("api.example.com")); + assert!(result.contains(":8080")); + } + + #[test] + fn test_sanitize_url_with_fragment() { + let url = "https://api.example.com/path#section"; + let result = super::sanitize_url_for_logging(url); + assert_eq!(result, "https://api.example.com/path"); + assert!(!result.contains("#")); + assert!(!result.contains("section")); + } + + #[test] + fn test_sanitize_url_with_port() { + let url = "https://api.example.com:9443/path?key=value"; + let result = super::sanitize_url_for_logging(url); + assert_eq!(result, "https://api.example.com:9443/path"); + assert!(result.contains(":9443")); + assert!(!result.contains("key")); + } + + #[test] + fn test_sanitize_url_with_all_components() { + let url = "https://admin:secret@api.example.com:8080/v1/data?api_key=xyz#results"; + let result = super::sanitize_url_for_logging(url); + assert!(!result.contains("admin")); + assert!(!result.contains("secret")); + assert!(!result.contains("@")); + assert!(!result.contains("api_key")); + assert!(!result.contains("xyz")); + assert!(!result.contains("#")); + assert!(!result.contains("results")); + assert!(result.contains("api.example.com:8080")); + assert!(result.contains("/v1/data")); + } + + #[test] + fn test_sanitize_url_malformed() { + // Malformed URL should fallback to string splitting + let url = "https://[invalid-url"; + let result = super::sanitize_url_for_logging(url); + // Malformed URL without query should return as-is via fallback + assert_eq!(result, url); + + // Should still strip query params via fallback + let url_with_query = "https://[invalid-url?key=secret"; + let result_with_query = super::sanitize_url_for_logging(url_with_query); + assert_eq!(result_with_query, "https://[invalid-url"); + assert!(!result_with_query.contains("?")); + assert!(!result_with_query.contains("secret")); + } + + #[test] + fn test_sanitize_url_short_string() { + let url = "short"; + let result = super::sanitize_url_for_logging(url); + assert_eq!(result, "short"); + } + + #[test] + fn test_sanitize_url_not_url_like() { + let input = "this is not a url"; + let result = super::sanitize_url_for_logging(input); + assert_eq!(result, input); + } + + #[test] + fn test_sanitize_url_preserves_path() { + let url = "https://api.example.com/v1/users/123/profile"; + let result = super::sanitize_url_for_logging(url); + assert_eq!(result, url); + assert!(result.contains("/v1/users/123/profile")); + } } diff --git a/src/llm/nearai_chat.rs b/src/llm/nearai_chat.rs index 3f4b4339..da99c080 100644 --- a/src/llm/nearai_chat.rs +++ b/src/llm/nearai_chat.rs @@ -270,8 +270,15 @@ impl NearAiChatProvider { reason: format!("Failed to read response body: {}", e), })?; - tracing::debug!("NEAR AI Chat response status: {}", status); - tracing::debug!("NEAR AI Chat response body: {}", response_text); + if tracing::enabled!(tracing::Level::DEBUG) { + tracing::debug!("NEAR AI Chat response status: {}", status); + } + + // Log response body only at TRACE level to avoid exposing sensitive content + // (user-generated data, tool outputs, leaked secrets) in DEBUG logs + if tracing::enabled!(tracing::Level::TRACE) { + tracing::trace!("NEAR AI Chat response body: {}", response_text); + } if !status.is_success() { let status_code = status.as_u16(); diff --git a/src/llm/response_cache.rs b/src/llm/response_cache.rs index b1e7aa8e..b8238427 100644 --- a/src/llm/response_cache.rs +++ b/src/llm/response_cache.rs @@ -205,7 +205,7 @@ impl LlmProvider for CachedProvider { let hit_count = entry.hit_count; // Clone now so we can release the mutable borrow before stats. let cached_response = entry.response.clone(); - tracing::debug!(hits = hit_count, "response cache hit"); + tracing::trace!(hits = hit_count, "response cache hit"); // Drop the mutable borrow of `entry` before reading `guard` immutably. let _ = entry; let total_hits = self.total_hit_count.fetch_add(1, Ordering::Relaxed) + 1; diff --git a/src/llm/smart_routing.rs b/src/llm/smart_routing.rs index 6d413723..dbcae429 100644 --- a/src/llm/smart_routing.rs +++ b/src/llm/smart_routing.rs @@ -770,7 +770,7 @@ impl SmartRoutingProvider { } }; let complexity = TaskComplexity::from(tier); - tracing::debug!( + tracing::trace!( %tier, ?complexity, "Smart routing: explicit tier hint" @@ -782,7 +782,7 @@ impl SmartRoutingProvider { for po in DEFAULT_OVERRIDES.iter() { if po.regex.is_match(last_user_msg) { let complexity = TaskComplexity::from(po.tier); - tracing::debug!( + tracing::trace!( tier = %po.tier, ?complexity, "Smart routing: pattern override matched" @@ -798,7 +798,7 @@ impl SmartRoutingProvider { &self.domain_regex, ); let complexity = TaskComplexity::from(breakdown.tier); - tracing::debug!( + tracing::trace!( score = breakdown.total, tier = %breakdown.tier, ?complexity, @@ -872,7 +872,7 @@ impl LlmProvider for SmartRoutingProvider { match complexity { TaskComplexity::Simple => { - tracing::debug!( + tracing::trace!( model = %self.cheap.model_name(), "Smart routing: Simple task -> cheap model" ); @@ -880,7 +880,7 @@ impl LlmProvider for SmartRoutingProvider { self.cheap.complete(request).await } TaskComplexity::Complex => { - tracing::debug!( + tracing::trace!( model = %self.primary.model_name(), "Smart routing: Complex task -> primary model" ); @@ -889,7 +889,7 @@ impl LlmProvider for SmartRoutingProvider { } TaskComplexity::Moderate => { if self.config.cascade_enabled { - tracing::debug!( + tracing::trace!( model = %self.cheap.model_name(), "Smart routing: Moderate task -> cheap model (cascade enabled)" ); @@ -913,7 +913,7 @@ impl LlmProvider for SmartRoutingProvider { } } else { // Without cascade, moderate tasks go to cheap model - tracing::debug!( + tracing::trace!( model = %self.cheap.model_name(), "Smart routing: Moderate task -> cheap model (cascade disabled)" ); @@ -931,7 +931,7 @@ impl LlmProvider for SmartRoutingProvider { ) -> Result { self.stats.total_requests.fetch_add(1, Ordering::Relaxed); self.stats.primary_requests.fetch_add(1, Ordering::Relaxed); - tracing::debug!( + tracing::trace!( model = %self.primary.model_name(), "Smart routing: Tool use -> primary model (always)" ); diff --git a/src/tools/registry.rs b/src/tools/registry.rs index b487366a..7054eea3 100644 --- a/src/tools/registry.rs +++ b/src/tools/registry.rs @@ -137,7 +137,7 @@ impl ToolRegistry { return; } self.tools.write().await.insert(name.clone(), tool); - tracing::debug!("Registered tool: {}", name); + tracing::trace!("Registered tool: {}", name); } /// Register a tool (sync version for startup, marks as built-in). diff --git a/src/workspace/mod.rs b/src/workspace/mod.rs index 16c7bc0e..fa48072b 100644 --- a/src/workspace/mod.rs +++ b/src/workspace/mod.rs @@ -887,13 +887,13 @@ impl Workspace { Ok(_) => continue, Err(WorkspaceError::DocumentNotFound { .. }) => {} Err(e) => { - tracing::warn!("Failed to check {}: {}", path, e); + tracing::debug!("Failed to check {}: {}", path, e); continue; } } if let Err(e) = self.write(path, content).await { - tracing::warn!("Failed to seed {}: {}", path, e); + tracing::debug!("Failed to seed {}: {}", path, e); } else { count += 1; } @@ -977,7 +977,7 @@ impl Workspace { Ok(_) => continue, Err(WorkspaceError::DocumentNotFound { .. }) => {} Err(e) => { - tracing::warn!("Failed to check {}: {}", file_name, e); + tracing::trace!("Failed to check {}: {}", file_name, e); continue; } }