agent: engine slop residuals B — eprintln → tracing sweep

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) <noreply@anthropic.com>
This commit is contained in:
2026-05-12 22:27:06 +01:00
parent 792fb5ea08
commit 184214b60a
12 changed files with 95 additions and 65 deletions

2
Cargo.lock generated
View File

@@ -2829,6 +2829,7 @@ dependencies = [
"magnotia-core", "magnotia-core",
"magnotia-llm", "magnotia-llm",
"regex-lite", "regex-lite",
"tracing",
] ]
[[package]] [[package]]
@@ -2882,6 +2883,7 @@ dependencies = [
"notify", "notify",
"serde", "serde",
"tokio", "tokio",
"tracing",
] ]
[[package]] [[package]]

View File

@@ -8,3 +8,4 @@ description = "Text post-processing pipeline: filler removal, British English co
magnotia-core = { path = "../core" } magnotia-core = { path = "../core" }
magnotia-llm = { path = "../llm" } magnotia-llm = { path = "../llm" }
regex-lite = "0.1" regex-lite = "0.1"
tracing = "0.1"

View File

@@ -91,8 +91,9 @@ pub fn post_process_segments(
replace_segments_with_cleaned(segments, cleaned.trim()); replace_segments_with_cleaned(segments, cleaned.trim());
} }
Ok(_) => {} Ok(_) => {}
Err(err) => eprintln!( Err(err) => tracing::warn!(
"[ai-formatting] LLM cleanup failed, keeping rule-based output: {err}" error = %err,
"LLM cleanup failed, keeping rule-based output"
), ),
} }
} }

View File

@@ -9,6 +9,7 @@ magnotia-core = { path = "../core" }
tokio = { version = "1", features = ["rt", "sync", "macros", "time"] } tokio = { version = "1", features = ["rt", "sync", "macros", "time"] }
serde = { version = "1", features = ["derive"] } serde = { version = "1", features = ["derive"] }
log = "0.4" log = "0.4"
tracing = "0.1"
[target.'cfg(target_os = "linux")'.dependencies] [target.'cfg(target_os = "linux")'.dependencies]
evdev = { version = "0.12", features = ["tokio"] } evdev = { version = "0.12", features = ["tokio"] }

View File

@@ -88,19 +88,19 @@ impl EvdevHotkeyListener {
match w.watch(Path::new("/dev/input"), RecursiveMode::NonRecursive) { match w.watch(Path::new("/dev/input"), RecursiveMode::NonRecursive) {
Ok(()) => Some(w), Ok(()) => Some(w),
Err(e) => { Err(e) => {
eprintln!( tracing::warn!(
"[magnotia-hotkey] cannot watch /dev/input ({e}); \ error = %e,
hotplug detection disabled, devices present \ "cannot watch /dev/input; hotplug detection disabled, \
at startup still work", devices present at startup still work"
); );
None None
} }
} }
} }
Err(e) => { Err(e) => {
eprintln!( tracing::warn!(
"[magnotia-hotkey] cannot create inotify watcher ({e}); \ error = %e,
hotplug detection disabled", "cannot create inotify watcher; hotplug detection disabled"
); );
None None
} }

View File

