logging.rs

// Structured debug logging + metrics. Writes one JSON line per record to a
// debug log file (if configured) and exposes counters the core/TUI can show.
// ponytail: no tracing crate; a locked append is enough for a local harness.
use crate::message::{Content, ContentPart, Message};
use serde_json::{json, Value};
use std::fs::OpenOptions;
use std::io::Write;
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::{Arc, Mutex, OnceLock};
use std::time::Instant;

/// Process-wide mirror of `Config.debug_verbose`. Set once at core boot so
/// hot paths (provider HTTP, protocol emit) can check without holding State.
static DEBUG_VERBOSE: AtomicBool = AtomicBool::new(false);

/// Optional process-wide logger used by code that has no State handle
/// (provider HTTP, protocol emit mirror). Installed at boot when a debug log
/// path is configured; never cleared mid-session.
static GLOBAL_LOGGER: OnceLock<Arc<Logger>> = OnceLock::new();

/// Cap for verbose payloads (request bodies, tool args/outputs, event data)
/// so a single giant write_file or SSE dump cannot blow the log past rotation.
pub const VERBOSE_PAYLOAD_CAP: usize = 64 * 1024;

pub fn set_debug_verbose(on: bool) {
    DEBUG_VERBOSE.store(on, Ordering::SeqCst);
}

pub fn debug_verbose() -> bool {
    DEBUG_VERBOSE.load(Ordering::Relaxed)
}

/// Install the process-wide logger. First call wins (Arc clone shared).
pub fn install_global_logger(logger: Arc<Logger>) {
    let _ = GLOBAL_LOGGER.set(logger);
}

/// Best-effort log through the process-wide logger (no-op if not installed).
pub fn global_log(kind: &str, payload: Value) {
    if let Some(logger) = GLOBAL_LOGGER.get() {
        logger.log(kind, payload);
    }
}

/// Truncate a string for verbose logging. Returns (text, original_len, truncated).
pub fn truncate_for_log(s: &str, cap: usize) -> (String, usize, bool) {
    let len = s.len();
    if len <= cap {
        return (s.to_string(), len, false);
    }
    // Prefer a char boundary so we never emit invalid UTF-8 mid-grapheme.
    let mut end = cap.min(len);
    while end > 0 && !s.is_char_boundary(end) {
        end -= 1;
    }
    let mut out = s[..end].to_string();
    out.push_str(&format!(
        "\n…[truncated {omitted} chars]",
        omitted = len - end
    ));
    (out, len, true)
}

/// Truncate a JSON value's string form for verbose logging. Objects/arrays are
/// re-serialized then truncated; already-string values are truncated in place.
pub fn truncate_json_for_log(value: &Value, cap: usize) -> Value {
    match value {
        Value::String(s) => {
            let (text, len, truncated) = truncate_for_log(s, cap);
            if truncated {
                json!({ "text": text, "original_len": len, "truncated": true })
            } else {
                Value::String(text)
            }
        }
        other => {
            let rendered = serde_json::to_string(other).unwrap_or_else(|_| "null".into());
            let (text, len, truncated) = truncate_for_log(&rendered, cap);
            if truncated {
                json!({ "json": text, "original_len": len, "truncated": true })
            } else {
                // Prefer structured JSON when it fits; fall back to the string
                // form only if re-parse somehow fails (shouldn't).
                serde_json::from_str(&text).unwrap_or(Value::String(text))
            }
        }
    }
}

pub struct Logger {
    file: Mutex<Option<std::fs::File>>,
    turns: std::sync::atomic::AtomicU64,
    /// When true, callers may attach full request bodies / tool args / event
    /// mirrors. The flag also lives process-wide (`debug_verbose()`) so code
    /// without a Logger handle can check it.
    verbose: bool,
}

#[derive(Default, Clone, Debug)]
pub struct TurnMetrics {
    pub ttft_ms: Option<u64>,
    pub elapsed_ms: u64,
    pub tokens_in: u64,
    pub tokens_out: u64,
    pub cached_tokens: u64,
    pub tps: Option<f64>,
    pub model: String,
}

impl Logger {
    pub fn new(path: Option<&std::path::Path>) -> Self {
        Self::with_verbose(path, false)
    }

