diff --git a/AGENTS.md b/AGENTS.md index ee9a34b..8cdfa01 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -69,6 +69,7 @@ Large-diff work is a separate evaluation track, not part of the default live-rep - **LLM-as-judge** — evaluator that scores analysis quality across 5 criteria - **Eval suite** — 5 synthetic fixture codebases, deterministic scoring, 0.89 avg score - **Config** — `.diffcore.toml` with entrypoint globs, layer names, ignore patterns, LLM settings, refinement settings +- **Logging** — `tracing` + `tracing-subscriber` behind `diffcore-core`'s `logging` feature; `RUST_LOG` sets the filter (default `info`), `DIFFCORE_LOG_FORMAT=json` switches to line-delimited JSON, `DIFFCORE_LOG_FILE` redirects to a file (the desktop app falls back to `~/.diffcore/desktop.log` when stderr is not a terminal, since GUI bundles discard it). Backend activity logs on the `activity` target, IR cache on `ir_cache`. `log`-crate call sites bridge in automatically. ## Tests diff --git a/Cargo.lock b/Cargo.lock index e71df79..70a21b4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -79,21 +79,6 @@ version = "0.1.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4b46cbb362ab8752921c97e041f5e366ee6297bd428a31275b9fcf1e380f7299" -[[package]] -name = "anstream" -version = "0.6.21" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "43d5b281e737544384e969a5ccad3f1cdd24b48086a0fc1b2a5262a26b8f4f4a" -dependencies = [ - "anstyle", - "anstyle-parse 0.2.7", - "anstyle-query", - "anstyle-wincon", - "colorchoice", - "is_terminal_polyfill", - "utf8parse", -] - [[package]] name = "anstream" version = "1.0.0" @@ -101,7 +86,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "824a212faf96e9acacdbd09febd34438f8f711fb84e09a8916013cd7815ca28d" dependencies = [ "anstyle", - "anstyle-parse 1.0.0", + "anstyle-parse", "anstyle-query", "anstyle-wincon", "colorchoice", @@ -115,15 +100,6 @@ version = "1.0.14" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "940b3a0ca603d1eade50a4846a2afffd5ef57a9feac2c0e2ec2e14f9ead76000" -[[package]] -name = "anstyle-parse" -version = "0.2.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4e7644824f0aa2c7b9384579234ef10eb7efb6a0deb83f9630a49594dd9c15c2" -dependencies = [ - "utf8parse", -] - [[package]] name = "anstyle-parse" version = "1.0.0" @@ -721,7 +697,7 @@ version = "4.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "714a53001bf66416adb0e2ef5ac857140e7dc3a0c48fb28b2f10762fc4b5069f" dependencies = [ - "anstream 1.0.0", + "anstream", "anstyle", "clap_lex", "strsim", @@ -1235,7 +1211,6 @@ version = "0.5.15" dependencies = [ "clap", "diffcore-core", - "env_logger", "git2", "log", "serde_json", @@ -1274,6 +1249,8 @@ dependencies = [ "thiserror 2.0.18", "tokio", "toml 0.8.2", + "tracing", + "tracing-subscriber", "tree-sitter", "tree-sitter-c", "tree-sitter-c-sharp", @@ -1298,7 +1275,6 @@ dependencies = [ "async-stream", "axum", "diffcore-core", - "env_logger", "futures-core", "git2", "hex", @@ -1321,6 +1297,7 @@ dependencies = [ "tokio", "tower", "tower-http", + "tracing", "uuid", ] @@ -1499,29 +1476,6 @@ dependencies = [ "cfg-if", ] -[[package]] -name = "env_filter" -version = "1.0.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7a1c3cc8e57274ec99de65301228b537f1e4eedc1b8e0f9411c6caac8ae7308f" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.9" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b2daee4ea451f429a58296525ddf28b45a3b64f1acf6587e2067437bb11e218d" -dependencies = [ - "anstream 0.6.21", - "anstyle", - "env_filter", - "jiff", - "log", -] - [[package]] name = "equator" version = "0.4.2" @@ -2807,30 +2761,6 @@ dependencies = [ "system-deps", ] -[[package]] -name = "jiff" -version = "0.2.23" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1a3546dc96b6d42c5f24902af9e2538e82e39ad350b0c766eb3fbf2d8f3d8359" -dependencies = [ - "jiff-static", - "log", - "portable-atomic", - "portable-atomic-util", - "serde_core", -] - -[[package]] -name = "jiff-static" -version = "0.2.23" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2a8c8b344124222efd714b73bb41f8b5120b27a7cc1c75593a6ff768d9d05aa4" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.117", -] - [[package]] name = "jni" version = "0.21.1" @@ -3122,6 +3052,15 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.10" @@ -3370,6 +3309,15 @@ version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0676bb32a98c1a483ce53e500a81ad9c3d5b3f7c920c28c24e9cb0980d0b5bc8" +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num-bigint" version = "0.4.6" @@ -5397,6 +5345,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shared_child" version = "1.1.1" @@ -6172,6 +6129,15 @@ dependencies = [ "syn 2.0.117", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "tiff" version = "0.11.3" @@ -6515,9 +6481,21 @@ checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" dependencies = [ "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.117", +] + [[package]] name = "tracing-core" version = "0.1.36" @@ -6525,6 +6503,49 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "serde", + "serde_json", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] @@ -6907,6 +6928,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/Cargo.toml b/Cargo.toml index 001f9f5..5926dda 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -14,6 +14,8 @@ serde = { version = "1", features = ["derive"] } # stable for arbitrary f64 scores (see assert_json_roundtrip). serde_json = { version = "1", features = ["float_roundtrip"] } log = "0.4" +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] } git2 = { version = "0.20", default-features = false } # Optimize test builds: trades slightly longer compile for faster test runtime. diff --git a/README.md b/README.md index 0476c8c..aa53625 100644 --- a/README.md +++ b/README.md @@ -199,6 +199,24 @@ When using direct API providers (`anthropic`, `openai`, `gemini`), Diffcore chec When using `codex` or `claude`, Diffcore uses the local CLI login instead of an API key and lets that agent inspect the repository with structured output constraints. +### Logging + +`diffcore` and `diffcore-web` log to stderr at `info` by default, so piping +stdout to `jq` still works; the desktop app logs to a file (see below). + +Backend activity (`codex`, `claude`) logs on the `activity` target with `source` +and `event_type` fields — the same events the desktop UI shows; the IR cache logs +on `ir_cache`. + +```bash +RUST_LOG=info,activity=warn diffcore analyze --base main # mute per-event chatter +DIFFCORE_LOG_FORMAT=json diffcore analyze --base main 2> analyze.log.jsonl +``` + +Launched from a terminal the desktop app logs there like the others; launched +from Finder or a `.desktop` entry — where stderr is discarded — it falls back to +`~/.diffcore/desktop.log`. `DIFFCORE_LOG_FILE` overrides the path for any binary. + ## Architecture ``` diff --git a/crates/diffcore-cli/Cargo.toml b/crates/diffcore-cli/Cargo.toml index 9fa9c72..c1e194f 100644 --- a/crates/diffcore-cli/Cargo.toml +++ b/crates/diffcore-cli/Cargo.toml @@ -8,14 +8,13 @@ name = "diffcore" path = "src/main.rs" [dependencies] -diffcore-core = { path = "../diffcore-core" } +diffcore-core = { path = "../diffcore-core", features = ["logging"] } clap = { version = "4", features = ["derive"] } serde_json = { workspace = true } git2 = { workspace = true } tokio = { version = "1", features = ["full"] } tempfile = "3" log = { workspace = true } -env_logger = "0.11" [features] embeddings = ["diffcore-core/embeddings"] diff --git a/crates/diffcore-cli/src/main.rs b/crates/diffcore-cli/src/main.rs index 8694955..b3c2583 100644 --- a/crates/diffcore-cli/src/main.rs +++ b/crates/diffcore-cli/src/main.rs @@ -272,7 +272,7 @@ struct EmbedDiffArgs { } fn main() { - env_logger::init(); + diffcore_core::logging::init(None); let cli = Cli::parse(); match cli.command { @@ -697,7 +697,7 @@ async fn run_refinement( ); for w in &warnings { - eprintln!("refinement repair: {}", w.message); + warn!(target: "refinement", "repair: {}", w.message); } analysis_output.groups = refined_groups; diff --git a/crates/diffcore-core/Cargo.toml b/crates/diffcore-core/Cargo.toml index cc5bb7a..537ab18 100644 --- a/crates/diffcore-core/Cargo.toml +++ b/crates/diffcore-core/Cargo.toml @@ -30,6 +30,8 @@ bincode = "1" dashmap = "6" once_cell = "1" log = { workspace = true } +tracing = { workspace = true } +tracing-subscriber = { workspace = true, optional = true } tempfile = "3" tree-sitter-c-sharp = "0.23.1" tree-sitter-php = "0.24.2" @@ -48,12 +50,14 @@ test-support = [] ## Enables local code embeddings via fastembed (ONNX Runtime + Jina Code model). ## Used for semantic similarity between file diffs in clustering. embeddings = ["dep:fastembed"] +## Subscriber stack for the binaries; library consumers skip it. +logging = ["dep:tracing-subscriber"] # Enable test-support feature automatically when running tests # (dev-dependencies trigger `cfg(test)` in unit tests but not integration tests, # so we also enable the feature here for integration test access to `with_base_url`). [dev-dependencies] -diffcore-core = { path = ".", features = ["test-support"] } +diffcore-core = { path = ".", features = ["test-support", "logging"] } proptest = "1" tokio = { version = "1", features = ["full", "test-util"] } wiremock = "0.6" diff --git a/crates/diffcore-core/src/lib.rs b/crates/diffcore-core/src/lib.rs index c6502b3..1be85a5 100644 --- a/crates/diffcore-core/src/lib.rs +++ b/crates/diffcore-core/src/lib.rs @@ -19,6 +19,8 @@ pub mod git; pub mod graph; pub mod ir; pub mod llm; +#[cfg(feature = "logging")] +pub mod logging; pub mod output; pub mod pipeline; pub mod query_engine; diff --git a/crates/diffcore-core/src/llm/claude_cli.rs b/crates/diffcore-core/src/llm/claude_cli.rs index 7cde831..c1b4e52 100644 --- a/crates/diffcore-core/src/llm/claude_cli.rs +++ b/crates/diffcore-core/src/llm/claude_cli.rs @@ -269,11 +269,7 @@ where output.push('\n'); } if let Some(update) = summarize_claude_line(&line, stream_name, parse_json) { - if let Some(callback) = &activity_callback { - callback(update); - } else { - super::emit_activity(update); - } + super::emit_activity_with(update, activity_callback.as_ref()); } } Ok(output) @@ -555,9 +551,44 @@ fn truncate_for_activity(text: &str) -> String { mod tests { use serde_json::json; + use std::sync::{Arc, Mutex}; + use super::{ - parse_claude_structured_output, summarize_claude_assistant, summarize_claude_tool_input, + collect_claude_stream, parse_claude_structured_output, summarize_claude_assistant, + summarize_claude_tool_input, }; + use crate::llm::activity_logging_tests::capture_logs; + use crate::llm::{ActivityCallback, ActivityUpdate}; + + /// Regression: the stream collectors used to call the UI callback *instead* + /// of the logging path, so the desktop app showed warnings the terminal + /// never saw. Both must fire. + #[test] + fn stream_events_are_logged_when_a_ui_callback_is_installed() { + let seen: Arc>> = Arc::new(Mutex::new(Vec::new())); + let sink = Arc::clone(&seen); + let callback: ActivityCallback = Arc::new(move |update: ActivityUpdate| { + if let Ok(mut seen) = sink.lock() { + seen.push(update); + } + }); + + let out = capture_logs(|| { + let rt = tokio::runtime::Builder::new_current_thread() + .build() + .expect("runtime"); + rt.block_on(async { + let stderr = &b"Sandbox disabled: bwrap not installed\n"[..]; + collect_claude_stream(stderr, "stderr", false, Some(callback)) + .await + .expect("collect"); + }); + }); + + assert!(out.contains("WARN"), "not logged to the terminal: {out}"); + assert!(out.contains("Sandbox disabled"), "{out}"); + assert_eq!(seen.lock().unwrap().len(), 1, "UI callback must still fire"); + } #[test] fn tool_input_prefers_concrete_path_details() { diff --git a/crates/diffcore-core/src/llm/codex_cli.rs b/crates/diffcore-core/src/llm/codex_cli.rs index 39435d8..343a8c4 100644 --- a/crates/diffcore-core/src/llm/codex_cli.rs +++ b/crates/diffcore-core/src/llm/codex_cli.rs @@ -276,11 +276,7 @@ where output.push('\n'); } if let Some(update) = summarize_codex_line(&line, stream_name) { - if let Some(callback) = &activity_callback { - callback(update); - } else { - super::emit_activity(update); - } + super::emit_activity_with(update, activity_callback.as_ref()); } } Ok(output) @@ -316,14 +312,24 @@ fn summarize_codex_line(line: &str, stream_name: &str) -> Option summarize_codex_item(parsed.get("item")?, stream_name, true), Some("item.completed") => summarize_codex_item(parsed.get("item")?, stream_name, false), - _ => Some(super::ActivityUpdate { - source: "codex".to_string(), - level: "info".to_string(), - message: truncate_for_activity(trimmed), - event_type, - payload: Some(parsed), - timestamp_ms: super::timestamp_ms(), - }), + other => { + let level = level_for_event(other.unwrap_or_default()); + // Failures nest the useful text; the raw line truncates before it. + let detail = parsed + .get("error") + .and_then(|error| error.get("message").or(Some(error))) + .and_then(serde_json::Value::as_str) + .or_else(|| parsed.get("message").and_then(serde_json::Value::as_str)) + .unwrap_or(trimmed); + Some(super::ActivityUpdate { + source: "codex".to_string(), + level, + message: truncate_for_activity(detail), + event_type, + payload: Some(parsed), + timestamp_ms: super::timestamp_ms(), + }) + } } } @@ -383,6 +389,7 @@ fn summarize_codex_item( .get("path") .and_then(serde_json::Value::as_str) .or_else(|| item.get("file").and_then(serde_json::Value::as_str)) + .or_else(|| item.get("message").and_then(serde_json::Value::as_str)) .map(truncate_for_activity); let base_message = if other.contains("search") || other.contains("grep") || other.contains("find") { @@ -406,7 +413,7 @@ fn summarize_codex_item( .unwrap_or(base_message); Some(super::ActivityUpdate { source: "codex".to_string(), - level: "info".to_string(), + level: level_for_event(other), message, event_type: Some(format!("{}.{}", stream_name, other)), payload: Some(item.clone()), @@ -416,6 +423,17 @@ fn summarize_codex_item( } } +/// Called only from the catch-all arms, i.e. on names nothing else matched. +/// Codex labels failures `error` / `turn.failed`. +fn level_for_event(name: &str) -> String { + if name.contains("error") || name.contains("failed") { + "error" + } else { + "info" + } + .to_string() +} + fn humanize_event_name(value: &str) -> String { value.replace('_', " ") } @@ -460,7 +478,7 @@ fn looks_like_structured_json(text: &str) -> bool { mod tests { use serde_json::json; - use super::{pretty_codex_command, summarize_codex_item}; + use super::{pretty_codex_command, summarize_codex_item, summarize_codex_line}; #[test] fn pretty_codex_command_unwraps_shell_prefixes() { @@ -490,4 +508,38 @@ mod tests { "Inspecting a file: crates/diffcore-tauri/ui/src/App.tsx" ); } + + /// Codex failures used to render as `INFO "Completed error"`, so a real + /// backend failure was invisible under `RUST_LOG=warn` and carried no detail. + #[test] + fn codex_error_items_are_reported_as_errors_with_detail() { + let item = json!({ + "type": "error", + "message": "stream error: 400 Bad Request" + }); + + let update = summarize_codex_item(&item, "stdout", false).expect("activity update"); + + assert_eq!(update.level, "error"); + assert!( + update.message.contains("stream error: 400 Bad Request"), + "detail dropped: {}", + update.message + ); + } + + #[test] + fn unrecognised_codex_failure_events_are_reported_as_errors() { + let line = json!({ "type": "turn.failed", "error": "context window exceeded" }); + + let update = + summarize_codex_line(&line.to_string(), "stdout").expect("activity update"); + + assert_eq!(update.level, "error"); + assert!( + update.message.contains("context window exceeded"), + "detail buried in raw JSON: {}", + update.message + ); + } } diff --git a/crates/diffcore-core/src/llm/mod.rs b/crates/diffcore-core/src/llm/mod.rs index 6fedd46..f938357 100644 --- a/crates/diffcore-core/src/llm/mod.rs +++ b/crates/diffcore-core/src/llm/mod.rs @@ -154,8 +154,28 @@ where ACTIVITY_CALLBACK.scope(callback, future).await } +/// Callback is passed explicitly because task-locals do not cross `tokio::spawn`. +pub(crate) fn emit_activity_with(mut update: ActivityUpdate, callback: Option<&ActivityCallback>) { + // Backend output reaches persistent logs now, not just the in-memory UI stream. + update.message = redact_api_keys(&update.message); + let source = update.source.as_str(); + let event_type = update.event_type.as_deref().unwrap_or("-"); + let message = update.message.as_str(); + match update.level.as_str() { + "error" => tracing::error!(target: "activity", source, event_type, "{message}"), + "warning" => tracing::warn!(target: "activity", source, event_type, "{message}"), + _ => tracing::info!(target: "activity", source, event_type, "{message}"), + } + match callback { + Some(callback) => callback(update), + None => { + let _ = ACTIVITY_CALLBACK.try_with(|callback| callback(update)); + } + } +} + pub(crate) fn emit_activity(update: ActivityUpdate) { - let _ = ACTIVITY_CALLBACK.try_with(|callback| callback(update)); + emit_activity_with(update, None); } pub(crate) fn current_activity_callback() -> Option { @@ -616,7 +636,10 @@ pub fn estimate_tokens(text: &str) -> usize { /// displayed in the UI or logs. pub fn redact_api_keys(text: &str) -> String { // Truncate to a safe length first (no error body needs to be > 500 chars) - let truncated = if text.len() > 500 { &text[..500] } else { text }; + let truncated = match text.char_indices().nth(500) { + Some((idx, _)) => &text[..idx], + None => text, + }; let mut result = truncated.to_string(); @@ -630,16 +653,27 @@ pub fn redact_api_keys(text: &str) -> String { ]; for &(prefix, replacement) in prefixes { - while let Some(start) = result.find(prefix) { + let mut from = 0; + while let Some(rel) = result[from..].find(prefix) { + let start = from + rel; + // `sk-` occurs inside ordinary words (task-, risk-, disk-), so a key + // must start one. + let at_word_start = start == 0 + || !result[..start] + .chars() + .next_back() + .is_some_and(char::is_alphanumeric); // Find the end of the key (alphanumeric, dash, underscore chars) let key_end = result[start + prefix.len()..] .find(|c: char| !c.is_alphanumeric() && c != '-' && c != '_') .map_or(result.len(), |pos| start + prefix.len() + pos); // Only redact if the key-like string is at least 10 chars total - if key_end - start >= 10 { + if at_word_start && key_end - start >= 10 { result.replace_range(start..key_end, replacement); + from = start + replacement.len(); } else { - break; + // Skip past this match; a later one may still be a real key. + from = start + prefix.len(); } } } @@ -1534,6 +1568,28 @@ mod tests { assert!(redacted.contains("[REDACTED_ANTHROPIC_KEY]")); } + /// Activity messages cap at 180 *chars*; non-ASCII made that >500 bytes, + /// and the old byte-slice truncation panicked mid-codepoint. + #[test] + fn redaction_does_not_panic_on_multibyte_text() { + let text = "构".repeat(183); + assert!(!redact_api_keys(&text).is_empty()); + } + + /// `sk-` occurs inside ordinary words, and bailing on the first non-key + /// match used to skip real keys later in the same line. + #[test] + fn redaction_leaves_ordinary_words_alone_and_still_finds_keys() { + assert_eq!( + redact_api_keys("Codex is running task-manager build"), + "Codex is running task-manager build" + ); + + let redacted = redact_api_keys("disk-usage high; using sk-abcdefghijklmnopqrstuv now"); + assert!(redacted.contains("disk-usage"), "{redacted}"); + assert!(!redacted.contains("sk-abcdef"), "key not redacted: {redacted}"); + } + #[test] fn test_redact_openai_key() { let body = @@ -1592,3 +1648,51 @@ mod tests { } } } + +#[cfg(test)] +pub(crate) mod activity_logging_tests { + use super::*; + use std::io; + use std::sync::Mutex; + + #[derive(Default)] + struct Capture(Mutex>); + + // `MakeWriter` is already implemented for `Arc where &W: io::Write`. + impl io::Write for &Capture { + fn write(&mut self, buf: &[u8]) -> io::Result { + if let Ok(mut sink) = self.0.lock() { + sink.extend_from_slice(buf); + } + Ok(buf.len()) + } + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + pub(crate) fn capture_logs(body: impl FnOnce()) -> String { + let capture = Arc::new(Capture::default()); + let subscriber = tracing_subscriber::fmt() + .with_writer(Arc::clone(&capture)) + .with_ansi(false) + .finish(); + tracing::subscriber::with_default(subscriber, body); + let bytes = capture.0.lock().unwrap_or_else(|e| e.into_inner()).clone(); + String::from_utf8(bytes).unwrap_or_default() + } + + #[test] + fn activity_levels_map_onto_tracing_levels() { + let out = capture_logs(|| { + emit_activity(ActivityUpdate::warning("codex", "rate limited", None)); + emit_activity(ActivityUpdate::info("claude", "starting pass 1", None)); + emit_activity(ActivityUpdate::error("codex", "backend exited", None)); + }); + + assert!(out.contains("WARN") && out.contains("rate limited"), "{out}"); + assert!(out.contains("INFO") && out.contains("starting pass 1"), "{out}"); + assert!(out.contains("ERROR") && out.contains("backend exited"), "{out}"); + assert!(out.contains("source=\"codex\""), "fields missing: {out}"); + } +} diff --git a/crates/diffcore-core/src/logging.rs b/crates/diffcore-core/src/logging.rs new file mode 100644 index 0000000..2ba4aaf --- /dev/null +++ b/crates/diffcore-core/src/logging.rs @@ -0,0 +1,123 @@ +//! Shared log setup for the CLI, web server and desktop app. + +use std::io::IsTerminal; +use std::path::PathBuf; + +use tracing_subscriber::fmt::writer::BoxMakeWriter; +use tracing_subscriber::EnvFilter; + +/// Install the global subscriber. Idempotent: later calls are no-ops. +/// +/// `RUST_LOG` sets the filter (default `info`), `DIFFCORE_LOG_FORMAT=json` +/// switches renderer. Output goes to stderr when it is a terminal, otherwise +/// to `DIFFCORE_LOG_FILE` or `fallback_file` — GUI bundles discard stderr. +pub fn init(fallback_file: Option) { + let raw = std::env::var("RUST_LOG").unwrap_or_default(); + let (spec, bad_filter) = resolve_filter(&raw); + let filter = EnvFilter::new(&spec); + + let path = resolve_sink( + std::env::var_os("DIFFCORE_LOG_FILE").map(PathBuf::from), + fallback_file, + std::io::stderr().is_terminal(), + ); + let mut open_error = None; + let file = path.as_ref().and_then(|path| { + if let Some(parent) = path.parent() { + let _ = std::fs::create_dir_all(parent); + } + std::fs::File::options() + .create(true) + .append(true) + .open(path) + .map_err(|e| open_error = Some(format!("{}: {e}", path.display()))) + .ok() + }); + + let builder = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_ansi( + file.is_none() + && std::io::stderr().is_terminal() + && std::env::var_os("NO_COLOR").is_none(), + ); + let builder = match file { + Some(file) => builder.with_writer(BoxMakeWriter::new(std::sync::Mutex::new(file))), + None => builder.with_writer(BoxMakeWriter::new(std::io::stderr)), + }; + + let _ = if std::env::var("DIFFCORE_LOG_FORMAT").as_deref() == Ok("json") { + builder.json().flatten_event(true).try_init() + } else { + builder.compact().try_init() + }; + + if bad_filter { + tracing::warn!("ignoring unparseable RUST_LOG {raw:?}, using `info`"); + } + if let Some(error) = open_error { + tracing::warn!("cannot open log file {error}; logging to stderr"); + } +} + +/// Log destination: `None` means stderr. +/// +/// A terminal is the better sink when there is one; `fallback` exists for GUI +/// launches (Finder, `.desktop`, Windows release) that discard stderr. +fn resolve_sink( + explicit: Option, + fallback: Option, + stderr_is_terminal: bool, +) -> Option { + match explicit { + Some(path) => Some(path), + None if stderr_is_terminal => None, + None => fallback, + } +} + +/// Effective filter spec, and whether `raw` was set but unparseable. +/// +/// An empty `RUST_LOG` means "unset", not "silence everything" — a blank value +/// in a `.env` or CI matrix must not blind the process to its own errors. +fn resolve_filter(raw: &str) -> (String, bool) { + let raw = raw.trim(); + if raw.is_empty() { + ("info".to_string(), false) + } else if EnvFilter::try_new(raw).is_err() { + ("info".to_string(), true) + } else { + (raw.to_string(), false) + } +} + +#[cfg(test)] +mod tests { + use super::{resolve_filter, resolve_sink}; + use std::path::PathBuf; + + #[test] + fn a_terminal_wins_over_the_gui_fallback_file() { + let explicit = || Some(PathBuf::from("/explicit.log")); + let fallback = || Some(PathBuf::from("/fallback.log")); + + // Desktop app launched from a terminal: log where the user is looking. + assert_eq!(resolve_sink(None, fallback(), true), None); + // Desktop app launched from Finder/.desktop: stderr goes nowhere. + assert_eq!(resolve_sink(None, fallback(), false), fallback()); + // CLI: stderr either way. + assert_eq!(resolve_sink(None, None, true), None); + assert_eq!(resolve_sink(None, None, false), None); + // An explicit request always wins. + assert_eq!(resolve_sink(explicit(), fallback(), true), explicit()); + assert_eq!(resolve_sink(explicit(), None, false), explicit()); + } + + #[test] + fn filter_falls_back_to_info_unless_the_spec_is_usable() { + assert_eq!(resolve_filter(""), ("info".to_string(), false)); + assert_eq!(resolve_filter(" "), ("info".to_string(), false)); + assert_eq!(resolve_filter("ir_cache=trace"), ("ir_cache=trace".to_string(), false)); + assert_eq!(resolve_filter("ir_cahce=trce=x"), ("info".to_string(), true)); + } +} diff --git a/crates/diffcore-core/src/pipeline.rs b/crates/diffcore-core/src/pipeline.rs index 96d70a5..444c0d2 100644 --- a/crates/diffcore-core/src/pipeline.rs +++ b/crates/diffcore-core/src/pipeline.rs @@ -18,7 +18,6 @@ //! ``` use dashmap::DashMap; -use log::{debug, info, warn}; use rayon::prelude::*; use sha2::{Digest, Sha256}; use std::path::{Path, PathBuf}; @@ -31,14 +30,6 @@ use crate::query_engine::QueryEngine; // Content-addressed IrFile cache // --------------------------------------------------------------------------- -/// Returns true when `DIFFCORE_CACHE_DEBUG=1` is set. -/// Checked once per process via `OnceLock`. -fn cache_debug_enabled() -> bool { - use std::sync::OnceLock; - static ENABLED: OnceLock = OnceLock::new(); - *ENABLED.get_or_init(|| std::env::var("DIFFCORE_CACHE_DEBUG").as_deref() == Ok("1")) -} - /// A thread-safe, content-addressed cache for parsed `IrFile` results. /// /// Key: `SHA-256(file_path + "\0" + source_content)` — identical content at the @@ -79,15 +70,11 @@ impl IrCache { match self.inner.get(&key) { Some(entry) => { self.hits.fetch_add(1, std::sync::atomic::Ordering::Relaxed); - if cache_debug_enabled() { - eprintln!("[IrCache] HIT {}", path); - } + tracing::trace!(target: "ir_cache", path, "hit"); Some(entry.value().clone()) } None => { - if cache_debug_enabled() { - eprintln!("[IrCache] MISS {}", path); - } + tracing::trace!(target: "ir_cache", path, "miss"); None } } @@ -122,23 +109,19 @@ impl IrCache { } /// Log cache statistics at debug level. - /// Also prints to stderr when `DIFFCORE_CACHE_DEBUG=1`. pub fn log_stats(&self) { let hits = self.hits(); let misses = self.misses(); let total = hits + misses; if total > 0 { - let msg = format!( - "IrCache stats: {} hits, {} misses, {} entries ({:.0}% hit rate)", + tracing::debug!( + target: "ir_cache", hits, misses, - self.len(), - (hits as f64 / total as f64) * 100.0 + entries = self.len(), + hit_rate = (hits as f64 / total as f64) * 100.0, + "cache stats" ); - debug!("{}", msg); - if cache_debug_enabled() { - eprintln!("[IrCache] {}", msg); - } } } } @@ -233,7 +216,8 @@ impl DiskIrCache { let ir: IrFile = match bincode::deserialize(&bytes) { Ok(ir) => ir, Err(e) => { - warn!( + tracing::warn!( + target: "ir_cache", "Skipping malformed IR cache entry {}: {}", path.display(), e @@ -248,7 +232,7 @@ impl DiskIrCache { let count = loaded_keys.len(); if count > 0 { - debug!("Loaded {} IR cache entries from disk", count); + tracing::debug!(target: "ir_cache", "Loaded {} entries from disk", count); } } @@ -270,8 +254,9 @@ impl DiskIrCache { /// This is best-effort: I/O errors are logged as warnings but never propagate. pub fn flush(&self) { if let Err(e) = std::fs::create_dir_all(&self.dir) { - warn!( - "Failed to create IR cache directory {}: {}", + tracing::warn!( + target: "ir_cache", + "Failed to create cache directory {}: {}", self.dir.display(), e ); @@ -292,19 +277,19 @@ impl DiskIrCache { match bincode::serialize(entry.value()) { Ok(bytes) => { if let Err(e) = std::fs::write(&path, &bytes) { - warn!("Failed to write IR cache entry {}: {}", path.display(), e); + tracing::warn!(target: "ir_cache", "Failed to write entry {}: {}", path.display(), e); } else { new_count += 1; } } Err(e) => { - warn!("Failed to serialize IR cache entry: {}", e); + tracing::warn!(target: "ir_cache", "Failed to serialize entry: {}", e); } } } if new_count > 0 { - info!("Wrote {} new IR cache entries to disk", new_count); + tracing::info!(target: "ir_cache", "Wrote {} new entries to disk", new_count); } // LRU eviction: if total size exceeds limit, remove oldest files first. @@ -350,7 +335,7 @@ impl DiskIrCache { break; } if let Err(e) = std::fs::remove_file(path) { - warn!("Failed to evict IR cache entry {}: {}", path.display(), e); + tracing::warn!(target: "ir_cache", "Failed to evict entry {}: {}", path.display(), e); } else { total_size -= size; evicted += 1; @@ -358,8 +343,9 @@ impl DiskIrCache { } if evicted > 0 { - info!( - "Evicted {} IR cache entries (disk usage now ~{} bytes)", + tracing::info!( + target: "ir_cache", + "Evicted {} entries (disk usage now ~{} bytes)", evicted, total_size ); } @@ -424,7 +410,7 @@ pub fn parse_to_ir( // Non-fatal: file may have syntax errors or unsupported language. match data_flow_result { Ok(df) => ir.enrich_with_data_flow(&df), - Err(e) => warn!( + Err(e) => tracing::warn!( "Data flow extraction failed for {}: {} (non-fatal, skipping enrichment)", path, e ), @@ -493,7 +479,7 @@ pub fn parse_files_parallel(files: &[(&str, &str)]) -> Vec { match result { Ok(file) => parsed.push(file), Err((path, e)) => { - warn!("Skipping file {} due to parse error: {}", path, e); + tracing::warn!("Skipping file {} due to parse error: {}", path, e); } } } diff --git a/crates/diffcore-tauri/Cargo.toml b/crates/diffcore-tauri/Cargo.toml index 29b8f2c..0cae912 100644 --- a/crates/diffcore-tauri/Cargo.toml +++ b/crates/diffcore-tauri/Cargo.toml @@ -14,7 +14,7 @@ desktop = [ "dep:tauri-plugin-updater", "dep:tauri-plugin-process", ] -web = ["tower-http/fs", "dep:env_logger"] +web = ["tower-http/fs"] custom-protocol = ["desktop", "tauri/custom-protocol"] [[bin]] @@ -28,7 +28,7 @@ path = "src/bin/web.rs" required-features = ["web"] [dependencies] -diffcore-core = { path = "../diffcore-core" } +diffcore-core = { path = "../diffcore-core", features = ["logging"] } tauri = { version = "2", features = [], optional = true } tauri-plugin-shell = { version = "2", optional = true } tauri-plugin-updater = { version = "2", optional = true } @@ -39,7 +39,7 @@ git2 = { workspace = true } tokio = { version = "1", features = ["full"] } thiserror = "2" log = { workspace = true } -env_logger = { version = "0.11", optional = true } +tracing = { workspace = true } axum = "0.7" async-stream = "0.3" tower-http = { version = "0.6", features = ["cors"] } diff --git a/crates/diffcore-tauri/src/activity_stream.rs b/crates/diffcore-tauri/src/activity_stream.rs index 76353f8..883551c 100644 --- a/crates/diffcore-tauri/src/activity_stream.rs +++ b/crates/diffcore-tauri/src/activity_stream.rs @@ -199,12 +199,14 @@ impl JobHandle { } pub async fn fail(&self, error: impl Into) { + let error = error.into(); + tracing::error!(target: "activity", job_id = %self.job_id, "{error}"); self.manager .push_event( &self.job_id, JobEvent::Failed { job_id: self.job_id.clone(), - error: error.into(), + error, timestamp_ms: timestamp_ms(), }, ) diff --git a/crates/diffcore-tauri/src/bin/web.rs b/crates/diffcore-tauri/src/bin/web.rs index 7508b81..bea0540 100644 --- a/crates/diffcore-tauri/src/bin/web.rs +++ b/crates/diffcore-tauri/src/bin/web.rs @@ -66,7 +66,7 @@ fn default_ui_dir() -> PathBuf { #[tokio::main] async fn main() -> ExitCode { - env_logger::Builder::from_env(env_logger::Env::default().default_filter_or("info")).init(); + diffcore_core::logging::init(None); let opts = match parse_args() { Ok(opts) => opts, Err(msg) => { diff --git a/crates/diffcore-tauri/src/commands.rs b/crates/diffcore-tauri/src/commands.rs index 721713c..2b72d00 100644 --- a/crates/diffcore-tauri/src/commands.rs +++ b/crates/diffcore-tauri/src/commands.rs @@ -155,7 +155,11 @@ impl serde::Serialize for CommandError { where S: serde::Serializer, { - serializer.serialize_str(&self.to_string()) + // Only reached when the error crosses the IPC boundary into the UI, so + // internally-handled errors stay quiet. + let message = self.to_string(); + tracing::error!(target: "command", "{message}"); + serializer.serialize_str(&message) } } @@ -611,9 +615,20 @@ fn make_activity_callback( }) } +/// Entries created here; core activity is logged by `emit_activity_with`. +async fn emit_logged_activity(job: &JobHandle, entry: ActivityEntry) { + tracing::info!( + target: "activity", + source = entry.source.as_str(), + event_type = entry.event_type.as_deref().unwrap_or("-"), + "{}", + entry.message + ); + job.emit(entry).await; +} + async fn emit_diffcore_activity(job: &JobHandle, message: impl Into) { - job.emit(ActivityEntry::info("diffcore", message, None)) - .await; + emit_logged_activity(job, ActivityEntry::info("diffcore", message, None)).await; } fn provider_supports_tool_activity(provider: &str) -> bool { @@ -788,11 +803,14 @@ async fn run_refinement_with_activity( .map_err(|e| CommandError::Llm(format!("{}", e)))?; if let Some(reasoning) = refinement_reasoning_excerpt(&response.reasoning) { - job.emit(ActivityEntry::info( - provider_name.clone(), - format!("Refinement rationale: {}", reasoning), - Some("refinement.reasoning".to_string()), - )) + emit_logged_activity( + &job, + ActivityEntry::info( + provider_name.clone(), + format!("Refinement rationale: {}", reasoning), + Some("refinement.reasoning".to_string()), + ), + ) .await; } @@ -825,6 +843,7 @@ async fn run_refinement_with_activity( ); for warning in &warnings { + tracing::warn!(target: "refinement", "repair: {}", warning.message); job.emit(ActivityEntry::info( provider_name.clone(), format!("Refinement repair: {}", warning.message), diff --git a/crates/diffcore-tauri/src/main.rs b/crates/diffcore-tauri/src/main.rs index ab69610..1fbc18c 100644 --- a/crates/diffcore-tauri/src/main.rs +++ b/crates/diffcore-tauri/src/main.rs @@ -39,6 +39,14 @@ fn set_macos_dock_icon() { } fn main() { + // Used only when stderr is not a terminal: GUI bundles discard it (no + // console on Windows release, Finder/.desktop launches drop it). Launched + // from a terminal, the desktop app still logs there. + // `~/.diffcore` matches the cache convention and is not world-writable. + let log_file = std::env::var_os("HOME") + .map(|home| std::path::PathBuf::from(home).join(".diffcore").join("desktop.log")) + .unwrap_or_else(|| std::env::temp_dir().join("diffcore-desktop.log")); + diffcore_core::logging::init(Some(log_file)); if let Err(e) = tauri::Builder::default() .plugin(tauri_plugin_shell::init()) .plugin(tauri_plugin_updater::Builder::new().build()) diff --git a/specs/diff-analyzer.md b/specs/diff-analyzer.md index e227ae2..de2a686 100644 --- a/specs/diff-analyzer.md +++ b/specs/diff-analyzer.md @@ -1083,7 +1083,7 @@ Goal: cache deterministic intermediate results so repeated/unchanged inputs skip - [x] All existing tests still pass (1638 tests: 1426 unit + 212 integration) - [x] Add a benchmark test (criterion) for: graph_build_from_ir (20/50/100 files, parallel vs serial) and flow_analysis/heuristic_patterns (20/50/100 files with 37 mixed call sites each) -- [x] Cache hit/miss logging behind `DIFFCORE_CACHE_DEBUG=1` env var (per-operation HIT/MISS lines + summary stats to stderr) +- [x] Cache hit/miss logging via tracing (`RUST_LOG=ir_cache=trace` for per-operation lines, `ir_cache=debug` for summary stats) - [x] No behavior change: cached results are byte-identical to uncached results (verified by `ir_cache_cached_result_byte_identical` test) ---