supercode_harness/
slow_log.rs

1//! The slow log: a command or door call that takes more than a second is one JSON line in
2//! `<supercode home>/logs/slow.jsonl`, so slowness reads as bug monitoring (the audit reads it
3//! every round). The Node packages write the same lines (`@volter/supercode-harness-sdk/slow-log`).
4//!
5//! `{ v: 1, at, kind: "command"|"door"|"call", name, args, ms, outcome, machine, pid, caller,
6//! slowest: { step, ms } }`. `slowest` is the longest step the command noted. Writing never
7//! fails the command it measures.
8
9use std::io::Write;
10use std::path::PathBuf;
11use std::sync::Mutex;
12use std::time::Instant;
13
14/// Anything slower than this many milliseconds is written.
15pub const SLOW_MS: u128 = 1000;
16
17/// The log's size before it rotates: it and the one rotation before it are all that is kept.
18pub const ROTATE_BYTES: u64 = 4 * 1024 * 1024;
19
20static SLOWEST: Mutex<Option<(String, u128)>> = Mutex::new(None);
21/// Every step the running command noted: its name, total milliseconds and count.
22static STEPS: Mutex<Vec<(String, u128, u32)>> = Mutex::new(Vec::new());
23
24/// A step of the running command took `ms`; the longest is the command's `slowest`, and every
25/// step's total is in its line's `steps`.
26pub fn note_step(step: &str, ms: u128) {
27    if let Ok(mut slowest) = SLOWEST.lock() {
28        if slowest.as_ref().is_none_or(|(_, longest)| ms > *longest) {
29            *slowest = Some((step.to_string(), ms));
30        }
31    }
32    if let Ok(mut steps) = STEPS.lock() {
33        match steps.iter_mut().find(|(name, _, _)| name == step) {
34            Some((_, total, count)) => {
35                *total += ms;
36                *count += 1;
37            }
38            None => steps.push((step.to_string(), ms, 1)),
39        }
40    }
41}
42
43/// The steps noted so far, longest total first: where a slow command spent its time.
44fn step_totals() -> serde_json::Value {
45    let mut steps = STEPS.lock().map(|steps| steps.clone()).unwrap_or_default();
46    steps.sort_by(|a, b| b.1.cmp(&a.1));
47    serde_json::Value::Array(
48        steps
49            .into_iter()
50            .take(12)
51            .map(|(step, ms, count)| serde_json::json!({ "step": step, "ms": ms as u64, "count": count }))
52            .collect(),
53    )
54}
55
56/// Run `f` as the step `step` of the running command.
57pub fn timed<T>(step: &str, f: impl FnOnce() -> T) -> T {
58    let started = Instant::now();
59    let value = f();
60    note_step(step, started.elapsed().as_millis());
61    value
62}
63
64/// The longest step noted so far.
65pub fn slowest_step() -> Option<(String, u128)> {
66    SLOWEST.lock().ok().and_then(|slowest| slowest.clone())
67}
68
69/// Where the lines go.
70pub fn path() -> PathBuf {
71    crate::agent::global_instructions_dir()
72        .join("logs")
73        .join("slow.jsonl")
74}
75
76fn secret_flag(flag: &str) -> bool {
77    let name = flag.trim_start_matches('-').to_ascii_lowercase();
78    matches!(
79        name.as_str(),
80        "token"
81            | "key"
82            | "api-key"
83            | "apikey"
84            | "secret"
85            | "password"
86            | "passwd"
87            | "credential"
88            | "credentials"
89            | "auth"
90            | "authorization"
91            | "bearer"
92            | "cookie"
93            | "session-token"
94    )
95}
96
97fn secret_name(name: &str) -> bool {
98    let name = name.to_ascii_lowercase();
99    [
100        "token",
101        "secret",
102        "password",
103        "passwd",
104        "credential",
105        "api_key",
106        "api-key",
107        "apikey",
108        "authorization",
109        "cookie",
110    ]
111    .iter()
112    .any(|word| name.contains(word))
113}
114
115fn secret_value(value: &str) -> bool {
116    let token_like = |prefix: &str, min: usize| value.starts_with(prefix) && value.len() >= min;
117    token_like("sk-", 19)
118        || token_like("ghp_", 24)
119        || token_like("gho_", 24)
120        || token_like("ghs_", 24)
121        || token_like("ghu_", 24)
122        || token_like("ghr_", 24)
123        || token_like("xoxb-", 15)
124        || token_like("xoxp-", 15)
125        || (value.starts_with("eyJ") && value.matches('.').count() == 2 && value.len() > 40)
126        || (value.len() >= 40
127            && value.bytes().all(|b| {
128                b.is_ascii_alphanumeric() || matches!(b, b'+' | b'/' | b'_' | b'-' | b'=')
129            }))
130}
131
132/// The arguments as the log keeps them: secrets replaced, each at most 200 characters.
133pub fn redact_args(args: &[String]) -> Vec<String> {
134    let mut out = Vec::with_capacity(args.len());
135    let mut hide_next = false;
136    for arg in args {
137        if hide_next {
138            out.push("[redacted]".to_string());
139            hide_next = false;
140            continue;
141        }
142        if let Some((flag, _)) = arg.split_once('=') {
143            if flag.starts_with('-') && secret_flag(flag) {
144                out.push(format!("{flag}=[redacted]"));
145                continue;
146            }
147            if !flag.starts_with('-')
148                && !flag.is_empty()
149                && flag.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_')
150                && secret_name(flag)
151            {
152                out.push(format!("{flag}=[redacted]"));
153                continue;
154            }
155        }
156        if arg.starts_with('-') && secret_flag(arg) {
157            out.push(arg.clone());
158            hide_next = true;
159            continue;
160        }
161        if secret_value(arg) {
162            out.push("[redacted]".to_string());
163            continue;
164        }
165        if arg.chars().count() > 200 {
166            out.push(format!("{}…", arg.chars().take(200).collect::<String>()));
167        } else {
168            out.push(arg.clone());
169        }
170    }
171    out
172}
173
174/// One line, when `ms` is above the bound. `caller` is asked only then (resolving a caller reads
175/// the process table). Answers whether a line was written.
176#[allow(clippy::too_many_arguments)]
177pub fn record(
178    kind: &str,
179    name: &str,
180    args: &[String],
181    ms: u128,
182    outcome: &str,
183    slowest: Option<(String, u128)>,
184    caller: impl FnOnce() -> Option<String>,
185) -> bool {
186    if ms <= SLOW_MS {
187        return false;
188    }
189    let line = serde_json::json!({
190        "v": 1,
191        "at": supercode_interchange::sidecar::ms_to_rfc3339(
192            std::time::SystemTime::now()
193                .duration_since(std::time::UNIX_EPOCH)
194                .map(|elapsed| elapsed.as_millis() as i64)
195                .unwrap_or_default(),
196        ),
197        "kind": kind,
198        "name": name,
199        "args": redact_args(args),
200        "ms": ms as u64,
201        "outcome": outcome,
202        "machine": crate::mailbox::local_machine_name(),
203        "pid": std::process::id(),
204        "caller": caller().map(|address| serde_json::json!({ "address": address })),
205        "slowest": slowest.map(|(step, ms)| serde_json::json!({ "step": step, "ms": ms as u64 })),
206        "steps": if kind == "command" { step_totals() } else { serde_json::Value::Null },
207    });
208    let path = path();
209    if let Some(dir) = path.parent() {
210        let _ = std::fs::create_dir_all(dir);
211    }
212    // Bounded: past ROTATE_BYTES the log becomes `slow.jsonl.1` (replacing the one before) and starts again.
213    if std::fs::metadata(&path).is_ok_and(|meta| meta.len() > ROTATE_BYTES) {
214        let _ = std::fs::rename(&path, path.with_extension("jsonl.1"));
215    }
216    std::fs::OpenOptions::new()
217        .create(true)
218        .append(true)
219        .open(&path)
220        .and_then(|mut file| writeln!(file, "{line}"))
221        .is_ok()
222}
supercode_harness/slow_log.rs

supercode_harness/
slow_log.rs