    pub fn with_verbose(path: Option<&std::path::Path>, verbose: bool) -> Self {
        let file = path.and_then(|p| {
            // Rotate once if the debug log has grown past a generous cap, so a
            // long-running session with CATALYST_CODE_DEBUG_LOG set can't fill
            // the disk. Single rotation: the current file is renamed to <path>.1
            // (overwriting any prior .1), then a fresh file is opened below.
            // Best-effort — rename errors are ignored (we just keep appending to
            // the oversized file). Only checked on open, not on every write.
            const ROTATE_CAP: u64 = 64 * 1024 * 1024; // 64 MiB
            if let Ok(meta) = std::fs::metadata(p) {
                if meta.len() > ROTATE_CAP {
                    let mut rotated = p.as_os_str().to_os_string();
                    rotated.push(".1");
                    let _ = std::fs::rename(p, &rotated);
                }
            }
            OpenOptions::new().create(true).append(true).open(p).ok()
        });
        // Keep the process-wide flag in sync so provider/protocol code can
        // check without a Logger handle. Safe to call repeatedly.
        set_debug_verbose(verbose);
        Self {
            file: Mutex::new(file),
            turns: std::sync::atomic::AtomicU64::new(0),
            verbose,
        }
    }

    pub fn is_verbose(&self) -> bool {
        self.verbose
    }

    /// Number of completed turns this session (incremented by main on turn_done).
    pub fn turn_count(&self) -> u64 {
        self.turns.load(std::sync::atomic::Ordering::SeqCst)
    }
    pub fn record_turn(&self) {
        self.turns.fetch_add(1, std::sync::atomic::Ordering::SeqCst);
    }
    /// Restore the turn counter from a persisted session (see `session::load_stats`)
    /// so `/stats` shows the real cumulative turn count after a restart instead of
    /// resetting to zero.
    pub fn set_turns(&self, n: u64) {
        self.turns.store(n, std::sync::atomic::Ordering::SeqCst);
    }

    /// Append one structured record. `kind` is a short tag (e.g. "tool", "http_retry").
    pub fn log(&self, kind: &str, payload: Value) {
        let (session_id, run_id) = (
            crate::runtime::current_session_id(),
            crate::runtime::current_run_id(),
        );
        let mut payload = payload;
        redact_log_value(&mut payload);
        let rec = json!({
            "ts": now_iso(),
            "kind": kind,
            "session_id": session_id,
            "run_id": run_id,
            "payload": payload,
        });
        let mut line = serde_json::to_string(&rec).unwrap_or_default();
        line.push('\n');
        if let Some(f) = self.file.lock().unwrap().as_mut() {
            let _ = f.write_all(line.as_bytes());
            let _ = f.flush();
        }
    }

    /// Log only when verbose mode is on. Used for high-volume mirrors (protocol
    /// events, full HTTP bodies) that would drown a normal debug log.
    pub fn log_verbose(&self, kind: &str, payload: Value) {
        if self.verbose {
            self.log(kind, payload);
        }
    }
}

/// Redact secret-bearing keys in place. Public so protocol mirrors can scrub
/// BEFORE `truncate_json_for_log` serializes a payload — otherwise a truncated
/// string form can embed a live `password` / `api_key` that key-based redaction
/// can no longer see.
pub fn redact_log_value(value: &mut Value) {
    match value {
        Value::Object(map) => {
            for (key, value) in map {
                if matches!(
                    key.to_ascii_lowercase().as_str(),
                    "api_key"
                        | "authorization"
                        | "password"
                        | "access_token"
                        | "refresh_token"
                        | "id_token"
                        | "client_secret"
                        | "oauth_token"
                ) {
                    *value = Value::String("[REDACTED]".into());
                } else {
                    redact_log_value(value);
                }
            }
        }
        Value::Array(values) => values.iter_mut().for_each(redact_log_value),
        _ => {}
    }
}

/// Rough token estimate: ~4 chars per token. Good enough for compaction triggers.
/// ponytail: no tokenizer dep; this is within ~15% for code/prose, fine for a threshold.
pub fn estimate_tokens(text: &str) -> u64 {
    // Byte length / 4 is ~as accurate as char/4 for ASCII-heavy code and avoids
    // a full Unicode walk on every soft-digest / compaction estimate.
    let n = text.len() as u64;
    n.saturating_add(3) / 4
}