@@ -33,7 +33,7 @@ const MAGNOTIA_VERSION: &str = env!("CARGO_PKG_VERSION");
/// Called once at startup before tauri::Builder. /// Called once at startup before tauri::Builder.
pub fn install_panic_hook() { pub fn install_panic_hook() {
if let Err(e) = fs::create_dir_all(crashes_dir()) { 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; return;
} }

View File

@@ -529,9 +529,12 @@ pub async fn start_live_transcription_session(
.model_id .model_id
.clone() .clone()
.unwrap_or_else(|| default_model_id_for_engine(&config.engine).to_string()); .unwrap_or_else(|| default_model_id_for_engine(&config.engine).to_string());
eprintln!( tracing::info!(
"[live] starting session: engine={}, model={}, language={:?}, save_audio={}", engine = %config.engine,
config.engine, model_id, config.language, config.save_audio model = %model_id,
language = ?config.language,
save_audio = config.save_audio,
"starting live session"
); );
// None: live-transcription model loads don't enforce sequential-GPU // None: live-transcription model loads don't enforce sequential-GPU
// mode. The Settings-level load flow owns that guard. // mode. The Settings-level load flow owns that guard.
@@ -788,14 +791,16 @@ fn maybe_dispatch_chunk(
"insufficient_speech" => "insufficient speech energy", "insufficient_speech" => "insufficient speech energy",
other => other, other => other,
}; };
eprintln!( tracing::debug!(
"[live] session {session_id}: skipped {skipped_ms}ms chunk as {gate_reason} \ session_id,
(peak_rms={:.6}, peak={:.6}, speech_windows={}/{}, max_consecutive={})", skipped_ms,
speech_gate.peak_rms, gate_reason,
speech_gate.peak_amplitude, peak_rms = speech_gate.peak_rms,
speech_gate.speech_window_count, peak_amplitude = speech_gate.peak_amplitude,
speech_gate.window_count, speech_window_count = speech_gate.speech_window_count,
speech_gate.max_consecutive_speech_windows, 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 { let _ = status_channel.send(LiveStatusMessage::Warning {
session_id, session_id,
@@ -818,10 +823,12 @@ fn maybe_dispatch_chunk(
let chunk_start_sample = *buffer_start_sample; let chunk_start_sample = *buffer_start_sample;
let duration_secs = target_len as f64 / WHISPER_SAMPLE_RATE as f64; let duration_secs = target_len as f64 / WHISPER_SAMPLE_RATE as f64;
let chunk_samples = capture_buffer[..target_len].to_vec(); let chunk_samples = capture_buffer[..target_len].to_vec();
eprintln!( tracing::debug!(
"[live] session {session_id}: dispatching chunk {} ({duration_secs:.2}s, {} samples)", session_id,
current_chunk_id, chunk_id = current_chunk_id,
chunk_samples.len() duration_secs,
samples = chunk_samples.len(),
"dispatching chunk"
); );
let advance_by = if stopping || target_len < CHUNK_SAMPLES { let advance_by = if stopping || target_len < CHUNK_SAMPLES {
target_len target_len
@@ -925,28 +932,21 @@ fn poll_inference(
&result_message, &result_message,
); );
remember_recent_segments(recent_segments, &delivered_segments, chunk_start_secs); remember_recent_segments(recent_segments, &delivered_segments, chunk_start_secs);
eprintln!( tracing::info!(
"[live] session {session_id}: {} chunk {} with {} segments in {}ms{}", session_id,
if delivered { chunk_id = task.chunk_id,
"delivered" segments = segment_count,
} else { inference_ms = timed.inference_ms,
"processed without listener for" delivered,
}, skipped_duplicates,
task.chunk_id, "processed live chunk"
segment_count,
timed.inference_ms,
if skipped_duplicates > 0 {
format!(" (skipped {skipped_duplicates} duplicate boundary segment(s))")
} else {
String::new()
}
); );
*inflight = None; *inflight = None;
Ok(Some(true)) Ok(Some(true))
} }
Ok(Err(err)) => { Ok(Err(err)) => {
eprintln!("[live] session {session_id}: inference error: {err}"); tracing::error!(session_id, error = %err, "inference error");
*inflight = None; *inflight = None;
let _ = status_channel.send(LiveStatusMessage::Error { let _ = status_channel.send(LiveStatusMessage::Error {
session_id, session_id,
@@ -958,7 +958,7 @@ fn poll_inference(
Err(std::sync::mpsc::TryRecvError::Disconnected) => { Err(std::sync::mpsc::TryRecvError::Disconnected) => {
*inflight = None; *inflight = None;
let message = "Inference worker disconnected unexpectedly".to_string(); 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 { let _ = status_channel.send(LiveStatusMessage::Error {
session_id, session_id,
message: message.clone(), message: message.clone(),
@@ -983,9 +983,11 @@ fn emit_live_result(
Ok(()) => true, Ok(()) => true,
Err(err) => { Err(err) => {
*result_listener_lost = true; *result_listener_lost = true;
eprintln!( tracing::warn!(
"[live] session {}: result listener unavailable on chunk {}: {}; continuing without live updates", session_id = result_message.session_id,
result_message.session_id, result_message.chunk_id, err 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 // If the warning send also fails, the entire frontend channel
// pair is dead — almost certainly the user closed the app // 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(), message: "Live preview disconnected; transcription will continue in the background until you stop the session.".into(),
}); });
if warn_send.is_err() { if warn_send.is_err() {
eprintln!( tracing::error!(
"[live] session {}: status channel also unavailable; \ session_id = result_message.session_id,
self-asserting stop_flag so the worker exits", "status channel also unavailable; self-asserting stop_flag so the worker exits"
result_message.session_id
); );
stop_flag.store(true, Ordering::Relaxed); stop_flag.store(true, Ordering::Relaxed);
} }

View File

@@ -207,17 +207,35 @@ pub fn prewarm_default_model(whisper_engine: Arc<LocalEngine>) {
let silence = AudioSamples::mono_16khz(vec![0.0_f32; WHISPER_SAMPLE_RATE as usize]); let silence = AudioSamples::mono_16khz(vec![0.0_f32; WHISPER_SAMPLE_RATE as usize]);
let options = TranscriptionOptions::default(); let options = TranscriptionOptions::default();
match whisper_engine.transcribe_sync(&silence, &options) { match whisper_engine.transcribe_sync(&silence, &options) {
Ok(_) => eprintln!("[startup] Whisper warm-up inference complete"), Ok(_) => tracing::info!(
Err(e) => eprintln!("[startup] Whisper warm-up inference failed: {e}"), target: "magnotia_startup",
"Whisper warm-up inference complete"
),
Err(e) => tracing::warn!(
target: "magnotia_startup",
error = %e,
"Whisper warm-up inference failed"
),
} }
}) })
}) })
.await; .await;
match result { match result {
Ok(Ok(())) => eprintln!("[startup] Whisper model pre-warmed successfully"), Ok(Ok(())) => tracing::info!(
Ok(Err(e)) => eprintln!("[startup] Whisper pre-warm failed: {e}"), target: "magnotia_startup",
Err(e) => eprintln!("[startup] Whisper pre-warm task panicked: {e}"), "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"
),
} }
}); });
} }

View File

@@ -91,9 +91,9 @@ impl PowerAssertion {
#[cfg(target_os = "macos")] #[cfg(target_os = "macos")]
if acquired { 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 { } 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"))] #[cfg(not(target_os = "macos"))]
@@ -135,9 +135,10 @@ impl Drop for PowerAssertion {
#[cfg(target_os = "macos")] #[cfg(target_os = "macos")]
if let Some(handle) = self.activity.take() { if let Some(handle) = self.activity.take() {
objc_bridge::end_activity(handle); objc_bridge::end_activity(handle);
eprintln!( tracing::info!(
"[power] ended macOS App Nap guard #{} for reason '{}'", assertion_id = self.id,
self.id, self.reason reason = self.reason,
"ended macOS App Nap guard"
); );
} }
assertion_registry().lock().unwrap().remove(&self.id); assertion_registry().lock().unwrap().remove(&self.id);

View File

@@ -227,9 +227,11 @@ fn to_llm_examples(rows: Vec<FeedbackRow>) -> Vec<LlmFeedbackExample> {
let ctx: serde_json::Value = match serde_json::from_str(raw) { let ctx: serde_json::Value = match serde_json::from_str(raw) {
Ok(v) => v, Ok(v) => v,
Err(e) => { Err(e) => {
eprintln!( tracing::warn!(
"[feedback] skipping row id={} with malformed context_json: {e}", target: "magnotia_lib::feedback",
r.id row_id = r.id,
error = %e,
"skipping feedback row with malformed context_json"
); );
return None; return None;
} }

View File

@@ -88,8 +88,11 @@ fn transcribe_samples_sync(
.saturating_sub(strategy.overlap_samples) .saturating_sub(strategy.overlap_samples)
.max(1); .max(1);
let chunk_count = ((samples.len().saturating_sub(1)) / stride) + 1; let chunk_count = ((samples.len().saturating_sub(1)) / stride) + 1;
eprintln!( tracing::info!(
"[transcription] chunking {total_duration_secs:.2}s of {engine_name} audio into {chunk_count} chunk(s)" engine = engine_name,
duration_secs = total_duration_secs,
chunk_count,
"chunking audio for transcription"
); );
let mut all_segments = Vec::new(); let mut all_segments = Vec::new();

View File

@@ -162,7 +162,7 @@ fn init_tracing() {
TRACING_INIT.call_once(|| { TRACING_INIT.call_once(|| {
let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| { let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
EnvFilter::new( 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",
) )
}); });