From 184214b60afb61b73a3a33b069f30cdbdae5c686 Mon Sep 17 00:00:00 2001 From: Jake Date: Tue, 12 May 2026 22:27:06 +0100 Subject: [PATCH] =?UTF-8?q?agent:=20engine=20slop=20residuals=20B=20?= =?UTF-8?q?=E2=80=94=20eprintln=20=E2=86=92=20tracing=20sweep?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replaces 22 production eprintln! sites with structured tracing events across 8 files. Closes Area B of the post-prognosis residuals plan (docs/superpowers/plans/2026-05-12-engine-slop-residuals.md). Files touched (22 sites): - crates/hotkey/src/linux.rs (2) — hotplug watcher degraded-mode warnings - crates/ai-formatting/src/pipeline.rs (1) — LLM cleanup fallback warning - src-tauri/src/commands/transcription.rs (1) — chunking dispatch info - src-tauri/src/commands/diagnostics.rs (1) — crashes-dir setup warning - src-tauri/src/commands/tasks.rs (1) — malformed feedback row warning - src-tauri/src/commands/power.rs (3) — App Nap acquire/release/fail - src-tauri/src/commands/models.rs (5) — Whisper warmup lifecycle - src-tauri/src/commands/live.rs (8) — session start, chunk dispatch, per-chunk delivery, inference errors, worker disconnects, listener loss, status-channel cascade Levels: error for unrecoverable failures (inference disconnect, panic, status cascade), warn for recoverable degradation (LLM fallback, malformed rows, App Nap fail, hotplug watcher fail), info for lifecycle (session start, chunk processed, App Nap acquire/release, warmup complete, chunking dispatch), debug for per-chunk noise (speech-gate skip, chunk dispatch). Two new dependencies and two new filter targets: - tracing = "0.1" added to crates/hotkey and crates/ai-formatting - Default EnvFilter in src-tauri/src/lib.rs::init_tracing extended with magnotia_hotkey=info,magnotia_ai_formatting=info so the new targets emit at the default level Out of scope (intentional, left as-is): - crates/mcp/src/main.rs — CLI binary, stderr is the log contract (module docstring) so the JSON-RPC stdout stream stays clean - crates/*/tests/*.rs and crates/core/examples/tuning_log_demo.rs — test/example diagnostic output relies on --nocapture stdio semantics Discovery during sweep (not fixed — separate follow-up): hotkey crate has 6 existing log:: calls (log::error/warn/info/debug) but the workspace builds tracing-subscriber without the tracing-log feature, so those events are currently silent. Worth a follow-up to either add the tracing-log bridge or migrate hotkey's existing log:: calls to tracing::. Verification: - cargo fmt --all - cargo check --workspace --all-targets — clean - cargo test --workspace — 330+ tests, zero failures - rg eprintln! src-tauri/src/commands/ crates/hotkey/src/ crates/ai-formatting/src/ — zero hits Pre-existing working-tree churn in crates/llm/, src/lib/pages/, src/lib/utils/saveMarkdown.ts and the untracked phase10a dogfood notes deliberately left unstaged per Jake's instruction. Co-Authored-By: Claude Opus 4.7 (1M context) --- Cargo.lock | 2 + crates/ai-formatting/Cargo.toml | 1 + crates/ai-formatting/src/pipeline.rs | 5 +- crates/hotkey/Cargo.toml | 1 + crates/hotkey/src/linux.rs | 14 ++--- src-tauri/src/commands/diagnostics.rs | 2 +- src-tauri/src/commands/live.rs | 79 +++++++++++++------------ src-tauri/src/commands/models.rs | 28 +++++++-- src-tauri/src/commands/power.rs | 11 ++-- src-tauri/src/commands/tasks.rs | 8 ++- src-tauri/src/commands/transcription.rs | 7 ++- src-tauri/src/lib.rs | 2 +- 12 files changed, 95 insertions(+), 65 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d626491..a470247 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2829,6 +2829,7 @@ dependencies = [ "magnotia-core", "magnotia-llm", "regex-lite", + "tracing", ] [[package]] @@ -2882,6 +2883,7 @@ dependencies = [ "notify", "serde", "tokio", + "tracing", ] [[package]] diff --git a/crates/ai-formatting/Cargo.toml b/crates/ai-formatting/Cargo.toml index 576ac4c..0d0a1a3 100644 --- a/crates/ai-formatting/Cargo.toml +++ b/crates/ai-formatting/Cargo.toml @@ -8,3 +8,4 @@ description = "Text post-processing pipeline: filler removal, British English co magnotia-core = { path = "../core" } magnotia-llm = { path = "../llm" } regex-lite = "0.1" +tracing = "0.1" diff --git a/crates/ai-formatting/src/pipeline.rs b/crates/ai-formatting/src/pipeline.rs index 00e4baf..93aab42 100644 --- a/crates/ai-formatting/src/pipeline.rs +++ b/crates/ai-formatting/src/pipeline.rs @@ -91,8 +91,9 @@ pub fn post_process_segments( replace_segments_with_cleaned(segments, cleaned.trim()); } Ok(_) => {} - Err(err) => eprintln!( - "[ai-formatting] LLM cleanup failed, keeping rule-based output: {err}" + Err(err) => tracing::warn!( + error = %err, + "LLM cleanup failed, keeping rule-based output" ), } } diff --git a/crates/hotkey/Cargo.toml b/crates/hotkey/Cargo.toml index 825417e..db00b2c 100644 --- a/crates/hotkey/Cargo.toml +++ b/crates/hotkey/Cargo.toml @@ -9,6 +9,7 @@ magnotia-core = { path = "../core" } tokio = { version = "1", features = ["rt", "sync", "macros", "time"] } serde = { version = "1", features = ["derive"] } log = "0.4" +tracing = "0.1" [target.'cfg(target_os = "linux")'.dependencies] evdev = { version = "0.12", features = ["tokio"] } diff --git a/crates/hotkey/src/linux.rs b/crates/hotkey/src/linux.rs index 19f851e..5f18ef0 100644 --- a/crates/hotkey/src/linux.rs +++ b/crates/hotkey/src/linux.rs @@ -88,19 +88,19 @@ impl EvdevHotkeyListener { match w.watch(Path::new("/dev/input"), RecursiveMode::NonRecursive) { Ok(()) => Some(w), Err(e) => { - eprintln!( - "[magnotia-hotkey] cannot watch /dev/input ({e}); \ - hotplug detection disabled, devices present \ - at startup still work", + tracing::warn!( + error = %e, + "cannot watch /dev/input; hotplug detection disabled, \ + devices present at startup still work" ); None } } } Err(e) => { - eprintln!( - "[magnotia-hotkey] cannot create inotify watcher ({e}); \ - hotplug detection disabled", + tracing::warn!( + error = %e, + "cannot create inotify watcher; hotplug detection disabled" ); None } diff --git a/src-tauri/src/commands/diagnostics.rs b/src-tauri/src/commands/diagnostics.rs index fb71de1..e2b0742 100644 --- a/src-tauri/src/commands/diagnostics.rs +++ b/src-tauri/src/commands/diagnostics.rs @@ -33,7 +33,7 @@ const MAGNOTIA_VERSION: &str = env!("CARGO_PKG_VERSION"); /// Called once at startup before tauri::Builder. pub fn install_panic_hook() { if let Err(e) = fs::create_dir_all(crashes_dir()) { - eprintln!("[diagnostics] could not create crashes dir: {e}"); + tracing::warn!(error = %e, "could not create crashes dir; panic dumps disabled"); return; } diff --git a/src-tauri/src/commands/live.rs b/src-tauri/src/commands/live.rs index 614e0b5..335a071 100644 --- a/src-tauri/src/commands/live.rs +++ b/src-tauri/src/commands/live.rs @@ -529,9 +529,12 @@ pub async fn start_live_transcription_session( .model_id .clone() .unwrap_or_else(|| default_model_id_for_engine(&config.engine).to_string()); - eprintln!( - "[live] starting session: engine={}, model={}, language={:?}, save_audio={}", - config.engine, model_id, config.language, config.save_audio + tracing::info!( + engine = %config.engine, + model = %model_id, + language = ?config.language, + save_audio = config.save_audio, + "starting live session" ); // None: live-transcription model loads don't enforce sequential-GPU // mode. The Settings-level load flow owns that guard. @@ -788,14 +791,16 @@ fn maybe_dispatch_chunk( "insufficient_speech" => "insufficient speech energy", other => other, }; - eprintln!( - "[live] session {session_id}: skipped {skipped_ms}ms chunk as {gate_reason} \ -(peak_rms={:.6}, peak={:.6}, speech_windows={}/{}, max_consecutive={})", - speech_gate.peak_rms, - speech_gate.peak_amplitude, - speech_gate.speech_window_count, - speech_gate.window_count, - speech_gate.max_consecutive_speech_windows, + tracing::debug!( + session_id, + skipped_ms, + gate_reason, + peak_rms = speech_gate.peak_rms, + peak_amplitude = speech_gate.peak_amplitude, + speech_window_count = speech_gate.speech_window_count, + window_count = speech_gate.window_count, + max_consecutive_speech_windows = speech_gate.max_consecutive_speech_windows, + "skipped chunk on speech gate" ); let _ = status_channel.send(LiveStatusMessage::Warning { session_id, @@ -818,10 +823,12 @@ fn maybe_dispatch_chunk( let chunk_start_sample = *buffer_start_sample; let duration_secs = target_len as f64 / WHISPER_SAMPLE_RATE as f64; let chunk_samples = capture_buffer[..target_len].to_vec(); - eprintln!( - "[live] session {session_id}: dispatching chunk {} ({duration_secs:.2}s, {} samples)", - current_chunk_id, - chunk_samples.len() + tracing::debug!( + session_id, + chunk_id = current_chunk_id, + duration_secs, + samples = chunk_samples.len(), + "dispatching chunk" ); let advance_by = if stopping || target_len < CHUNK_SAMPLES { target_len @@ -925,28 +932,21 @@ fn poll_inference( &result_message, ); remember_recent_segments(recent_segments, &delivered_segments, chunk_start_secs); - eprintln!( - "[live] session {session_id}: {} chunk {} with {} segments in {}ms{}", - if delivered { - "delivered" - } else { - "processed without listener for" - }, - task.chunk_id, - segment_count, - timed.inference_ms, - if skipped_duplicates > 0 { - format!(" (skipped {skipped_duplicates} duplicate boundary segment(s))") - } else { - String::new() - } + tracing::info!( + session_id, + chunk_id = task.chunk_id, + segments = segment_count, + inference_ms = timed.inference_ms, + delivered, + skipped_duplicates, + "processed live chunk" ); *inflight = None; Ok(Some(true)) } Ok(Err(err)) => { - eprintln!("[live] session {session_id}: inference error: {err}"); + tracing::error!(session_id, error = %err, "inference error"); *inflight = None; let _ = status_channel.send(LiveStatusMessage::Error { session_id, @@ -958,7 +958,7 @@ fn poll_inference( Err(std::sync::mpsc::TryRecvError::Disconnected) => { *inflight = None; let message = "Inference worker disconnected unexpectedly".to_string(); - eprintln!("[live] session {session_id}: {message}"); + tracing::error!(session_id, "{message}"); let _ = status_channel.send(LiveStatusMessage::Error { session_id, message: message.clone(), @@ -983,9 +983,11 @@ fn emit_live_result( Ok(()) => true, Err(err) => { *result_listener_lost = true; - eprintln!( - "[live] session {}: result listener unavailable on chunk {}: {}; continuing without live updates", - result_message.session_id, result_message.chunk_id, err + tracing::warn!( + session_id = result_message.session_id, + chunk_id = result_message.chunk_id, + error = %err, + "result listener unavailable; continuing without live updates" ); // If the warning send also fails, the entire frontend channel // pair is dead — almost certainly the user closed the app @@ -999,10 +1001,9 @@ fn emit_live_result( message: "Live preview disconnected; transcription will continue in the background until you stop the session.".into(), }); if warn_send.is_err() { - eprintln!( - "[live] session {}: status channel also unavailable; \ - self-asserting stop_flag so the worker exits", - result_message.session_id + tracing::error!( + session_id = result_message.session_id, + "status channel also unavailable; self-asserting stop_flag so the worker exits" ); stop_flag.store(true, Ordering::Relaxed); } diff --git a/src-tauri/src/commands/models.rs b/src-tauri/src/commands/models.rs index a5f5cbd..d3dc526 100644 --- a/src-tauri/src/commands/models.rs +++ b/src-tauri/src/commands/models.rs @@ -207,17 +207,35 @@ pub fn prewarm_default_model(whisper_engine: Arc) { let silence = AudioSamples::mono_16khz(vec![0.0_f32; WHISPER_SAMPLE_RATE as usize]); let options = TranscriptionOptions::default(); match whisper_engine.transcribe_sync(&silence, &options) { - Ok(_) => eprintln!("[startup] Whisper warm-up inference complete"), - Err(e) => eprintln!("[startup] Whisper warm-up inference failed: {e}"), + Ok(_) => tracing::info!( + target: "magnotia_startup", + "Whisper warm-up inference complete" + ), + Err(e) => tracing::warn!( + target: "magnotia_startup", + error = %e, + "Whisper warm-up inference failed" + ), } }) }) .await; match result { - Ok(Ok(())) => eprintln!("[startup] Whisper model pre-warmed successfully"), - Ok(Err(e)) => eprintln!("[startup] Whisper pre-warm failed: {e}"), - Err(e) => eprintln!("[startup] Whisper pre-warm task panicked: {e}"), + Ok(Ok(())) => tracing::info!( + target: "magnotia_startup", + "Whisper model pre-warmed successfully" + ), + Ok(Err(e)) => tracing::warn!( + target: "magnotia_startup", + error = %e, + "Whisper pre-warm failed" + ), + Err(e) => tracing::error!( + target: "magnotia_startup", + error = %e, + "Whisper pre-warm task panicked" + ), } }); } diff --git a/src-tauri/src/commands/power.rs b/src-tauri/src/commands/power.rs index 241aef1..9b6eefa 100644 --- a/src-tauri/src/commands/power.rs +++ b/src-tauri/src/commands/power.rs @@ -91,9 +91,9 @@ impl PowerAssertion { #[cfg(target_os = "macos")] if acquired { - eprintln!("[power] began macOS App Nap guard #{id} for reason '{reason}'"); + tracing::info!(assertion_id = id, reason, "began macOS App Nap guard"); } else { - eprintln!("[power] macOS App Nap guard could not begin activity for reason '{reason}'"); + tracing::warn!(reason, "macOS App Nap guard could not begin activity"); } #[cfg(not(target_os = "macos"))] @@ -135,9 +135,10 @@ impl Drop for PowerAssertion { #[cfg(target_os = "macos")] if let Some(handle) = self.activity.take() { objc_bridge::end_activity(handle); - eprintln!( - "[power] ended macOS App Nap guard #{} for reason '{}'", - self.id, self.reason + tracing::info!( + assertion_id = self.id, + reason = self.reason, + "ended macOS App Nap guard" ); } assertion_registry().lock().unwrap().remove(&self.id); diff --git a/src-tauri/src/commands/tasks.rs b/src-tauri/src/commands/tasks.rs index 5f67201..c5e9cf3 100644 --- a/src-tauri/src/commands/tasks.rs +++ b/src-tauri/src/commands/tasks.rs @@ -227,9 +227,11 @@ fn to_llm_examples(rows: Vec) -> Vec { let ctx: serde_json::Value = match serde_json::from_str(raw) { Ok(v) => v, Err(e) => { - eprintln!( - "[feedback] skipping row id={} with malformed context_json: {e}", - r.id + tracing::warn!( + target: "magnotia_lib::feedback", + row_id = r.id, + error = %e, + "skipping feedback row with malformed context_json" ); return None; } diff --git a/src-tauri/src/commands/transcription.rs b/src-tauri/src/commands/transcription.rs index 2b06a50..6060f29 100644 --- a/src-tauri/src/commands/transcription.rs +++ b/src-tauri/src/commands/transcription.rs @@ -88,8 +88,11 @@ fn transcribe_samples_sync( .saturating_sub(strategy.overlap_samples) .max(1); let chunk_count = ((samples.len().saturating_sub(1)) / stride) + 1; - eprintln!( - "[transcription] chunking {total_duration_secs:.2}s of {engine_name} audio into {chunk_count} chunk(s)" + tracing::info!( + engine = engine_name, + duration_secs = total_duration_secs, + chunk_count, + "chunking audio for transcription" ); let mut all_segments = Vec::new(); diff --git a/src-tauri/src/lib.rs b/src-tauri/src/lib.rs index 1e0de59..dd29c9b 100644 --- a/src-tauri/src/lib.rs +++ b/src-tauri/src/lib.rs @@ -162,7 +162,7 @@ fn init_tracing() { TRACING_INIT.call_once(|| { let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { EnvFilter::new( - "warn,magnotia=info,magnotia_lib=info,magnotia_audio=info,magnotia_startup=info", + "warn,magnotia=info,magnotia_lib=info,magnotia_audio=info,magnotia_startup=info,magnotia_hotkey=info,magnotia_ai_formatting=info", ) });