/// Estimate tokens for a whole message list (serialize each message's text fields).
pub fn estimate_messages_tokens(messages: &[Message]) -> u64 {
    let mut total = 0u64;
    for m in messages {
        total += estimate_message_tokens(m);
    }
    total
}

/// Estimate tokens for a single message. Text-only messages serialize to
/// JSON and count chars/4 (within ~15% for prose/code). Multimodal messages
/// (content is an array of parts) exclude `image_url` data URLs: a base64
/// image is ~1.4M chars but only ~1-2k model tokens, so counting its chars
/// would over-estimate by orders of magnitude and trip compaction every turn
/// for vision users. Image parts are charged a fixed per-image token cost
/// instead; text parts are estimated normally.
pub fn estimate_message_tokens(m: &Message) -> u64 {
    const PER_IMAGE_TOKENS: u64 = 768;
    if let Some(parts) = m.content_parts() {
        let mut total = 0u64;
        let mut images = 0u64;
        for part in parts {
            match part {
                ContentPart::Image { .. } => images += 1,
                ContentPart::Text { text } => total += estimate_tokens(text),
            }
        }
        return total + images * PER_IMAGE_TOKENS + 4;
    }
    // Text-only message: sum role framing + text fields / 4. Avoids a full
    // serde Value round-trip on the hot soft-digest / compaction path.
    let mut n = 8u64; // role + JSON framing overhead
    match m {
        Message::System { content, .. } | Message::User { content, .. } => match content {
            Content::Text(s) => n += s.len() as u64,
            Content::Multimodal(parts) => {
                for part in parts {
                    if let ContentPart::Text { text } = part {
                        n += text.len() as u64;
                    }
                }
            }
        },
        Message::Assistant {
            content,
            thinking,
            tool_calls,
            ..
        } => {
            if let Some(c) = content {
                n += c.len() as u64;
            }
            if let Some(t) = thinking {
                n += t.len() as u64;
            }
            if let Some(tcs) = tool_calls {
                for tc in tcs {
                    n += tc.id.len() as u64;
                    n += tc.function.name.len() as u64;
                    n += tc.function.arguments.len() as u64;
                }
            }
        }
        Message::Tool {
            tool_call_id,
            content,
            ..
        } => {
            n += tool_call_id.len() as u64;
            n += content.len() as u64;
        }
    }
    n.saturating_add(3) / 4
}

/// Real-usage-anchored token estimate for a whole message list.
///
/// The endpoint reports the *real* `prompt_tokens` in its final `usage` chunk —
/// the authoritative count of the conversation exactly as the model tokenized
/// it (system prompt + every message + tool-call syntax + role framing that
/// the char/4 heuristic cannot see). When we have that number (`last_real`), use
/// it as the baseline and only char/4-estimate the messages appended *since*
/// (`len_at_real` onward). The delta is small (one assistant turn + a few tool
/// results), so its estimation error is tiny versus re-estimating the entire
/// history — which is what makes compaction fire at the right time and the
/// footer percentage track reality instead of drifting ±15-30%.
///
/// Falls back to a full `estimate_messages_tokens` when no real usage has been
/// seen yet (first turn) or right after compaction rewrites history (the old
/// baseline no longer describes the current messages).
pub fn grounded_estimate(messages: &[Message], last_real: Option<u64>, len_at_real: usize) -> u64 {
    match last_real {
        Some(real) => {
            // Clamp: a rewrite (undo/digest/compaction) may have shrunk the
            // list below the recorded index. When that happens the baseline is
            // stale and the caller should have invalidated it; clamp to len so
            // we never slice out of range, yielding just the baseline.
            let start = len_at_real.min(messages.len());
            real.saturating_add(estimate_messages_tokens(&messages[start..]))
        }
        None => estimate_messages_tokens(messages),
    }
}

pub fn now_iso() -> String {
    use std::time::{SystemTime, UNIX_EPOCH};
    let secs = SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .map(|d| d.as_secs())
        .unwrap_or(0);
    // ponytail: ISO formatting without chrono — seconds-since-epoch + a Z tag.
    format!("{secs}Z")
}

