fix: agent logging (#888)

* fix: optimize agent logging to reduce DataDog bill

* fix: log permanent repair failures as ERROR not WARN

RepairResult::Failed is permanent failure requiring attention (ERROR level)
not a temporary/retryable condition (WARN level).

[skip-regression-check]

Co-Authored-By: Claude Haiku 4.5 <[email protected]>

* security: remove user message content from trace logs

Never log user message content at any log level (includes TRACE).
Log only safe metadata: content length, message ID, image count.

This prevents accidental exposure of sensitive user data in logs
even at the most verbose logging level.

[skip-regression-check]

Co-Authored-By: Claude Haiku 4.5 <[email protected]>

* security: move LLM response body logging to TRACE level

Response bodies can contain user-generated content, tool outputs, and
leaked secrets. Moving to TRACE (not enabled in production) prevents
exposure in DEBUG logs. Status log remains at DEBUG.

[skip-regression-check]

Co-Authored-By: Claude Haiku 4.5 <[email protected]>

* refactor: simplify URL sanitization using url::Url API

Use set_query, set_fragment, set_username, set_password methods
instead of manual string reconstruction. Cleaner, handles edge cases,
eliminates port branching complexity.

[skip-regression-check]

Co-Authored-By: Claude Haiku 4.5 <[email protected]>

* test: add comprehensive unit tests for sanitize_url_for_logging

Add 9 test cases covering:
- URL with query parameters
- URL with credentials (user:pass@host)
- URL with fragment
- URL with port
- URL with all components combined
- Malformed URL fallback behavior
- Short strings (pass-through)
- Non-URL-like strings
- Path preservation

Tests verify that sanitization correctly removes sensitive components
while preserving safe components like host, port, and path.

Co-Authored-By: Claude Haiku 4.5 <[email protected]>

* fix: libsql per-migration logs should be DEBUG, not TRACE

Individual migration logs are now visible with standard debug logging
(RUST_LOG=ironclaw=debug), improving debuggability when troubleshooting
migration issues. Summary log remains at INFO level.

Fixes behavioral change that made it harder to identify which specific
migration ran or failed without enabling full TRACE logging.

[skip-regression-check]

---------

Co-authored-by: Claude Haiku 4.5 <[email protected]>
This commit is contained in:
Nick Pismenkov
2026-03-10 13:55:06 -07:00
committed by GitHub
co-authored by Claude Haiku 4.5
parent 5635384e51
commit 1f5b582c5f
13 changed files with 187 additions and 61 deletions
+4 -4
View File
@@ -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,
+2 -2
View File
@@ -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(),
+3 -3
View File
@@ -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);
+11 -14
View File
@@ -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"
);
}
}
+7 -9
View File
@@ -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);
}
}
}
+6 -6
View File
@@ -663,9 +663,9 @@ async fn chat_send_handler(
headers: axum::http::HeaderMap,
Json(req): Json<SendMessageRequest>,
) -> Result<(StatusCode, Json<SendMessageResponse>), (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()
);
+7 -3
View File
@@ -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(())
+125 -5
View File
@@ -113,6 +113,31 @@ pub struct ExtensionManager {
gateway_token: Option<String>,
}
/// 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<ExtensionKind>,
) -> Result<InstallResult, ExtensionError> {
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:[email protected]: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:[email protected]: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"));
}
}
+9 -2
View File
@@ -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();
+1 -1
View File
@@ -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;
+8 -8
View File
@@ -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<ToolCompletionResponse, LlmError> {
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)"
);
+1 -1
View File
@@ -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).
+3 -3
View File
@@ -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;
}
}