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
22/// A step of the running command took `ms`; the longest is the command's `slowest`.
23pub fn note_step(step: &str, ms: u128) {
24    if let Ok(mut slowest) = SLOWEST.lock() {
25        if slowest.as_ref().is_none_or(|(_, longest)| ms > *longest) {
26            *slowest = Some((step.to_string(), ms));
27        }
28    }
29}
30
31/// Run `f` as the step `step` of the running command.
32pub fn timed<T>(step: &str, f: impl FnOnce() -> T) -> T {
33    let started = Instant::now();
34    let value = f();
35    note_step(step, started.elapsed().as_millis());
36    value
37}
38
39/// The longest step noted so far.
40pub fn slowest_step() -> Option<(String, u128)> {
41    SLOWEST.lock().ok().and_then(|slowest| slowest.clone())
42}
43
44/// Where the lines go.
45pub fn path() -> PathBuf {
46    crate::agent::global_instructions_dir()
47        .join("logs")
48        .join("slow.jsonl")
49}
50
51fn secret_flag(flag: &str) -> bool {
52    let name = flag.trim_start_matches('-').to_ascii_lowercase();
53    matches!(
54        name.as_str(),
55        "token"
56            | "key"
57            | "api-key"
58            | "apikey"
59            | "secret"
60            | "password"
61            | "passwd"
62            | "credential"
63            | "credentials"
64            | "auth"
65            | "authorization"
66            | "bearer"
67            | "cookie"
68            | "session-token"
69    )
70}
71
72fn secret_name(name: &str) -> bool {
73    let name = name.to_ascii_lowercase();
74    [
75        "token",
76        "secret",
77        "password",
78        "passwd",
79        "credential",
80        "api_key",
81        "api-key",
82        "apikey",
83        "authorization",
84        "cookie",
85    ]
86    .iter()
87    .any(|word| name.contains(word))
88}
89
90fn secret_value(value: &str) -> bool {
91    let token_like = |prefix: &str, min: usize| value.starts_with(prefix) && value.len() >= min;
92    token_like("sk-", 19)
93        || token_like("ghp_", 24)
94        || token_like("gho_", 24)
95        || token_like("ghs_", 24)
96        || token_like("ghu_", 24)
97        || token_like("ghr_", 24)
98        || token_like("xoxb-", 15)
99        || token_like("xoxp-", 15)
100        || (value.starts_with("eyJ") && value.matches('.').count() == 2 && value.len() > 40)
101        || (value.len() >= 40
102            && value.bytes().all(|b| {
103                b.is_ascii_alphanumeric() || matches!(b, b'+' | b'/' | b'_' | b'-' | b'=')
104            }))
105}
106
107/// The arguments as the log keeps them: secrets replaced, each at most 200 characters.
108pub fn redact_args(args: &[String]) -> Vec<String> {
109    let mut out = Vec::with_capacity(args.len());
110    let mut hide_next = false;
111    for arg in args {
112        if hide_next {
113            out.push("[redacted]".to_string());
114            hide_next = false;
115            continue;
116        }
117        if let Some((flag, _)) = arg.split_once('=') {
118            if flag.starts_with('-') && secret_flag(flag) {
119                out.push(format!("{flag}=[redacted]"));
120                continue;
121            }
122            if !flag.starts_with('-')
123                && !flag.is_empty()
124                && flag.bytes().all(|b| b.is_ascii_alphanumeric() || b == b'_')
125                && secret_name(flag)
126            {
127                out.push(format!("{flag}=[redacted]"));
128                continue;
129            }
130        }
131        if arg.starts_with('-') && secret_flag(arg) {
132            out.push(arg.clone());
133            hide_next = true;
134            continue;
135        }
136        if secret_value(arg) {
137            out.push("[redacted]".to_string());
138            continue;
139        }
140        if arg.chars().count() > 200 {
141            out.push(format!("{}…", arg.chars().take(200).collect::<String>()));
142        } else {
143            out.push(arg.clone());
144        }
145    }
146    out
147}
148
149/// One line, when `ms` is above the bound. `caller` is asked only then (resolving a caller reads
150/// the process table). Answers whether a line was written.
151#[allow(clippy::too_many_arguments)]
152pub fn record(
153    kind: &str,
154    name: &str,
155    args: &[String],
156    ms: u128,
157    outcome: &str,
158    slowest: Option<(String, u128)>,
159    caller: impl FnOnce() -> Option<String>,
160) -> bool {
161    if ms <= SLOW_MS {
162        return false;
163    }
164    let line = serde_json::json!({
165        "v": 1,
166        "at": supercode_interchange::sidecar::ms_to_rfc3339(
167            std::time::SystemTime::now()
168                .duration_since(std::time::UNIX_EPOCH)
169                .map(|elapsed| elapsed.as_millis() as i64)
170                .unwrap_or_default(),
171        ),
172        "kind": kind,
173        "name": name,
174        "args": redact_args(args),
175        "ms": ms as u64,
176        "outcome": outcome,
177        "machine": crate::mailbox::local_machine_name(),
178        "pid": std::process::id(),
179        "caller": caller().map(|address| serde_json::json!({ "address": address })),
180        "slowest": slowest.map(|(step, ms)| serde_json::json!({ "step": step, "ms": ms as u64 })),
181    });
182    let path = path();
183    if let Some(dir) = path.parent() {
184        let _ = std::fs::create_dir_all(dir);
185    }
186    // Bounded: past ROTATE_BYTES the log becomes `slow.jsonl.1` (replacing the one before) and starts again.
187    if std::fs::metadata(&path).is_ok_and(|meta| meta.len() > ROTATE_BYTES) {
188        let _ = std::fs::rename(&path, path.with_extension("jsonl.1"));
189    }
190    std::fs::OpenOptions::new()
191        .create(true)
192        .append(true)
193        .open(&path)
194        .and_then(|mut file| writeln!(file, "{line}"))
195        .is_ok()
196}
supercode_harness/slow_log.rs

supercode_harness/
slow_log.rs