/// Helper for TTFT: record the first-token time relative to a turn start.
pub struct TurnTimer {
    pub start: Instant,
    /// Turn-level first generated token (reasoning, content, or tool-call
    /// chunk). Drives TTFT (time to first token of the whole turn).
    pub first_token: Option<Instant>,
    /// First generated token of the *current* stream call. `end_call` resets it
    /// so each request is timed independently of the wall time spent waiting for
    /// tool calls to run between requests.
    pub call_first_token: Option<Instant>,
    call_started: Option<Instant>,
    last_provider_call: Option<ProviderCallMetrics>,
    /// Accumulated generation time across every stream call in the turn (ms):
    /// each call's first-token → end window, summed. Excludes prefill (TTFT)
    /// and tool-call wait, so TPS reflects pure model generation throughput.
    pub gen_ms: u64,
    /// Accumulated real output tokens (completion_tokens/output_tokens) across
    /// all stream calls. TPS is only reported from this real usage count; when
    /// a provider omits usage we leave TPS blank instead of showing a char/4
    /// guess as if it were measured model throughput.
    pub out_tokens: u64,
    /// Accumulated char/4-estimated output tokens. Kept for token accounting and
    /// diagnostics, but deliberately NOT used for the footer TPS widget.
    pub out_tokens_est: u64,
}

#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)]
pub struct ProviderCallMetrics {
    pub duration_ms: u64,
    pub ttft_ms: Option<u64>,
    pub stream_ms: Option<u64>,
}

impl TurnTimer {
    pub fn new() -> Self {
        Self {
            start: Instant::now(),
            first_token: None,
            call_first_token: None,
            call_started: None,
            last_provider_call: None,
            gen_ms: 0,
            out_tokens: 0,
            out_tokens_est: 0,
        }
    }
    pub fn begin_provider_call(&mut self) {
        self.call_started = Some(Instant::now());
        self.call_first_token = None;
        self.last_provider_call = None;
    }
    /// Record the first generated token of the turn (TTFT) and of the current
    /// stream call (generation-time accounting). Called on the first reasoning,
    /// content, or tool-call chunk of each call.
    pub fn mark_first_token(&mut self) {
        let now = Instant::now();
        if self.first_token.is_none() {
            self.first_token = Some(now);
        }
        if self.call_first_token.is_none() {
            self.call_first_token = Some(now);
        }
    }
    /// Estimated in-flight throughput for the footer while a stream is still
    /// running. This is intentionally separate from final `tps`: the current
    /// stream's real usage is not available until the final usage chunk, so the
    /// live numerator uses the current char/4 output estimate and the UI marks it
    /// as approximate. Completed prior calls use real output tokens when any
    /// have been reported, else their estimate.
    pub fn live_tps_estimate(&self, current_est_out: u64) -> Option<f64> {
        let ft = self.call_first_token?;
        let current_ms = ft.elapsed().as_millis() as u64;
        if current_ms < 200 {
            return None;
        }
        let total_ms = self.gen_ms.saturating_add(current_ms);
        if total_ms == 0 {
            return None;
        }
        let completed_out = if self.out_tokens > 0 {
            self.out_tokens
        } else {
            self.out_tokens_est
        };
        let total_out = completed_out.saturating_add(current_est_out);
        if total_out == 0 {
            return None;
        }
        Some(total_out as f64 / (total_ms as f64 / 1000.0))
    }
    /// Close out one stream call: fold its generation time and output tokens
    /// into the turn totals. `tokens_out` is the real completion_tokens /
    /// output_tokens from usage (0 when the endpoint omits usage); `est_out` is
    /// the char/4 estimate retained for diagnostics/accounting only.
    pub fn end_call(&mut self, tokens_out: u64, est_out: u64) {
        if let Some(ft) = self.call_first_token {
            self.gen_ms = self.gen_ms.saturating_add(ft.elapsed().as_millis() as u64);
        }
        self.out_tokens = self.out_tokens.saturating_add(tokens_out);
        self.out_tokens_est = self.out_tokens_est.saturating_add(est_out);
        self.finish_provider_call();
        self.call_first_token = None;
    }

