Skip to main content

submilli_engine/runtime/
decision.rs

1//! Decision records: what an embedder's recorder sees of each capability decision.
2//!
3//! The recorder is a [`SecurityCheck`] decorator ([`DecisionLog::install`]): it forwards
4//! every call to the check it wraps, including `audit`, so the embedder's own audit sees
5//! exactly what it would without a recorder, and taps the same `audit` calls. Recording
6//! never changes a decision, never fails a call, and never charges guest fuel.
7//!
8//! Observation work (the source-line backtrace per call) is never charged to guest fuel;
9//! see [`DecisionLogConfig::max_line_capture_frames`] for why and what bounds it. Lines stop
10//! being captured when the decision cap is reached, when the byte budget cannot fit even a
11//! bare record, after a record has been dropped whole for want of bytes, or when that frame
12//! budget is exceeded. A later, smaller record may still be kept after such a drop, without
13//! a line. Other truncation (a byte-budget payload drop, the pair cap) does not stop them.
14//!
15//! Record buffers are charged against the recorder's own byte budget, separate from the
16//! run's memory limit so that recording never changes a run's memory behavior, and a
17//! per-run decision cap; a run that reaches either is marked truncated rather than refused.
18
19use std::collections::HashMap;
20use std::sync::atomic::{AtomicU64, Ordering};
21use std::sync::{Arc, Mutex, MutexGuard};
22use std::time::Instant;
23
24use serde::{Deserialize, Serialize};
25use serde_json::Value;
26
27use super::StoreData;
28use super::call_log::{self, CallOutcome, CallRecord, ModelUsage, Payload, Side};
29use super::security::{AuditDecision, CheckOutcome, SecurityCheck};
30
31/// What the policy decided. A record of an asked call keeps `AskHuman` or `AskAdmin`,
32/// and its `allowed` says what the approver decided.
33#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
34#[serde(rename_all = "kebab-case")]
35pub enum DecisionAction {
36    Allow,
37    Deny,
38    AskHuman,
39    AskAdmin,
40}
41
42/// A rule located by caller block and zero-based position.
43#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
44pub struct RuleCitation {
45    pub caller: String,
46    pub index: usize,
47    pub name: Option<String>,
48}
49
50#[derive(Debug, Clone, PartialEq, Serialize, Deserialize)]
51#[serde(rename_all = "kebab-case", tag = "kind")]
52pub enum DecisionCause {
53    /// A rule matched.
54    Rule(RuleCitation),
55    /// No rule matched. `caller_block` is whether the caller has any rules.
56    Default { caller_block: bool },
57    /// A runtime invariant refused the call ahead of, or instead of, the policy:
58    /// an unattributable caller, `main` calling a `main_denial` capability, a read-only
59    /// volume, a quota or egress refusal, or a path the policy could not normalize.
60    RuntimeInvariant { reason: String },
61    /// The installed policy does not explain its decisions.
62    Unexplained,
63}
64
65#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
66#[serde(rename_all = "kebab-case", tag = "kind", content = "variable")]
67pub enum FailureReasonRecord {
68    FieldMissing,
69    VariableNotBound(String),
70    NotSatisfied,
71}
72
73/// One comparison that kept a rule's filter from matching.
74#[derive(Debug, Clone, PartialEq, Serialize, Deserialize)]
75pub struct FailureRecord {
76    pub comparison: String,
77    pub actual: Option<Value>,
78    pub expected: Option<String>,
79    pub reason: FailureReasonRecord,
80    pub negated: bool,
81}
82
83/// A rule that named the capability but whose filter rejected the call.
84#[derive(Debug, Clone, PartialEq, Serialize, Deserialize)]
85pub struct NearMissRecord {
86    pub rule: RuleCitation,
87    pub filter: String,
88    pub failures: Vec<FailureRecord>,
89}
90
91/// The policy's reasoning for one decision.
92#[derive(Debug, Clone, PartialEq, Serialize)]
93pub struct DecisionExplanation {
94    pub action: DecisionAction,
95    pub cause: DecisionCause,
96    pub near_misses: Vec<NearMissRecord>,
97}
98
99/// Which seam produced a decision.
100#[derive(Debug, Clone, Copy, PartialEq, Eq, Default, Serialize, Deserialize)]
101#[serde(rename_all = "kebab-case", tag = "kind")]
102pub enum EntryPath {
103    /// A gated standard-library operation.
104    #[default]
105    GatedOp,
106    /// A package's `security.check` call, attributed to its consumer.
107    PackageCheck,
108    /// A redirect hop of `parent_call_index`'s request; `index` counts its hops from 0.
109    RedirectHop {
110        parent_call_index: u64,
111        index: u32,
112    },
113    Git,
114    /// A file tool of the server, outside any program run.
115    FileTool,
116}
117
118/// A position in the submitted program.
119#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
120pub struct SourceLine {
121    pub line: u32,
122    pub column: Option<u32>,
123}
124
125/// A position inside a package: the line of the package's code that made a call the
126/// program reached through it.
127#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
128pub struct PackageLine {
129    pub package: String,
130    /// The package's module the line is in: its path under the package's source
131    /// directory, without the extension, such as `lib` for `src/lib.ts`.
132    pub module: String,
133    /// The function the line is in, when its name is known.
134    #[serde(default, skip_serializing_if = "Option::is_none")]
135    pub function: Option<String>,
136    pub line: u32,
137    #[serde(default, skip_serializing_if = "Option::is_none")]
138    pub column: Option<u32>,
139}
140
141/// Where a call came from: the program's line, and the package's line when the program
142/// reached the call through a package.
143#[derive(Debug, Clone, Default, PartialEq, Eq)]
144pub struct CallOrigin {
145    pub line: Option<SourceLine>,
146    pub package: Option<PackageLine>,
147}
148
149/// Identity of one host call, assigned when it begins.
150#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize)]
151pub struct CallTicket {
152    /// Run-wide, in call order; counts every call the recorder saw.
153    pub call_index: u64,
154    /// Counts the calls of this (caller, capability) pair in the run, denials included,
155    /// from 1. Zero when the recorder stopped tracking pairs at its cap.
156    pub seq: u64,
157    /// Microseconds since the recorder was installed, from a clock that only moves forward.
158    pub at_micros: u64,
159    pub line: Option<SourceLine>,
160}
161
162/// The call a decision belongs to and how it arrived.
163#[derive(Debug, Clone, Copy, Default)]
164pub struct CallSite {
165    pub ticket: Option<CallTicket>,
166    pub entry: EntryPath,
167}
168
169impl CallSite {
170    pub fn new(ticket: Option<CallTicket>, entry: EntryPath) -> Self {
171        Self { ticket, entry }
172    }
173}
174
175/// The runtime's side of a recorder: identity for each call. Record contents arrive through
176/// [`SecurityCheck::audit`].
177pub trait DecisionRecorder: Send + Sync {
178    /// A new host call. `origin` is where in the program, and in a package, it came
179    /// from, when known.
180    fn begin_call(&self, caller: &str, capability: &str, origin: CallOrigin) -> CallTicket;
181    /// Marks the latest call's record as a denial the host function treated as a filter.
182    fn mark_last_filtered(&self);
183    /// Whether the next call's source line would be kept. Callers check it before paying
184    /// for a backtrace; it is false once the decision cap is reached, the byte budget cannot
185    /// fit even a bare record, a record has been dropped whole for want of bytes, or the
186    /// frame budget is exceeded. Other truncation (a payload drop, the pair cap) does not
187    /// turn it off.
188    fn wants_line(&self) -> bool;
189    /// Counts the frames of a backtrace captured for a line. Past the recorder's frame
190    /// budget it marks the run truncated and stops further captures.
191    fn note_line_capture(&self, frames: usize);
192    /// A host function that can begin calls was entered. Returns the marker its
193    /// [`exit_host_call`](Self::exit_host_call) passes back.
194    fn enter_host_call(&self) -> u64;
195    /// That host function returned (`returned`) or failed. Ends every call begun since
196    /// `marker` that is still open; a nested host function has ended its own already.
197    fn exit_host_call(&self, marker: u64, returned: bool);
198    /// Whether a payload for the call `call_index` would be kept: the call is open and the
199    /// payload budget is not spent. Callers check it before building a payload. The
200    /// default asks for every payload.
201    fn wants_payload(&self, _call_index: u64) -> bool {
202        true
203    }
204    /// One side of a call that reached outside the program.
205    fn call_payload(&self, call_index: u64, side: Side, payload: Payload<'_>);
206    /// Token counts a model provider reported for a call.
207    fn call_usage(&self, call_index: u64, usage: ModelUsage);
208}
209
210/// Sees records as they are made, for an embedder that streams a run while it executes.
211///
212/// Called on the thread running the program, after the recorder has released its lock.
213/// It must not block: an implementation that cannot keep up drops what it cannot hold.
214/// What it sees is also in the [`DecisionLogOutput`] the run ends with, unless the
215/// recorder's own caps dropped it there.
216pub trait RecordObserver: Send + Sync {
217    fn call_started(&self, _call: &CallRecord) {}
218    fn decision(&self, _record: &DecisionRecord) {}
219    /// The call as it ended, without its payload contents: each side's meta is `Null`
220    /// and it has no body and no masked header names, but it keeps its size, digest,
221    /// truncation flag, timing, and usage.
222    fn call_finished(&self, _call: &CallRecord) {}
223    /// A line the program wrote to its console. Not in the [`DecisionLogOutput`]: the
224    /// run's console holds the text.
225    fn console_line(&self, _line: &ConsoleLine<'_>) {}
226}
227
228/// A console line, placed on the run's clock among its calls.
229#[derive(Debug, Clone, Copy)]
230pub struct ConsoleLine<'a> {
231    pub text: &'a str,
232    /// Microseconds since the recorder started, on the clock its calls use.
233    pub written_micros: u64,
234    /// The last call begun before the line was written; `None` before the first.
235    pub after_call: Option<u64>,
236    /// `text` is the start of a longer line.
237    pub truncated: bool,
238}
239
240#[derive(Debug, Clone, Serialize, Deserialize)]
241pub struct DecisionRecord {
242    pub call_index: u64,
243    pub seq: u64,
244    pub at_micros: u64,
245    pub caller: String,
246    pub capability: String,
247    /// Capped; see [`DecisionLogConfig::max_context_value_bytes`].
248    pub context: Value,
249    pub context_truncated: bool,
250    /// Hash of the full context, kept when the payload copy is dropped.
251    pub context_digest: u64,
252    pub allowed: bool,
253    pub action: DecisionAction,
254    pub cause: DecisionCause,
255    pub near_misses: Vec<NearMissRecord>,
256    /// The audit's source: `policy`, `invariant`, `read_only`, `quota`, `egress_guard`.
257    pub source: String,
258    pub rule: Option<usize>,
259    pub reason: Option<String>,
260    pub entry_path: EntryPath,
261    pub line: Option<SourceLine>,
262    /// A denial the host function swallowed to filter a listing.
263    pub filtered: bool,
264    /// The context and near misses were dropped to stay within the recorder's byte budget.
265    pub payload_dropped: bool,
266}
267
268#[derive(Debug, Clone)]
269pub struct DecisionLogConfig {
270    /// Decisions kept per run; later ones are counted and mark the run truncated.
271    pub max_decisions: usize,
272    /// Longest string kept in a recorded context; longer ones end in a marker.
273    pub max_context_value_bytes: usize,
274    /// Bytes the recorder may hold, independent of the run's memory limit. Past it, payloads
275    /// are dropped (verdict and digest kept), then whole records.
276    pub max_recorder_bytes: u64,
277    /// Wasm frames the recorder may walk, summed over the run's source-line captures.
278    ///
279    /// Line capture is observation work, deliberately left uncharged to guest fuel so that
280    /// recording never changes a run: a recorded run spends exactly the fuel an unrecorded
281    /// one does (R19). That deviates from AGENTS.md, "Fuel for host functions", which asks
282    /// host work to be charged; this budget bounds the work instead, together with the
283    /// decision cap. The fuel plan's "Gated functions call `check_security`" bullet
284    /// (`plans/sub-1269-host-fuel-costs.md`) is the written record of the deviation.
285    ///
286    /// The budget is checked before each capture, so it can be exceeded by at most one
287    /// stack: the capture that crosses it keeps its line. Past it no new line is captured
288    /// and the run is marked truncated (a redirect hop or git worker check may still carry
289    /// a line captured earlier).
290    pub max_line_capture_frames: u64,
291    /// Calls kept per run; later ones are counted and mark the run truncated.
292    pub max_calls: usize,
293    /// Longest body copy a call's request or response keeps. Its digest and size always
294    /// describe the full body.
295    pub max_payload_bytes: usize,
296}
297
298impl Default for DecisionLogConfig {
299    fn default() -> Self {
300        Self {
301            max_decisions: 10_000,
302            max_context_value_bytes: 1024,
303            max_recorder_bytes: 16 * 1024 * 1024,
304            max_line_capture_frames: 1_000_000,
305            max_calls: 10_000,
306            max_payload_bytes: 1024 * 1024,
307        }
308    }
309}
310
311/// What a run recorded.
312#[derive(Debug, Clone, Default)]
313pub struct DecisionLogOutput {
314    pub records: Vec<DecisionRecord>,
315    /// Some decision was not kept in full: past the cap, over the byte budget, beyond the
316    /// pairs the recorder tracks, or the line-capture frame budget was exceeded (after which
317    /// no new lines are captured).
318    pub truncated: bool,
319    /// Decisions not kept at all.
320    pub dropped: u64,
321    /// Wasm frames walked by line captures over the run (diagnostic).
322    pub line_frames: u64,
323    /// The run's calls in the order they began.
324    pub calls: Vec<CallRecord>,
325    /// Calls not kept at all, past the cap or the byte budget.
326    pub calls_dropped: u64,
327}
328
329/// Distinct (caller, capability) pairs tracked per run. Capability names come from
330/// `security.check` calls, so the set is not bounded by the catalog.
331const MAX_TRACKED_PAIRS: usize = 4096;
332const PAIR_OVERHEAD_BYTES: u64 = 96;
333const RECORD_BASE_BYTES: u64 = std::mem::size_of::<DecisionRecord>() as u64;
334const CALL_BASE_BYTES: u64 = std::mem::size_of::<CallRecord>() as u64;
335/// The share of the recorder's byte budget, as a divisor, kept for what must survive a
336/// run that moves a lot of data. One rule: payload bodies and metas stop at the reserve;
337/// the digest-only record of a payload whose copy was dropped, and decision records, may
338/// use it.
339const RECORD_RESERVE_DIVISOR: u64 = 4;
340const MAX_CONTEXT_DEPTH: usize = 8;
341const MAX_CONTEXT_ENTRIES: usize = 64;
342
343#[derive(Default)]
344struct PairState {
345    count: u64,
346    last: Option<CallTicket>,
347}
348
349#[derive(Default)]
350struct LogState {
351    records: Vec<DecisionRecord>,
352    pairs: HashMap<(String, String), PairState>,
353    next_call_index: u64,
354    last_call_index: Option<u64>,
355    truncated: bool,
356    dropped: u64,
357    charged: u64,
358    line_frames: u64,
359    /// The frame budget was exceeded: no new lines are captured.
360    lines_exhausted: bool,
361    /// A record was dropped whole for want of bytes: no new lines are captured. A smaller
362    /// later record may still be kept, without a line.
363    bytes_exhausted: bool,
364    calls: Vec<CallRecord>,
365    /// Position in `calls` of each call still running, in call order.
366    open_calls: Vec<(u64, usize)>,
367    calls_dropped: u64,
368}
369
370/// The per-run recorder.
371pub struct DecisionLog {
372    state: Mutex<LogState>,
373    config: DecisionLogConfig,
374    started: Instant,
375    clock: AtomicU64,
376    observer: Option<Arc<dyn RecordObserver>>,
377}
378
379impl DecisionLog {
380    /// Wraps the store's security check in a recording decorator. Returns the log to read
381    /// results from.
382    ///
383    /// Install it outermost: after any embedder wrapper of the check (such as the server's
384    /// audit decorator). Other wrappers do not forward [`SecurityCheck::recorder`], so a
385    /// recorder installed beneath one is invisible to the host functions that begin calls.
386    pub fn install(data: &mut StoreData, config: DecisionLogConfig) -> Arc<Self> {
387        Self::install_observed(data, config, None)
388    }
389
390    /// [`install`](Self::install), with an observer that sees each record as it is made.
391    pub fn install_observed(
392        data: &mut StoreData,
393        config: DecisionLogConfig,
394        observer: Option<Arc<dyn RecordObserver>>,
395    ) -> Arc<Self> {
396        let log = Self::new(config, observer);
397        data.security_check = log.wrap(data.security_check.clone());
398        log
399    }
400
401    /// A log not yet attached to a run; [`wrap`](Self::wrap) a check to record through it.
402    /// The clock starts now.
403    pub fn new(config: DecisionLogConfig, observer: Option<Arc<dyn RecordObserver>>) -> Arc<Self> {
404        Arc::new(Self {
405            state: Mutex::new(LogState::default()),
406            config,
407            started: Instant::now(),
408            clock: AtomicU64::new(0),
409            observer,
410        })
411    }
412
413    /// `inner`, with every decision it audits also recorded here. For a check made outside
414    /// a program run, such as a server's file tool; a run uses [`install`](Self::install).
415    pub fn wrap(self: &Arc<Self>, inner: Arc<dyn SecurityCheck>) -> Arc<dyn SecurityCheck> {
416        Arc::new(RecordingCheck {
417            inner,
418            log: self.clone(),
419        })
420    }
421
422    /// Takes the run's records and releases their byte charge. Call once, when the
423    /// run ends: the truncation flags, drop count, and call numbering describe the
424    /// whole run, so a later call would not describe only its own records.
425    pub fn finish(&self) -> DecisionLogOutput {
426        let mut state = self.lock();
427        let records = std::mem::take(&mut state.records);
428        for (_, position) in std::mem::take(&mut state.open_calls) {
429            if let Some(call) = state.calls.get_mut(position) {
430                call.outcome = Some(CallOutcome::Unfinished);
431            }
432        }
433        let output = DecisionLogOutput {
434            records,
435            truncated: state.truncated,
436            dropped: state.dropped,
437            line_frames: state.line_frames,
438            calls: std::mem::take(&mut state.calls),
439            calls_dropped: state.calls_dropped,
440        };
441        state.charged = 0;
442        state.pairs.clear();
443        output
444    }
445
446    /// Reports a console line to the observer, stamped with the run's clock and the last
447    /// call begun.
448    pub fn console_line(&self, text: &str, truncated: bool) {
449        let Some(observer) = &self.observer else {
450            return;
451        };
452        let after_call = self.lock().last_call_index;
453        observer.console_line(&ConsoleLine {
454            text,
455            written_micros: self.now_micros(),
456            after_call,
457            truncated,
458        });
459    }
460
461    fn lock(&self) -> MutexGuard<'_, LogState> {
462        // A poisoned lock means a recorder call panicked while it may have been updating
463        // this state, so the state could be partly updated. Recovering is acceptable here
464        // (unlike the accepted poisoned-lock panics in AGENTS.md) only because the log is
465        // observation-only: it never feeds a decision, so a skewed record cannot change
466        // what the run is allowed to do.
467        self.state
468            .lock()
469            .unwrap_or_else(std::sync::PoisonError::into_inner)
470    }
471
472    fn now_micros(&self) -> u64 {
473        let elapsed = u64::try_from(self.started.elapsed().as_micros()).unwrap_or(u64::MAX);
474        let previous = self.clock.fetch_max(elapsed, Ordering::Relaxed);
475        previous.max(elapsed)
476    }
477
478    fn charge(&self, state: &mut LogState, bytes: u64) -> bool {
479        self.charge_within(state, bytes, self.config.max_recorder_bytes)
480    }
481
482    /// Charges `bytes` if the total stays within `limit`.
483    fn charge_within(&self, state: &mut LogState, bytes: u64, limit: u64) -> bool {
484        let next = state.charged.saturating_add(bytes);
485        if next > limit {
486            return false;
487        }
488        state.charged = next;
489        true
490    }
491
492    /// The most the recorder's charge may reach for payload bodies and metas: the budget
493    /// less the reserve. Digest-only records and decisions may spend the reserve.
494    fn payload_limit(&self) -> u64 {
495        let max = self.config.max_recorder_bytes;
496        max.saturating_sub(max / RECORD_RESERVE_DIVISOR)
497    }
498
499    /// Whether the decision cap and the byte budget leave room for one more bare record.
500    fn can_keep_another(&self, state: &LogState) -> bool {
501        state.records.len() < self.config.max_decisions
502            && state.charged.saturating_add(RECORD_BASE_BYTES) <= self.config.max_recorder_bytes
503    }
504
505    fn begin(
506        &self,
507        state: &mut LogState,
508        caller: &str,
509        capability: &str,
510        line: Option<SourceLine>,
511    ) -> CallTicket {
512        let call_index = state.next_call_index;
513        state.next_call_index = state.next_call_index.saturating_add(1);
514        state.last_call_index = Some(call_index);
515        let key = (caller.to_owned(), capability.to_owned());
516        if !state.pairs.contains_key(&key) {
517            let cost = (caller.len() + capability.len()) as u64 + PAIR_OVERHEAD_BYTES;
518            if state.pairs.len() >= MAX_TRACKED_PAIRS || !self.charge(state, cost) {
519                state.truncated = true;
520                return CallTicket {
521                    call_index,
522                    seq: 0,
523                    at_micros: self.now_micros(),
524                    line,
525                };
526            }
527        }
528        let pair = state.pairs.entry(key).or_default();
529        pair.count = pair.count.saturating_add(1);
530        let ticket = CallTicket {
531            call_index,
532            seq: pair.count,
533            at_micros: self.now_micros(),
534            line,
535        };
536        pair.last = Some(ticket);
537        ticket
538    }
539
540    /// Stores what the audit saw. Called from the decorator's `audit`.
541    fn record(&self, decision: &AuditDecision<'_>) {
542        let mut state = self.lock();
543        let ticket = match decision.site.ticket {
544            Some(ticket) => ticket,
545            // A decision with no call is its own call, never a follow-up of another one.
546            None => self.begin(&mut state, decision.caller, decision.capability, None),
547        };
548        if state.records.len() >= self.config.max_decisions || state.records.try_reserve(1).is_err()
549        {
550            state.truncated = true;
551            state.dropped = state.dropped.saturating_add(1);
552            return;
553        }
554        let mut record = self.build(decision, ticket);
555        let minimal = RECORD_BASE_BYTES
556            + (record.caller.len()
557                + record.capability.len()
558                + record.source.len()
559                + record.reason.as_ref().map_or(0, String::len)) as u64;
560        let payload = payload_bytes(&record);
561        if !self.charge(&mut state, minimal.saturating_add(payload)) {
562            // Keep the digest and the verdict; drop what carries the bytes.
563            record.context = Value::Null;
564            record.near_misses = Vec::new();
565            record.payload_dropped = true;
566            record.context_truncated = true;
567            state.truncated = true;
568            if !self.charge(&mut state, minimal) {
569                state.bytes_exhausted = true;
570                state.dropped = state.dropped.saturating_add(1);
571                return;
572            }
573        }
574        let observed = self.observer.as_ref().map(|_| record.clone());
575        state.records.push(record);
576        drop(state);
577        if let (Some(observer), Some(record)) = (&self.observer, observed) {
578            observer.decision(&record);
579        }
580    }
581
582    /// Opens the call `ticket` begins. Over the call cap or the byte budget it is
583    /// counted and the run marked truncated.
584    fn open_call(
585        &self,
586        state: &mut LogState,
587        caller: &str,
588        capability: &str,
589        ticket: CallTicket,
590        package_line: Option<PackageLine>,
591    ) -> Option<CallRecord> {
592        let package_bytes = package_line.as_ref().map_or(0, |at| {
593            at.package.len() + at.module.len() + at.function.as_ref().map_or(0, String::len)
594        });
595        let cost = CALL_BASE_BYTES.saturating_add(
596            caller
597                .len()
598                .saturating_add(capability.len())
599                .saturating_add(package_bytes) as u64,
600        );
601        if state.calls.len() >= self.config.max_calls
602            || state.calls.try_reserve(1).is_err()
603            || state.open_calls.try_reserve(1).is_err()
604            || !self.charge(state, cost)
605        {
606            state.truncated = true;
607            state.calls_dropped = state.calls_dropped.saturating_add(1);
608            return None;
609        }
610        let call = CallRecord {
611            call_index: ticket.call_index,
612            caller: caller.to_owned(),
613            capability: capability.to_owned(),
614            started_micros: ticket.at_micros,
615            ended_micros: None,
616            outcome: None,
617            line: ticket.line,
618            package_line,
619            request: None,
620            response: None,
621            usage: None,
622        };
623        let observed = self.observer.as_ref().map(|_| call.clone());
624        state
625            .open_calls
626            .push((ticket.call_index, state.calls.len()));
627        state.calls.push(call);
628        observed
629    }
630
631    fn call_mut(state: &mut LogState, call_index: u64) -> Option<&mut CallRecord> {
632        let position = state
633            .open_calls
634            .iter()
635            .rev()
636            .find(|(index, _)| *index == call_index)
637            .map(|(_, position)| *position)?;
638        state.calls.get_mut(position)
639    }
640
641    fn build(&self, decision: &AuditDecision<'_>, ticket: CallTicket) -> DecisionRecord {
642        let digest = digest_of(decision.context);
643        let (context, mut context_truncated) = if decision.capability == "secrets.get" {
644            // The key name is the record; nothing else a secret read carries is kept.
645            let name = decision.context.get("name").cloned().unwrap_or(Value::Null);
646            cap_context(
647                &serde_json::json!({ "name": name }),
648                self.config.max_context_value_bytes,
649            )
650        } else {
651            cap_context(decision.context, self.config.max_context_value_bytes)
652        };
653        let (action, cause, near_misses) = match decision.explanation {
654            Some(explanation) => (
655                enforced_action(decision.allowed, Some(explanation.action)),
656                explanation.cause.clone(),
657                self.capped_near_misses(&explanation.near_misses, &mut context_truncated),
658            ),
659            None => (
660                enforced_action(decision.allowed, None),
661                fallback_cause(decision),
662                Vec::new(),
663            ),
664        };
665        DecisionRecord {
666            call_index: ticket.call_index,
667            seq: ticket.seq,
668            at_micros: ticket.at_micros,
669            caller: decision.caller.to_owned(),
670            capability: decision.capability.to_owned(),
671            context,
672            context_truncated,
673            context_digest: digest,
674            allowed: decision.allowed,
675            action,
676            cause,
677            near_misses,
678            source: decision.source.to_owned(),
679            rule: decision.rule,
680            reason: decision.reason.map(str::to_owned),
681            entry_path: decision.site.entry,
682            line: ticket.line,
683            filtered: false,
684            payload_dropped: false,
685        }
686    }
687
688    /// Near misses carry the call's actual values, which are as unbounded as the context.
689    fn capped_near_misses(
690        &self,
691        near_misses: &[NearMissRecord],
692        truncated: &mut bool,
693    ) -> Vec<NearMissRecord> {
694        let max = self.config.max_context_value_bytes;
695        near_misses
696            .iter()
697            .map(|miss| NearMissRecord {
698                rule: miss.rule.clone(),
699                filter: miss.filter.clone(),
700                failures: miss
701                    .failures
702                    .iter()
703                    .map(|failure| FailureRecord {
704                        actual: failure
705                            .actual
706                            .as_ref()
707                            .map(|actual| cap_value(actual, max, 0, truncated)),
708                        ..failure.clone()
709                    })
710                    .collect(),
711            })
712            .collect()
713    }
714}
715
716impl DecisionRecorder for DecisionLog {
717    fn begin_call(&self, caller: &str, capability: &str, origin: CallOrigin) -> CallTicket {
718        let mut state = self.lock();
719        let ticket = self.begin(&mut state, caller, capability, origin.line);
720        let opened = self.open_call(&mut state, caller, capability, ticket, origin.package);
721        drop(state);
722        if let (Some(observer), Some(call)) = (&self.observer, opened) {
723            observer.call_started(&call);
724        }
725        ticket
726    }
727
728    fn enter_host_call(&self) -> u64 {
729        self.lock().next_call_index
730    }
731
732    fn exit_host_call(&self, marker: u64, returned: bool) {
733        let mut state = self.lock();
734        let Some(first) = state
735            .open_calls
736            .iter()
737            .position(|(index, _)| *index >= marker)
738        else {
739            return;
740        };
741        let ended = self.now_micros();
742        let closing: Vec<_> = state.open_calls.drain(first..).collect();
743        let mut finished = Vec::new();
744        for (_, position) in closing {
745            if let Some(call) = state.calls.get_mut(position) {
746                call.ended_micros = Some(ended);
747                call.outcome = Some(if returned {
748                    CallOutcome::Returned
749                } else {
750                    CallOutcome::Failed
751                });
752                if self.observer.is_some() {
753                    // Observers report sizes and timing; the bodies stay in the log.
754                    finished.push(call.without_bodies());
755                }
756            }
757        }
758        drop(state);
759        if let Some(observer) = &self.observer {
760            for call in &finished {
761                observer.call_finished(call);
762            }
763        }
764    }
765
766    fn wants_payload(&self, call_index: u64) -> bool {
767        let mut state = self.lock();
768        // Past the payload limit a record of it, at least its digest, still fits the
769        // budget, so a payload is wanted until even that cannot be charged.
770        Self::call_mut(&mut state, call_index).is_some()
771            && state.charged.saturating_add(call_log::DIGEST_ONLY_COST)
772                <= self.config.max_recorder_bytes
773    }
774
775    fn call_payload(&self, call_index: u64, side: Side, payload: Payload<'_>) {
776        let room = {
777            let mut state = self.lock();
778            // A call that was not kept, or has ended, takes no payload: skip the hashing
779            // and the copy.
780            if Self::call_mut(&mut state, call_index).is_none() {
781                return;
782            }
783            self.payload_limit().saturating_sub(state.charged)
784        };
785        let record = call_log::capture(
786            &payload,
787            self.config.max_context_value_bytes,
788            room,
789            self.config.max_payload_bytes,
790        );
791        let mut state = self.lock();
792        // The lock was released while the payload was hashed, so the call may have ended.
793        if Self::call_mut(&mut state, call_index).is_none() {
794            return;
795        }
796        let cost = call_log::payload_cost(&record);
797        let record = if self.charge_within(&mut state, cost, self.payload_limit()) {
798            record
799        } else {
800            // Only the digest and the size enter the reserve.
801            state.truncated = true;
802            let mut kept = record.digest_only();
803            kept.truncated = true;
804            if !self.charge(&mut state, call_log::payload_cost(&kept)) {
805                return;
806            }
807            kept
808        };
809        let Some(call) = Self::call_mut(&mut state, call_index) else {
810            return;
811        };
812        match side {
813            Side::Request => call.request = Some(Box::new(record)),
814            Side::Response => call.response = Some(Box::new(record)),
815        }
816    }
817
818    fn call_usage(&self, call_index: u64, usage: ModelUsage) {
819        let mut state = self.lock();
820        if let Some(call) = Self::call_mut(&mut state, call_index) {
821            call.usage = Some(usage);
822        }
823    }
824
825    fn wants_line(&self) -> bool {
826        let state = self.lock();
827        !state.lines_exhausted && !state.bytes_exhausted && self.can_keep_another(&state)
828    }
829
830    fn note_line_capture(&self, frames: usize) {
831        let mut state = self.lock();
832        state.line_frames = state.line_frames.saturating_add(frames as u64);
833        if state.line_frames > self.config.max_line_capture_frames {
834            state.lines_exhausted = true;
835            state.truncated = true;
836        }
837    }
838
839    fn mark_last_filtered(&self) {
840        let mut state = self.lock();
841        let Some(last) = state.last_call_index else {
842            return;
843        };
844        if let Some(record) = state
845            .records
846            .iter_mut()
847            .rev()
848            .find(|record| record.call_index == last)
849        {
850            record.filtered = true;
851        }
852    }
853}
854
855/// The action the enforcement path took. The explanation only refines it into an ask,
856/// so a disagreeing explanation cannot change what is recorded as allowed.
857fn enforced_action(allowed: bool, explained: Option<DecisionAction>) -> DecisionAction {
858    match (allowed, explained) {
859        (_, Some(asked @ (DecisionAction::AskHuman | DecisionAction::AskAdmin))) => asked,
860        (true, _) => DecisionAction::Allow,
861        (false, _) => DecisionAction::Deny,
862    }
863}
864
865fn fallback_cause(decision: &AuditDecision<'_>) -> DecisionCause {
866    if matches!(decision.source, "policy" | "human" | "admin") {
867        return DecisionCause::Unexplained;
868    }
869    DecisionCause::RuntimeInvariant {
870        reason: decision.reason.unwrap_or_default().to_owned(),
871    }
872}
873
874fn digest_of(context: &Value) -> u64 {
875    use std::hash::{Hash, Hasher};
876    let Ok(text) = serde_json::to_string(context) else {
877        return 0;
878    };
879    // `DefaultHasher::new()` is keyed with fixed constants, so a digest is stable in a run.
880    let mut hasher = std::collections::hash_map::DefaultHasher::new();
881    text.hash(&mut hasher);
882    hasher.finish()
883}
884
885fn payload_bytes(record: &DecisionRecord) -> u64 {
886    let context = serde_json::to_string(&record.context).map_or(0, |text| text.len());
887    let misses = serde_json::to_string(&record.near_misses).map_or(0, |text| text.len());
888    // Parsed JSON costs several times its text; charge generously.
889    (context.saturating_add(misses) as u64).saturating_mul(2)
890}
891
892/// Caps a recorded context: long strings, deep nesting, and wide containers each end in a
893/// marker. Returns whether anything was cut.
894pub(crate) fn cap_context(context: &Value, max_string_bytes: usize) -> (Value, bool) {
895    let mut truncated = false;
896    let capped = cap_value(context, max_string_bytes, 0, &mut truncated);
897    (capped, truncated)
898}
899
900fn cap_value(value: &Value, max_string: usize, depth: usize, truncated: &mut bool) -> Value {
901    match value {
902        Value::String(text) => Value::String(cap_text(text, max_string, truncated)),
903        Value::Array(_) | Value::Object(_) if depth >= MAX_CONTEXT_DEPTH => {
904            *truncated = true;
905            Value::String("…[truncated, nested too deep]".to_owned())
906        }
907        Value::Array(items) => {
908            if items.len() > MAX_CONTEXT_ENTRIES {
909                *truncated = true;
910            }
911            Value::Array(
912                items
913                    .iter()
914                    .take(MAX_CONTEXT_ENTRIES)
915                    .map(|item| cap_value(item, max_string, depth + 1, truncated))
916                    .collect(),
917            )
918        }
919        Value::Object(fields) => {
920            if fields.len() > MAX_CONTEXT_ENTRIES {
921                *truncated = true;
922            }
923            Value::Object(
924                fields
925                    .iter()
926                    .take(MAX_CONTEXT_ENTRIES)
927                    .enumerate()
928                    .map(|(position, (key, item))| {
929                        (
930                            capped_key(key, position, max_string, truncated),
931                            cap_value(item, max_string, depth + 1, truncated),
932                        )
933                    })
934                    .collect(),
935            )
936        }
937        other => other.clone(),
938    }
939}
940
941/// A capped object key. Two long keys can share their kept prefix, so a cut key
942/// also names its position in the object to keep both entries.
943fn capped_key(key: &str, position: usize, max: usize, truncated: &mut bool) -> String {
944    let capped = cap_text(key, max, truncated);
945    if capped.len() == key.len() {
946        return capped;
947    }
948    format!("{capped} #{position}")
949}
950
951/// `text` cut to `max` bytes at a character boundary, ending in a marker when cut.
952pub(crate) fn cap_text(text: &str, max: usize, truncated: &mut bool) -> String {
953    if text.len() <= max {
954        return text.to_owned();
955    }
956    *truncated = true;
957    let mut end = max;
958    while end > 0 && !text.is_char_boundary(end) {
959        end -= 1;
960    }
961    let kept = text.get(..end).unwrap_or_default();
962    format!(
963        "{kept}…[truncated, {} of {} bytes kept]",
964        kept.len(),
965        text.len()
966    )
967}
968
969struct RecordingCheck {
970    inner: Arc<dyn SecurityCheck>,
971    log: Arc<DecisionLog>,
972}
973
974impl SecurityCheck for RecordingCheck {
975    fn audit(&self, decision: AuditDecision<'_>) {
976        self.inner.audit(decision);
977        self.log.record(&decision);
978    }
979
980    fn audit_context<'a>(
981        &self,
982        capability: &str,
983        context: &'a Value,
984        cwd: &str,
985    ) -> std::borrow::Cow<'a, Value> {
986        self.inner.audit_context(capability, context, cwd)
987    }
988
989    fn check_with_cwd(
990        &self,
991        caller: &str,
992        capability: &str,
993        context: &Value,
994        cwd: &str,
995    ) -> CheckOutcome {
996        self.inner.check_with_cwd(caller, capability, context, cwd)
997    }
998
999    fn check(&self, caller: &str, capability: &str, context: &Value) -> CheckOutcome {
1000        self.inner.check(caller, capability, context)
1001    }
1002
1003    fn recorder(&self) -> Option<&dyn DecisionRecorder> {
1004        Some(self.log.as_ref())
1005    }
1006
1007    fn explain(
1008        &self,
1009        caller: &str,
1010        capability: &str,
1011        context: &Value,
1012        cwd: &str,
1013    ) -> Option<DecisionExplanation> {
1014        self.inner.explain(caller, capability, context, cwd)
1015    }
1016}
1017
1018#[cfg(test)]
1019mod tests {
1020    use super::*;
1021    use crate::runtime::Vfs;
1022
1023    fn log_with(config: DecisionLogConfig) -> (StoreData, Arc<DecisionLog>) {
1024        let mut data = StoreData::with_vfs_and_cap("test-run".into(), Vfs::none(), 1 << 20);
1025        let log = DecisionLog::install(&mut data, config);
1026        (data, log)
1027    }
1028
1029    fn audit_denied(data: &StoreData, ticket: CallTicket) {
1030        let context = serde_json::json!({});
1031        data.security_check.audit(
1032            AuditDecision::new("main", "fs.read", &context, false, "policy", None, None)
1033                .with_site(CallSite::new(Some(ticket), EntryPath::GatedOp)),
1034        );
1035    }
1036
1037    #[test]
1038    fn a_call_still_open_at_finish_is_unfinished() {
1039        let (data, log) = log_with(DecisionLogConfig::default());
1040        let recorder = data.security_check.recorder().unwrap();
1041        recorder.enter_host_call();
1042        recorder.begin_call("main", "http.get", CallOrigin::default());
1043        let output = log.finish();
1044        let [call] = output.calls.as_slice() else {
1045            panic!("one call: {output:?}");
1046        };
1047        assert_eq!(call.outcome, Some(CallOutcome::Unfinished));
1048        assert_eq!(call.ended_micros, None);
1049    }
1050
1051    #[test]
1052    fn payload_copies_leave_the_decision_reserve_free() {
1053        let max = 64 * 1024;
1054        let (data, log) = log_with(DecisionLogConfig {
1055            max_recorder_bytes: max,
1056            ..DecisionLogConfig::default()
1057        });
1058        let recorder = data.security_check.recorder().unwrap();
1059        let body = vec![b'x'; 20 * 1024];
1060        for _ in 0..6 {
1061            let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1062            recorder.call_payload(
1063                ticket.call_index,
1064                Side::Response,
1065                Payload::meta(serde_json::Value::Null).with_body(&body),
1066            );
1067        }
1068        assert!(
1069            log.lock().charged <= max - max / RECORD_RESERVE_DIVISOR + 6 * 256,
1070            "bodies stay out of the reserve; only digests may enter it"
1071        );
1072        let output = log.finish();
1073        let responses: Vec<_> = output
1074            .calls
1075            .iter()
1076            .filter_map(|call| call.response.as_deref())
1077            .collect();
1078        assert_eq!(responses.len(), 6, "every payload keeps a record");
1079        assert!(responses.iter().any(|payload| payload.body.is_some()));
1080        let cut = responses
1081            .iter()
1082            .find(|payload| payload.body.is_none())
1083            .expect("a payload past the reserve keeps no body");
1084        assert!(cut.truncated && cut.bytes == body.len() as u64 && !cut.digest.is_empty());
1085        assert!(output.truncated);
1086    }
1087
1088    #[test]
1089    fn digest_only_records_do_not_spend_the_reserve_on_masked_names() {
1090        let max = 64 * 1024;
1091        let (data, log) = log_with(DecisionLogConfig {
1092            max_recorder_bytes: max,
1093            ..DecisionLogConfig::default()
1094        });
1095        let recorder = data.security_check.recorder().unwrap();
1096        let body = vec![b'x'; 20 * 1024];
1097        for _ in 0..6 {
1098            let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1099            recorder.call_payload(
1100                ticket.call_index,
1101                Side::Response,
1102                Payload::meta(serde_json::Value::Null).with_body(&body),
1103            );
1104        }
1105        let before = log.lock().charged;
1106        let names: Vec<String> = (0..64)
1107            .map(|i| format!("x-token-{i}-{}", "n".repeat(900)))
1108            .collect();
1109        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1110        recorder.call_payload(
1111            ticket.call_index,
1112            Side::Response,
1113            Payload::meta(serde_json::Value::Null)
1114                .with_body(&body)
1115                .with_masked(names),
1116        );
1117        let spent = log.lock().charged - before;
1118        assert!(
1119            spent < 512,
1120            "a payload past the limit enters the reserve as a digest and a size: {spent}"
1121        );
1122        audit_denied(
1123            &data,
1124            recorder.begin_call("main", "fs.read", CallOrigin::default()),
1125        );
1126        let output = log.finish();
1127        assert_eq!(output.records.len(), 1, "a later denial is still recorded");
1128        let last = output
1129            .calls
1130            .iter()
1131            .rev()
1132            .find_map(|call| call.response.as_deref());
1133        assert!(last.is_some_and(|payload| payload.masked_headers.is_empty()));
1134    }
1135
1136    #[test]
1137    fn a_body_is_sized_to_the_room_its_record_leaves() {
1138        let max = 16 * 1024;
1139        let (data, log) = log_with(DecisionLogConfig {
1140            max_recorder_bytes: max,
1141            ..DecisionLogConfig::default()
1142        });
1143        let recorder = data.security_check.recorder().unwrap();
1144        let body = vec![b'x'; 64 * 1024];
1145        let meta = serde_json::json!({ "url": "https://x.test/" });
1146        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1147        recorder.call_payload(
1148            ticket.call_index,
1149            Side::Response,
1150            Payload::meta(meta.clone()).with_body(&body),
1151        );
1152        let charged = log.lock().charged;
1153        assert!(
1154            charged <= log.payload_limit(),
1155            "the copy fits what it is charged"
1156        );
1157        let output = log.finish();
1158        let payload = output.calls[0]
1159            .response
1160            .as_deref()
1161            .expect("a response record");
1162        let kept = match &payload.body {
1163            Some(call_log::BodyCopy::Text(text)) => text.len(),
1164            other => panic!("a cut text body is kept as text: {other:?}"),
1165        };
1166        assert!(payload.truncated && kept > 0 && kept < body.len());
1167        assert_eq!(payload.bytes, body.len() as u64);
1168        // Binary bodies are charged as base64: a quarter more.
1169        let (data, log) = log_with(DecisionLogConfig {
1170            max_recorder_bytes: max,
1171            ..DecisionLogConfig::default()
1172        });
1173        let recorder = data.security_check.recorder().unwrap();
1174        let binary = vec![0xffu8; 64 * 1024];
1175        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1176        recorder.call_payload(
1177            ticket.call_index,
1178            Side::Response,
1179            Payload::meta(meta).with_body(&binary),
1180        );
1181        let output = log.finish();
1182        let payload = output.calls[0]
1183            .response
1184            .as_deref()
1185            .expect("a response record");
1186        let Some(call_log::BodyCopy::Base64(text)) = &payload.body else {
1187            panic!("a binary body is kept as base64: {payload:?}");
1188        };
1189        assert!(payload.truncated);
1190        assert!(text.len() as u64 <= max - max / RECORD_RESERVE_DIVISOR);
1191    }
1192
1193    #[test]
1194    fn a_payload_is_wanted_exactly_while_its_digest_only_record_fits() {
1195        let max = 4096;
1196        let (data, log) = log_with(DecisionLogConfig {
1197            max_recorder_bytes: max,
1198            ..DecisionLogConfig::default()
1199        });
1200        let recorder = data.security_check.recorder().unwrap();
1201        recorder.enter_host_call();
1202        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1203        log.lock().charged = max - call_log::DIGEST_ONLY_COST;
1204        assert!(recorder.wants_payload(ticket.call_index));
1205        log.lock().charged = max - call_log::DIGEST_ONLY_COST + 1;
1206        assert!(!recorder.wants_payload(ticket.call_index));
1207    }
1208
1209    #[test]
1210    fn a_body_with_no_room_is_not_copied() {
1211        let (data, log) = log_with(DecisionLogConfig {
1212            max_recorder_bytes: 1024,
1213            ..DecisionLogConfig::default()
1214        });
1215        let recorder = data.security_check.recorder().unwrap();
1216        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1217        let meta = serde_json::json!({ "url": "u".repeat(400) });
1218        recorder.call_payload(
1219            ticket.call_index,
1220            Side::Response,
1221            Payload::meta(meta).with_body(&[b'x'; 4096]),
1222        );
1223        let output = log.finish();
1224        let payload = output.calls[0]
1225            .response
1226            .as_deref()
1227            .expect("a response record");
1228        assert!(payload.body.is_none() && payload.truncated);
1229        assert_eq!(payload.bytes, 4096);
1230    }
1231
1232    #[test]
1233    fn a_payload_is_wanted_while_its_call_is_open_and_the_budget_lasts() {
1234        let (data, _log) = log_with(DecisionLogConfig {
1235            max_recorder_bytes: 4096,
1236            ..DecisionLogConfig::default()
1237        });
1238        let recorder = data.security_check.recorder().unwrap();
1239        recorder.enter_host_call();
1240        let ticket = recorder.begin_call("main", "http.get", CallOrigin::default());
1241        assert!(recorder.wants_payload(ticket.call_index));
1242        assert!(
1243            !recorder.wants_payload(ticket.call_index + 1),
1244            "no such call"
1245        );
1246        recorder.exit_host_call(0, true);
1247        assert!(!recorder.wants_payload(ticket.call_index), "the call ended");
1248    }
1249
1250    #[test]
1251    fn a_full_log_stops_asking_for_lines() {
1252        let (data, log) = log_with(DecisionLogConfig {
1253            max_decisions: 2,
1254            ..DecisionLogConfig::default()
1255        });
1256        let recorder = data.security_check.recorder().unwrap();
1257        for _ in 0..2 {
1258            assert!(recorder.wants_line());
1259            audit_denied(
1260                &data,
1261                recorder.begin_call("main", "fs.read", CallOrigin::default()),
1262            );
1263        }
1264        assert!(!recorder.wants_line(), "the cap is reached");
1265        audit_denied(
1266            &data,
1267            recorder.begin_call("main", "fs.read", CallOrigin::default()),
1268        );
1269        assert!(!recorder.wants_line(), "still off once the log is full");
1270        assert!(log.finish().truncated);
1271    }
1272
1273    #[test]
1274    fn a_byte_budget_payload_drop_keeps_asking_for_lines() {
1275        let (data, log) = log_with(DecisionLogConfig {
1276            max_recorder_bytes: 4 * RECORD_BASE_BYTES,
1277            ..DecisionLogConfig::default()
1278        });
1279        let recorder = data.security_check.recorder().unwrap();
1280        let context = serde_json::json!({ "path": "p".repeat(900) });
1281        let ticket = recorder.begin_call("main", "fs.read", CallOrigin::default());
1282        data.security_check.audit(
1283            AuditDecision::new("main", "fs.read", &context, true, "policy", None, None)
1284                .with_site(CallSite::new(Some(ticket), EntryPath::GatedOp)),
1285        );
1286        assert!(recorder.wants_line(), "a minimal record still fits");
1287        let output = log.finish();
1288        assert!(output.truncated);
1289        assert!(output.records.iter().any(|r| r.payload_dropped));
1290    }
1291
1292    #[test]
1293    fn filling_the_pair_cap_keeps_asking_for_lines() {
1294        let (data, log) = log_with(DecisionLogConfig::default());
1295        let recorder = data.security_check.recorder().unwrap();
1296        for index in 0..=MAX_TRACKED_PAIRS {
1297            recorder.begin_call("main", &format!("cap.{index}"), CallOrigin::default());
1298        }
1299        assert!(recorder.wants_line());
1300        assert!(log.finish().truncated, "the pair cap truncates");
1301    }
1302
1303    #[test]
1304    fn lines_stop_once_the_byte_budget_cannot_fit_a_record() {
1305        let (data, log) = log_with(DecisionLogConfig {
1306            max_recorder_bytes: 3 * RECORD_BASE_BYTES,
1307            ..DecisionLogConfig::default()
1308        });
1309        let recorder = data.security_check.recorder().unwrap();
1310        let mut captures = 0;
1311        for _ in 0..20 {
1312            if recorder.wants_line() {
1313                captures += 1;
1314                recorder.note_line_capture(5);
1315            }
1316            audit_denied(
1317                &data,
1318                recorder.begin_call("main", "fs.read", CallOrigin::default()),
1319            );
1320        }
1321        let output = log.finish();
1322        assert!(output.dropped > 0, "records were dropped whole");
1323        assert!(
1324            captures < 20 && output.line_frames == 5 * captures,
1325            "capture stopped: {captures} captures"
1326        );
1327        assert!(
1328            captures <= output.records.len() as u64 + 1,
1329            "no captures beyond the first dropped record: {captures} for {} kept",
1330            output.records.len()
1331        );
1332    }
1333
1334    #[test]
1335    fn a_budget_below_one_bare_record_wants_no_line() {
1336        for max_recorder_bytes in [0, RECORD_BASE_BYTES - 1] {
1337            let (data, _log) = log_with(DecisionLogConfig {
1338                max_recorder_bytes,
1339                ..DecisionLogConfig::default()
1340            });
1341            let recorder = data.security_check.recorder().unwrap();
1342            assert!(!recorder.wants_line(), "budget {max_recorder_bytes}");
1343        }
1344    }
1345
1346    #[test]
1347    fn a_whole_record_drop_stops_lines_though_a_bare_record_would_fit() {
1348        let (data, log) = log_with(DecisionLogConfig {
1349            // After the call's pair is charged, the leftover is a bare record plus 2 bytes:
1350            // less than this record's strings need. No call records take a share.
1351            max_recorder_bytes: PAIR_OVERHEAD_BYTES
1352                + "main".len() as u64
1353                + "fs.read".len() as u64
1354                + RECORD_BASE_BYTES
1355                + 2,
1356            max_calls: 0,
1357            ..DecisionLogConfig::default()
1358        });
1359        let recorder = data.security_check.recorder().unwrap();
1360        assert!(recorder.wants_line(), "a bare record fits before any call");
1361        let ticket = recorder.begin_call("main", "fs.read", CallOrigin::default());
1362        assert!(
1363            recorder.wants_line(),
1364            "a bare record still fits after the call"
1365        );
1366        audit_denied(&data, ticket);
1367        assert!(!recorder.wants_line(), "the drop turns lines off");
1368        let output = log.finish();
1369        assert_eq!(output.dropped, 1);
1370        assert!(output.records.is_empty());
1371    }
1372
1373    #[test]
1374    fn the_line_capture_frame_budget_truncates_the_log_once_exceeded() {
1375        let (data, log) = log_with(DecisionLogConfig {
1376            max_line_capture_frames: 10,
1377            ..DecisionLogConfig::default()
1378        });
1379        let recorder = data.security_check.recorder().unwrap();
1380        recorder.note_line_capture(10);
1381        assert!(recorder.wants_line(), "at the budget is still within it");
1382        recorder.note_line_capture(1);
1383        assert!(!recorder.wants_line());
1384        assert!(log.finish().truncated);
1385    }
1386
1387    #[test]
1388    fn a_secret_read_keeps_the_key_name_and_nothing_else() {
1389        let (data, log) = log_with(DecisionLogConfig::default());
1390        let context = serde_json::json!({ "name": "api-key", "value": "s3cret" });
1391        data.security_check.audit(AuditDecision::new(
1392            "main",
1393            "secrets.get",
1394            &context,
1395            false,
1396            "invariant",
1397            None,
1398            Some("refused"),
1399        ));
1400        let output = log.finish();
1401        let [record] = output.records.as_slice() else {
1402            panic!("one record");
1403        };
1404        assert_eq!(record.context, serde_json::json!({ "name": "api-key" }));
1405        assert!(!format!("{record:?}").contains("s3cret"));
1406    }
1407
1408    #[test]
1409    fn an_exhausted_recorder_budget_keeps_the_verdict_and_drops_the_payload() {
1410        // Room for the pair bookkeeping and a bare record, not for a big context.
1411        let (data, log) = log_with(DecisionLogConfig {
1412            max_recorder_bytes: 2048,
1413            ..DecisionLogConfig::default()
1414        });
1415        let context = serde_json::json!({ "path": "p".repeat(900) });
1416        let recorder = data.security_check.recorder().unwrap();
1417        let ticket = recorder.begin_call("main", "fs.read", CallOrigin::default());
1418        data.security_check.audit(
1419            AuditDecision::new("main", "fs.read", &context, true, "policy", None, None)
1420                .with_site(CallSite::new(Some(ticket), EntryPath::GatedOp)),
1421        );
1422        let output = log.finish();
1423        assert!(output.truncated);
1424        let [record] = output.records.as_slice() else {
1425            panic!("the verdict is kept: {output:?}");
1426        };
1427        assert!(record.allowed && record.payload_dropped);
1428        assert_eq!(record.context, serde_json::Value::Null);
1429        assert_ne!(record.context_digest, 0, "the digest survives");
1430        assert_eq!(
1431            data.tenant_limits.host_attached_bytes(),
1432            0,
1433            "the run's memory budget is not touched"
1434        );
1435    }
1436
1437    #[test]
1438    fn caps_mark_long_strings_deep_nesting_and_wide_containers() {
1439        let long = serde_json::json!({ "a": "é".repeat(100) });
1440        let (capped, truncated) = cap_context(&long, 11);
1441        assert!(truncated);
1442        let text = capped["a"].as_str().unwrap();
1443        assert!(
1444            text.starts_with("éééé") && text.contains("truncated"),
1445            "{text}"
1446        );
1447
1448        let mut nested = serde_json::json!(1);
1449        for _ in 0..20 {
1450            nested = serde_json::json!([nested]);
1451        }
1452        assert!(cap_context(&nested, 100).1);
1453
1454        let wide = Value::Array((0..200).map(Value::from).collect());
1455        let (capped, truncated) = cap_context(&wide, 100);
1456        assert!(truncated);
1457        assert_eq!(capped.as_array().unwrap().len(), MAX_CONTEXT_ENTRIES);
1458
1459        let small = serde_json::json!({ "host": "x", "n": [1, 2] });
1460        assert_eq!(cap_context(&small, 100), (small.clone(), false));
1461    }
1462
1463    #[test]
1464    fn finish_refunds_the_recorders_budget() {
1465        let (data, log) = log_with(DecisionLogConfig {
1466            max_recorder_bytes: 4096,
1467            ..DecisionLogConfig::default()
1468        });
1469        let context = serde_json::json!({ "path": "p".repeat(300) });
1470        for _ in 0..2 {
1471            data.security_check.audit(AuditDecision::new(
1472                "main", "fs.read", &context, true, "policy", None, None,
1473            ));
1474            let output = log.finish();
1475            assert!(!output.truncated && output.records.len() == 1, "{output:?}");
1476        }
1477        assert_eq!(data.tenant_limits.host_attached_bytes(), 0);
1478    }
1479
1480    #[test]
1481    fn long_keys_sharing_a_prefix_both_survive_capping() {
1482        let long = "k".repeat(100);
1483        let value = serde_json::json!({ format!("{long}a"): 1, format!("{long}b"): 2 });
1484        let mut truncated = false;
1485        let Value::Object(capped) = cap_value(&value, 16, 0, &mut truncated) else {
1486            panic!("expected an object");
1487        };
1488        assert!(truncated);
1489        assert_eq!(capped.len(), 2, "{capped:?}");
1490        let mut values: Vec<_> = capped.values().cloned().collect();
1491        values.sort_by_key(Value::as_i64);
1492        assert_eq!(values, vec![serde_json::json!(1), serde_json::json!(2)]);
1493    }
1494
1495    #[test]
1496    fn near_miss_actual_values_and_keys_are_capped_like_the_context() {
1497        let (data, log) = log_with(DecisionLogConfig {
1498            max_context_value_bytes: 16,
1499            ..DecisionLogConfig::default()
1500        });
1501        let explanation = DecisionExplanation {
1502            action: DecisionAction::Deny,
1503            cause: DecisionCause::Default { caller_block: true },
1504            near_misses: vec![NearMissRecord {
1505                rule: RuleCitation {
1506                    caller: "main".into(),
1507                    index: 0,
1508                    name: None,
1509                },
1510                filter: "f".into(),
1511                failures: vec![FailureRecord {
1512                    comparison: "c".into(),
1513                    actual: Some(serde_json::json!({ "k".repeat(100): "v".repeat(100) })),
1514                    expected: None,
1515                    reason: FailureReasonRecord::NotSatisfied,
1516                    negated: false,
1517                }],
1518            }],
1519        };
1520        let context = serde_json::json!({});
1521        data.security_check.audit(
1522            AuditDecision::new("main", "fs.read", &context, false, "policy", None, None)
1523                .with_explanation(Some(&explanation)),
1524        );
1525        let output = log.finish();
1526        let [record] = output.records.as_slice() else {
1527            panic!("one record");
1528        };
1529        assert!(record.context_truncated);
1530        let actual = record.near_misses[0].failures[0].actual.as_ref().unwrap();
1531        assert!(
1532            serde_json::to_string(actual).unwrap().len() < 150,
1533            "{actual}"
1534        );
1535    }
1536}