supercode_harness/

slow_log.rs

//! The slow log: a command or door call that takes more than a second is one JSON line in
//! `<supercode home>/logs/slow.jsonl`, so slowness reads as bug monitoring (the audit reads it
//! every round). The Node packages write the same lines (`@volter/supercode-harness-sdk/slow-log`).
//!
//! `{ v: 1, at, kind: "command"|"door"|"call", name, args, ms, outcome, machine, pid, caller,
//! slowest: { step, ms } }`. `slowest` is the longest step the command noted. Writing never
//! fails the command it measures.

use std::io::Write;
use std::path::PathBuf;
use std::sync::Mutex;
use std::time::Instant;

/// Anything slower than this many milliseconds is written.
pub const SLOW_MS: u128 = 1000;

/// The log's size before it rotates: it and the one rotation before it are all that is kept.
pub const ROTATE_BYTES: u64 = 4 * 1024 * 1024;

/// How many rotated logs are kept beside the current one.
pub const KEEP_ROTATED: usize = 3;

static SLOWEST: Mutex<Option<(String, u128)>> = Mutex::new(None);
/// Every step the running command noted: its name, total milliseconds and count.
static STEPS: Mutex<Vec<(String, u128, u32)>> = Mutex::new(Vec::new());

/// A step of the running command took `ms`; the longest is the command's `slowest`, and every
/// step's total is in its line's `steps`.
pub fn note_step(step: &str, ms: u128) {
    if let Ok(mut slowest) = SLOWEST.lock() {
        if slowest.as_ref().is_none_or(|(_, longest)| ms > *longest) {
            *slowest = Some((step.to_string(), ms));
        }
    }
    if let Ok(mut steps) = STEPS.lock() {
        match steps.iter_mut().find(|(name, _, _)| name == step) {
            Some((_, total, count)) => {
                *total += ms;
                *count += 1;
            }
            None => steps.push((step.to_string(), ms, 1)),
        }
    }
}

/// The steps noted so far, longest total first: where a slow command spent its time.
fn step_totals() -> serde_json::Value {
    let mut steps = STEPS.lock().map(|steps| steps.clone()).unwrap_or_default();
    steps.sort_by(|a, b| b.1.cmp(&a.1));
    serde_json::Value::Array(
        steps
            .into_iter()
            .take(12)
            .map(|(step, ms, count)| serde_json::json!({ "step": step, "ms": ms as u64, "count": count }))
            .collect(),
    )
}

/// Run `f` as the step `step` of the running command.
pub fn timed<T>(step: &str, f: impl FnOnce() -> T) -> T {
    let started = Instant::now();
    let value = f();
    note_step(step, started.elapsed().as_millis());
    value
}

/// The longest step noted so far.
pub fn slowest_step() -> Option<(String, u128)> {
    SLOWEST.lock().ok().and_then(|slowest| slowest.clone())
}

/// Where the lines go.
pub fn path() -> PathBuf {
    crate::agent::global_instructions_dir()
        .join("logs")
        .join("slow.jsonl")
}

fn secret_flag(flag: &str) -> bool {
    let name = flag.trim_start_matches('-').to_ascii_lowercase();
    matches!(
        name.as_str(),
        "token"
            | "key"
            | "api-key"
            | "apikey"
            | "secret"
            | "password"
            | "passwd"
            | "credential"
            | "credentials"
            | "auth"
            | "authorization"
            | "bearer"
            | "cookie"
            | "session-token"
    )
}

fn secret_name(name: &str) -> bool {
    let name = name.to_ascii_lowercase();
    [
        "token",
        "secret",
        "password",
        "passwd",
        "credential",
        "api_key",
        "api-key",
        "apikey",
        "authorization",
        "cookie",
    ]
    .iter()
    .any(|word| name.contains(word))
}

fn secret_value(value: &str) -> bool {
    let token_like = |prefix: &str, min: usize| value.starts_with(prefix) && value.len() >= min;
    token_like("sk-", 19)
        || token_like("ghp_", 24)
        || token_like("gho_", 24)
        || token_like("ghs_", 24)
        || token_like("ghu_", 24)
        || token_like("ghr_", 24)
        || token_like("xoxb-", 15)
        || token_like("xoxp-", 15)
        || (value.starts_with("eyJ") && value.matches('.').count() == 2 && value.len() > 40)
        || (value.len() >= 40
            && value.bytes().all(|b| {
                b.is_ascii_alphanumeric() || matches!(b, b'+' | b'/' | b'_' | b'-' | b'=')
            }))
}

