From aa551e2d51dfc8df92616d38da9cf4ad87574880 Mon Sep 17 00:00:00 2001 From: Jakob Stender Guldberg Date: Fri, 28 Aug 2026 11:13:08 +0200 Subject: [PATCH] feat(logging): structured logging via tracing across all binaries The desktop UI surfaced backend warnings that never reached the terminal: emit_activity() only invoked the UI callback, and the CLI's bare env_logger::init() defaulted to `error`, hiding every existing log:: site. Replace env_logger with tracing + tracing-subscriber behind a shared logging::init(). RUST_LOG sets the filter (default info; an empty or unparseable value falls back to info rather than silencing the process), DIFFCORE_LOG_FORMAT=json switches renderer, and DIFFCORE_LOG_FILE redirects to a file. Output prefers stderr whenever it is a terminal; the desktop app falls back to ~/.diffcore/desktop.log only when it is not, since Finder and .desktop launches discard stderr. ANSI is emitted only to a real terminal and honours NO_COLOR. Existing log:: call sites and dependency logs bridge in via tracing-log, so no call site had to be rewritten. Route activity through emit_activity_with() so the UI callback and the logging path can no longer diverge; task-locals do not cross tokio::spawn, so stream collectors pass the callback explicitly. Close the channels that showed a user something while logging nothing: JobHandle::fail, CommandError's IPC serialization, codex error items and unrecognised failure events (which logged at info as "Completed error" with no detail, and now carry the nested error message). Redact api keys from activity messages before they reach persistent logs. Doing so exposed two bugs in redact_api_keys, now fixed: it byte-sliced at 500 bytes while activity messages cap at 180 *chars*, panicking mid-codepoint on non-ASCII output and killing the whole run via a JoinError; and `sk-` matched inside ordinary words (task-, risk-, disk-), corrupting them while `break` skipped real keys later in the same line. Note update.payload is still unredacted -- it does not reach the logs, only the UI and SSE stream. Filterable targets: `activity` for backend events, `ir_cache` for the IR cache (replacing the bespoke DIFFCORE_CACHE_DEBUG env gate), `refinement` for repair warnings, `command` for IPC errors. tracing-subscriber sits behind a default-off `logging` feature so library consumers do not link the subscriber stack. --- AGENTS.md | 1 + Cargo.lock | 177 +++++++++++-------- Cargo.toml | 2 + README.md | 18 ++ crates/diffcore-cli/Cargo.toml | 3 +- crates/diffcore-cli/src/main.rs | 4 +- crates/diffcore-core/Cargo.toml | 6 +- crates/diffcore-core/src/lib.rs | 2 + crates/diffcore-core/src/llm/claude_cli.rs | 43 ++++- crates/diffcore-core/src/llm/codex_cli.rs | 82 +++++++-- crates/diffcore-core/src/llm/mod.rs | 114 +++++++++++- crates/diffcore-core/src/logging.rs | 123 +++++++++++++ crates/diffcore-core/src/pipeline.rs | 58 +++--- crates/diffcore-tauri/Cargo.toml | 6 +- crates/diffcore-tauri/src/activity_stream.rs | 4 +- crates/diffcore-tauri/src/bin/web.rs | 2 +- crates/diffcore-tauri/src/commands.rs | 35 +++- crates/diffcore-tauri/src/main.rs | 8 + specs/diff-analyzer.md | 2 +- 19 files changed, 534 insertions(+), 156 deletions(-) create mode 100644 crates/diffcore-core/src/logging.rs diff --git a/AGENTS.md b/AGENTS.md index ee9a34b3..8cdfa01c 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 e71df79c..70a21b48 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 001f9f55..5926dda9 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 0476c8c2..aa536257 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 9fa9c722..c1e194fd 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 86949551..b3c2583a 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 cc5bb7ab..537ab18c 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 c6502b38..1be85a5a 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 7cde8314..c1b4e528 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 39435d83..343a8c45 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 6fedd46a..f9383574 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 00000000..2ba4aaf6 --- /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 96d70a56..444c0d22 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 29b8f2cf..0cae9124 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 76353f87..883551c6 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 7508b81d..bea05401 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 721713c5..2b72d003 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 ab69610e..1fbc18cc 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 e227ae26..de2a6864 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) ---