    pub fn finish_failed_provider_call(&mut self) {
        self.finish_provider_call();
        self.call_first_token = None;
    }

    pub fn take_provider_call_metrics(&mut self) -> Option<ProviderCallMetrics> {
        self.last_provider_call.take()
    }

    fn finish_provider_call(&mut self) {
        let Some(started) = self.call_started.take() else {
            return;
        };
        let duration_ms = started.elapsed().as_millis() as u64;
        let ttft_ms = self
            .call_first_token
            .map(|first| first.duration_since(started).as_millis() as u64);
        self.last_provider_call = Some(ProviderCallMetrics {
            duration_ms,
            ttft_ms,
            stream_ms: ttft_ms.map(|ttft| duration_ms.saturating_sub(ttft)),
        });
    }
    pub fn finalize(
        self,
        tokens_in: u64,
        tokens_out: u64,
        cached_tokens: u64,
        model: String,
    ) -> TurnMetrics {
        let elapsed_ms = self.start.elapsed().as_millis() as u64;
        let ttft_ms = self
            .first_token
            .map(|t| t.duration_since(self.start).as_millis() as u64);
        // TPS = output tokens / generation time. Generation time is the sum of
        // each stream call's first-token→end window, so it excludes both the
        // prefill latency (TTFT) and the wall time spent waiting for tool calls
        // to run between requests — i.e. pure model throughput, not end-to-end
        // wall time. Only real provider usage counts as TPS: showing a char/4
        // fallback made the footer look precise while actually being a guess,
        // and it drifted badly on tool-call JSON / reasoning-heavy turns.
        let tps = if self.gen_ms > 0 && self.out_tokens > 0 {
            Some(self.out_tokens as f64 / (self.gen_ms as f64 / 1000.0))
        } else {
            None
        };
        TurnMetrics {
            ttft_ms,
            elapsed_ms,
            tokens_in,
            tokens_out,
            cached_tokens,
            tps,
            model,
        }
    }
}

#[cfg(test)]
mod tests {
    use super::*;
    #[test]
    fn estimate_is_reasonable() {
        assert!(estimate_tokens("hello world foo bar") > 0);
        let m = vec![Message::user("hello world")];
        assert!(estimate_messages_tokens(&m) > 0);
    }

    #[test]
    fn grounded_estimate_uses_real_baseline_plus_delta() {
        // 4 messages; real prompt_tokens was recorded when the list had 2.
        let msgs = vec![
            Message::system("sys prompt here"),
            Message::user("first user message"),
            Message::assistant("assistant reply that grew the turn"),
            Message::tool("x", "tool output payload"),
        ];
        let real = 1_000u64;
        // Baseline covers msgs[0..2]; only msgs[2..4] should be char/4-estimated.
        let grounded = grounded_estimate(&msgs, Some(real), 2);
        let delta = estimate_messages_tokens(&msgs[2..]);
        assert_eq!(grounded, real + delta);
        // Must be strictly larger than re-estimating the whole list when the
        // real count exceeds the whole-list char/4 guess (which omits tool-call
        // framing, role tags, etc.) — i.e. the real baseline is authoritative.
        assert!(grounded > estimate_messages_tokens(&msgs));
    }

    #[test]
    fn grounded_estimate_falls_back_when_no_real_usage() {
        let msgs = vec![Message::user("hello world")];
        // No real baseline (first turn): behaves as a full char/4 estimate.
        assert_eq!(
            grounded_estimate(&msgs, None, 0),
            estimate_messages_tokens(&msgs)
        );
    }

    #[test]
    fn grounded_estimate_clamps_stale_length() {
        // Baseline recorded at length 10, but a rewrite shrank the list to 2.
        // Must clamp (never slice out of range) and yield just the baseline.
        let msgs = vec![Message::user("a"), Message::assistant("b")];
        let real = 500u64;
        assert_eq!(grounded_estimate(&msgs, Some(real), 10), real);
    }