/// The arguments as the log keeps them: secrets replaced, each at most 200 characters.
pub fn redact_args(args: &[String]) -> Vec<String> {
    let mut out = Vec::with_capacity(args.len());
    let mut hide_next = false;
    for arg in args {
        if hide_next {
            out.push("[redacted]".to_string());
            hide_next = false;
            continue;
        }
        if let Some((flag, _)) = arg.split_once('=') {
            if flag.starts_with('-') && secret_flag(flag) {
                out.push(format!("{flag}=[redacted]"));
                continue;
            }
            if !flag.starts_with('-')
                && !flag.is_empty()
                && flag.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_')
                && secret_name(flag)
            {
                out.push(format!("{flag}=[redacted]"));
                continue;
            }
        }
        if arg.starts_with('-') && secret_flag(arg) {
            out.push(arg.clone());
            hide_next = true;
            continue;
        }
        if secret_value(arg) {
            out.push("[redacted]".to_string());
            continue;
        }
        if arg.chars().count() > 200 {
            out.push(format!("{}…", arg.chars().take(200).collect::<String>()));
        } else {
            out.push(arg.clone());
        }
    }
    out
}

/// Bounded: past [`ROTATE_BYTES`] the log is renamed to a name of its own (`slow.<ms>-<pid>.jsonl`) and starts
/// again, and only the newest [`KEEP_ROTATED`] are kept. A name per rotation: two processes rotating at once each
/// keep what they renamed (one fixed name let the second rename replace the first's file, losing its lines). The Node
/// writer rotates the same way.
fn rotate(path: &std::path::Path) {
    if !std::fs::metadata(path).is_ok_and(|meta| meta.len() > ROTATE_BYTES) {
        return;
    }
    let Some(dir) = path.parent() else { return };
    let now = std::time::SystemTime::now()
        .duration_since(std::time::UNIX_EPOCH)
        .map(|elapsed| elapsed.as_millis())
        .unwrap_or_default();
    if std::fs::rename(
        path,
        dir.join(format!("slow.{now:013}-{}.jsonl", std::process::id())),
    )
    .is_err()
    {
        return;
    }
    let mut rotated: Vec<std::path::PathBuf> = std::fs::read_dir(dir)
        .map(|entries| {
            entries
                .flatten()
                .map(|entry| entry.path())
                .filter(|path| {
                    path.file_name()
                        .and_then(|name| name.to_str())
                        .is_some_and(|name| {
                            name.starts_with("slow.")
                                && name.ends_with(".jsonl")
                                && name != "slow.jsonl"
                        })
                })
                .collect()
        })
        .unwrap_or_default();
    rotated.sort();
    let excess = rotated.len().saturating_sub(KEEP_ROTATED);
    for old in &rotated[..excess] {
        let _ = std::fs::remove_file(old);
    }
}

/// One line, when `ms` is above the bound. `caller` is asked only then (resolving a caller reads
/// the process table). Answers whether a line was written.
#[allow(clippy::too_many_arguments)]
pub fn record(
    kind: &str,
    name: &str,
    args: &[String],
    ms: u128,
    outcome: &str,
    slowest: Option<(String, u128)>,
    caller: impl FnOnce() -> Option<String>,
) -> bool {
    if ms <= SLOW_MS {
        return false;
    }
    let line = serde_json::json!({
        "v": 1,
        "at": supercode_interchange::sidecar::ms_to_rfc3339(
            std::time::SystemTime::now()
                .duration_since(std::time::UNIX_EPOCH)
                .map(|elapsed| elapsed.as_millis() as i64)
                .unwrap_or_default(),
        ),
        "kind": kind,
        "name": name,
        "args": redact_args(args),
        "ms": ms as u64,
        "outcome": outcome,
        "machine": crate::mailbox::local_machine_name(),
        "pid": std::process::id(),
        "caller": caller().map(|address| serde_json::json!({ "address": address })),
        "slowest": slowest.map(|(step, ms)| serde_json::json!({ "step": step, "ms": ms as u64 })),
        "steps": if kind == "command" { step_totals() } else { serde_json::Value::Null },
    });
    let path = path();
    if let Some(dir) = path.parent() {
        let _ = std::fs::create_dir_all(dir);
    }
    rotate(&path);
    std::fs::OpenOptions::new()
        .create(true)
        .append(true)
        .open(&path)
        .and_then(|mut file| writeln!(file, "{line}"))
        .is_ok()
}