    #[test]
    fn tps_uses_generation_time_not_wall_time() {
        let mut t = TurnTimer::new();
        // Two stream calls: 500 tok / 5s + 300 tok / 3s = 800 tok / 8s = 100 tok/s.
        // The tool-call wait between the calls is NOT in gen_ms, so TPS must be
        // 100 tok/s — not 800 / total-turn-wall-time, which the old elapsed-based
        // formula computed (dumping tool-wait into the denominator).
        t.gen_ms = 8000;
        t.out_tokens = 800;
        let m = t.finalize(1000, 800, 0, "test".into());
        assert!((m.tps.unwrap() - 100.0).abs() < 0.5, "tps was {:?}", m.tps);
    }

    #[test]
    fn tps_is_blank_when_provider_omits_usage() {
        let mut t = TurnTimer::new();
        // Endpoint reported no usage (out_tokens 0). Do not show the char/4
        // estimate as final TPS; it is not real model throughput.
        t.gen_ms = 4000;
        t.out_tokens = 0;
        t.out_tokens_est = 400;
        let m = t.finalize(1000, 0, 0, "test".into());
        assert!(m.tps.is_none());
    }

    #[test]
    fn live_tps_estimate_uses_current_stream_estimate() {
        let mut t = TurnTimer::new();
        t.gen_ms = 1000;
        t.out_tokens = 100;
        t.call_first_token = Some(Instant::now() - std::time::Duration::from_millis(1000));
        let live = t.live_tps_estimate(100).unwrap();
        assert!((live - 100.0).abs() < 1.0, "live tps was {live}");
    }

    #[test]
    fn tps_none_when_no_generation_time() {
        let t = TurnTimer::new();
        // Nothing streamed into gen_ms (e.g. only untimed tool-call args) → no TPS.
        let m = t.finalize(1000, 50, 0, "test".into());
        assert!(m.tps.is_none());
    }

    #[test]
    fn provider_call_metrics_split_ttft_and_stream_duration() {
        let mut timer = TurnTimer::new();
        timer.begin_provider_call();
        timer.call_started = Some(Instant::now() - std::time::Duration::from_millis(80));
        timer.call_first_token = Some(Instant::now() - std::time::Duration::from_millis(50));
        timer.end_call(1, 1);
        let metrics = timer.take_provider_call_metrics().unwrap();
        assert!(metrics.duration_ms >= 75);
        assert!(metrics
            .ttft_ms
            .is_some_and(|ttft| (25..=40).contains(&ttft)));
        assert!(metrics.stream_ms.is_some_and(|stream| stream >= 45));
    }

    #[test]
    fn failed_provider_call_still_records_duration() {
        let mut timer = TurnTimer::new();
        timer.begin_provider_call();
        timer.call_started = Some(Instant::now() - std::time::Duration::from_millis(20));
        timer.finish_failed_provider_call();
        let metrics = timer.take_provider_call_metrics().unwrap();
        assert!(metrics.duration_ms >= 15);
        assert_eq!(metrics.ttft_ms, None);
        assert_eq!(metrics.stream_ms, None);
    }

    #[test]
    fn structured_log_redacts_sudo_reply_password() {
        let path = std::env::temp_dir().join(format!(
            "catalyst-code-log-sudo-redaction-{}-{}.jsonl",
            std::process::id(),
            std::thread::current().name().unwrap_or("test")
        ));
        let _ = std::fs::remove_file(&path);
        {
            let logger = Logger::with_verbose(Some(&path), true);
            // Mirrors the dispatcher verbose command path shape after the
            // pre-truncate scrub: password must never reach the file.
            let mut cmd = json!({
                "type": "sudo_reply",
                "request_id": "sudo-789",
                "approved": true,
                "password": "hunter2-super-secret",
            });
            redact_log_value(&mut cmd);
            logger.log(
                "command",
                json!({ "raw": truncate_json_for_log(&cmd, VERBOSE_PAYLOAD_CAP) }),
            );
        }
        let text = std::fs::read_to_string(&path).unwrap();
        assert!(
            !text.contains("hunter2-super-secret"),
            "sudo password leaked into debug log: {text}"
        );
        let record: Value = serde_json::from_str(text.trim()).unwrap();
        assert_eq!(record["payload"]["raw"]["password"], "[REDACTED]");
        assert_eq!(record["payload"]["raw"]["type"], "sudo_reply");
        let _ = std::fs::remove_file(path);
        set_debug_verbose(false);
    }

    #[test]
    fn redact_before_truncate_keeps_password_out_of_flattened_payload() {
        // Even if a future change re-orders scrub vs truncate, redact_log_value
        // on the structured object must replace password before any string form
        // is taken — this is the invariant the dispatcher depends on.
        let mut cmd = json!({
            "type": "sudo_reply",
            "request_id": "sudo-1",
            "approved": true,
            "password": "never-in-log",
            "padding": "x".repeat(100),
        });
        redact_log_value(&mut cmd);
        let rendered = serde_json::to_string(&cmd).unwrap();
        assert!(!rendered.contains("never-in-log"));
        assert!(rendered.contains("[REDACTED]"));
        let capped = truncate_json_for_log(&cmd, 64);
        let capped_s = serde_json::to_string(&capped).unwrap();
        assert!(!capped_s.contains("never-in-log"));
    }

    #[test]
    fn structured_log_redacts_nested_credentials() {
        let path = std::env::temp_dir().join(format!(
            "catalyst-code-log-redaction-{}-{}.jsonl",
            std::process::id(),
            std::thread::current().name().unwrap_or("test")
        ));
        let _ = std::fs::remove_file(&path);
        {
            let logger = Logger::new(Some(&path));
            logger.log(
                "security_test",
                json!({
                    "api_key": "secret-one",
                    "nested": {"refresh_token": "secret-two", "safe": "visible"},
                }),
            );
        }
        let text = std::fs::read_to_string(&path).unwrap();
        let record: Value = serde_json::from_str(text.trim()).unwrap();
        assert_eq!(record["payload"]["api_key"], "[REDACTED]");
        assert_eq!(record["payload"]["nested"]["refresh_token"], "[REDACTED]");
        assert_eq!(record["payload"]["nested"]["safe"], "visible");
        assert!(!text.contains("secret-one"));
        assert!(!text.contains("secret-two"));
        let _ = std::fs::remove_file(path);
    }

    #[test]
    fn truncate_for_log_keeps_short_strings() {
        let (text, len, truncated) = truncate_for_log("hello", 100);
        assert_eq!(text, "hello");
        assert_eq!(len, 5);
        assert!(!truncated);
    }

    #[test]
    fn truncate_for_log_caps_long_strings() {
        let big = "x".repeat(1000);
        let (text, len, truncated) = truncate_for_log(&big, 50);
        assert!(truncated);
        assert_eq!(len, 1000);
        assert!(text.contains("[truncated 950 chars]"));
        assert!(text.len() < 100);
    }

    #[test]
    fn log_verbose_is_a_no_op_when_not_verbose() {
        let path = std::env::temp_dir().join(format!(
            "catalyst-code-log-verbose-off-{}-{}.jsonl",
            std::process::id(),
            std::thread::current().name().unwrap_or("test")
        ));
        let _ = std::fs::remove_file(&path);
        {
            let logger = Logger::with_verbose(Some(&path), false);
            logger.log_verbose("should_not_appear", json!({"x": 1}));
            logger.log("always", json!({"y": 2}));
        }
        let text = std::fs::read_to_string(&path).unwrap();
        assert!(!text.contains("should_not_appear"));
        assert!(text.contains("always"));
        let _ = std::fs::remove_file(path);
    }

    #[test]
    fn log_verbose_writes_when_verbose() {
        let path = std::env::temp_dir().join(format!(
            "catalyst-code-log-verbose-on-{}-{}.jsonl",
            std::process::id(),
            std::thread::current().name().unwrap_or("test")
        ));
        let _ = std::fs::remove_file(&path);
        {
            let logger = Logger::with_verbose(Some(&path), true);
            assert!(logger.is_verbose());
            assert!(debug_verbose());
            logger.log_verbose("http_request", json!({"url": "https://example.test"}));
        }
        let text = std::fs::read_to_string(&path).unwrap();
        assert!(text.contains("http_request"));
        assert!(text.contains("example.test"));
        // Reset process-wide flag so other tests aren't polluted.
        set_debug_verbose(false);
        let _ = std::fs::remove_file(path);
    }
}