Skip to main content

act_runtime/audit/
layer.rs

1//! The audit layer.
2//!
3//! Rollup requires state accumulated across events within a span, which a
4//! `FormatEvent` implementation cannot hold — so this is a full `Layer` that
5//! keeps per-span state in span extensions:
6//!
7//! * `on_new_span`  — capture the envelope fields, install an empty `Rollup`
8//! * `on_record`    — pick up `outcome` / `duration_ms` recorded at finish
9//! * `on_event`     — print exceptions now, fold allows into the parent span
10//! * `on_close`     — render and flush the rollup line
11
12use std::io::Write;
13use std::sync::Mutex;
14
15use tracing::field::{Field, Visit};
16use tracing::{Event, Subscriber, span};
17use tracing_subscriber::layer::{Context, Layer};
18use tracing_subscriber::registry::LookupSpan;
19
20use crate::audit::TARGET_AUDIT;
21use crate::audit::record::{
22    Actor, CapDecisionRecord, CeilingClassRecord, CredentialIssueRecord, Decision4, attr,
23};
24use crate::audit::render::{
25    Rollup, SpanFields, render_credential_issue, render_declared_ask_blocked_warning,
26    render_declared_ungranted_warning, render_exception, render_header, render_rollup,
27};
28
29/// Name of the tool-call envelope span, set by `emit::tool_call_span`.
30const SPAN_TOOL_CALL: &str = "act.tool_call";
31/// Name of the instantiation envelope span, set by `emit::instantiation_span`.
32const SPAN_INSTANTIATION: &str = "act.instantiation";
33
34/// Default cap on distinct rollup groups per tool call. Chosen to comfortably
35/// cover a well-behaved component; past it, new groups collapse into a count.
36pub const DEFAULT_ROLLUP_CAP: usize = 64;
37
38/// How much the operator wants to see.
39#[derive(Debug, Clone, Copy, PartialEq, Eq)]
40pub enum Detail {
41    /// Exceptions immediately; allows summarised per tool call.
42    Rollup,
43    /// Every operation, plus the summary.
44    Full,
45}
46
47/// Where rendered lines go. Abstracted so tests can capture them.
48pub trait AuditWriter: Send + Sync + 'static {
49    fn write_line(&self, line: &str);
50}
51
52/// The production sink: stderr, line-buffered, failures ignored.
53pub struct StderrWriter {
54    inner: Mutex<std::io::Stderr>,
55}
56
57impl Default for StderrWriter {
58    fn default() -> Self {
59        Self {
60            inner: Mutex::new(std::io::stderr()),
61        }
62    }
63}
64
65impl AuditWriter for StderrWriter {
66    fn write_line(&self, line: &str) {
67        // A closed or full stderr degrades to silence. Audit must never
68        // affect a decision, so nothing here can fail upward.
69        if let Ok(mut w) = self.inner.lock() {
70            let _ = writeln!(w, "{line}");
71            let _ = w.flush();
72        }
73    }
74}
75
76pub struct AuditLayer<W> {
77    writer: W,
78    detail: Detail,
79    rollup_cap: usize,
80}
81
82impl AuditLayer<StderrWriter> {
83    pub fn stderr(detail: Detail) -> Self {
84        Self::new(StderrWriter::default(), detail)
85    }
86}
87
88impl<W: AuditWriter> AuditLayer<W> {
89    pub fn new(writer: W, detail: Detail) -> Self {
90        Self {
91            writer,
92            detail,
93            rollup_cap: DEFAULT_ROLLUP_CAP,
94        }
95    }
96
97    /// Never let a rendering or writing fault escape into enforcement.
98    ///
99    /// Takes a **closure**, not a `String`, deliberately: an argument would be
100    /// evaluated before `catch_unwind` is entered, so a panic while rendering
101    /// would unwind through the layer — and rendering handles guest-chosen
102    /// values. The audit path must not be able to take the host down.
103    fn emit(&self, render: impl FnOnce() -> String) {
104        let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
105            self.writer.write_line(&render());
106        }));
107    }
108}
109
110/// Collects the envelope fields declared by `emit::tool_call_span`.
111#[derive(Default)]
112struct SpanVisitor(SpanFields);
113
114impl Visit for SpanVisitor {
115    fn record_str(&mut self, f: &Field, v: &str) {
116        match f.name() {
117            n if n == attr::COMPONENT_REF => self.0.component_ref = v.to_string(),
118            n if n == attr::COMPONENT_DIGEST => self.0.digest = v.to_string(),
119            n if n == attr::TOOL_NAME => self.0.tool = v.to_string(),
120            n if n == attr::TOOL_ARGS_SHA256 => self.0.args_sha256 = v.to_string(),
121            // Empty means --audit-args was not set for this call — same
122            // "absent means empty string on the wire" convention SESSION_ID
123            // uses below, so render_rollup's `Option` check can tell "no
124            // value recorded" apart from "recorded as an empty string".
125            n if n == attr::TOOL_ARGS && !v.is_empty() => self.0.args_json = Some(v.to_string()),
126            // AGENT_ID, TRACE_PARENT and TRACE_STATE are captured onto the
127            // span but stay unrendered by design; only REQUEST_ID reaches a
128            // line, so an operator can join it back to a client log line.
129            n if n == attr::REQUEST_ID => self.0.request_id = v.to_string(),
130            n if n == attr::TRANSPORT => self.0.transport = v.to_string(),
131            n if n == attr::OUTCOME => self.0.outcome = v.to_string(),
132            n if n == attr::SESSION_ID && !v.is_empty() => {
133                self.0.session_id = Some(v.to_string());
134            }
135            _ => {}
136        }
137    }
138
139    fn record_u64(&mut self, f: &Field, v: u64) {
140        if f.name() == attr::DURATION_MS {
141            self.0.duration_ms = v;
142        }
143    }
144
145    fn record_debug(&mut self, f: &Field, v: &dyn std::fmt::Debug) {
146        // Every field here is recorded with `%value` (Display), which
147        // tracing routes through `record_debug` with a wrapper whose `Debug`
148        // impl just forwards to `Display` — so `{v:?}` is already the plain,
149        // unquoted value. Do not strip quotes here: a guest-chosen value may
150        // legitimately start or end with one, and trimming it corrupts data.
151        let s = format!("{v:?}");
152        self.record_str(f, &s);
153    }
154}
155
156/// Collects one capability-decision event — or one ceiling-class event, from
157/// an instantiation span — back into a record. The two share a visitor
158/// because both carry `act.capability.id`; `into_record` / the `declared`
159/// field is how the layer tells them apart (see `on_event`).
160#[derive(Default)]
161struct EventVisitor {
162    cap_id: String,
163    key: String,
164    action: String,
165    decision: String,
166    mode: String,
167    actor: String,
168    reason: String,
169    rule: String,
170    declared: bool,
171    never_rollup: bool,
172    has_prompt_channel: bool,
173    /// Present on a credential-issue event and on nothing else — see
174    /// `on_event`, which branches on it before anything else.
175    ///
176    /// An `Option`, not a `String`, and the difference is load-bearing: the
177    /// kind comes straight off the stored record and nothing validates it, so
178    /// a record written with `kind: ""` is served to the guest all the same.
179    /// Branching on emptiness would drop that event through both other
180    /// branches too, and a secret would cross the sandbox boundary with no
181    /// audit line at all — the one thing this record exists to make
182    /// impossible. Presence of the field is the signal; its value is not.
183    credential_kind: Option<String>,
184    /// Carried on the credential-issue event itself rather than read off an
185    /// enclosing span, so the record identifies itself without depending on
186    /// span context.
187    component_ref: String,
188    session_id: String,
189}
190
191impl Visit for EventVisitor {
192    fn record_str(&mut self, f: &Field, v: &str) {
193        match f.name() {
194            n if n == attr::CAPABILITY_ID => self.cap_id = v.to_string(),
195            n if n == attr::RESOURCE_KEY => self.key = v.to_string(),
196            n if n == attr::RESOURCE_ACTION => self.action = v.to_string(),
197            n if n == attr::DECISION => self.decision = v.to_string(),
198            n if n == attr::POLICY_MODE => self.mode = v.to_string(),
199            n if n == attr::CREDENTIAL_KIND => self.credential_kind = Some(v.to_string()),
200            n if n == attr::COMPONENT_REF => self.component_ref = v.to_string(),
201            n if n == attr::SESSION_ID => self.session_id = v.to_string(),
202            n if n == attr::POLICY_ACTOR => self.actor = v.to_string(),
203            n if n == attr::POLICY_REASON => self.reason = v.to_string(),
204            n if n == attr::POLICY_RULE => self.rule = v.to_string(),
205            _ => {}
206        }
207    }
208
209    fn record_bool(&mut self, f: &Field, v: bool) {
210        // `act.capability.declared`, `act.consent.prompt_channel` and
211        // `act.decision.never_rollup` are the only bool fields this crate
212        // emits. Without this override, tracing's default `Visit::record_bool`
213        // routes a bool to `record_debug`, whose output ("true"/"false")
214        // doesn't match any `record_str` arm above — the field would be
215        // silently dropped and neither instantiation warning could ever fire.
216        match f.name() {
217            n if n == attr::CAPABILITY_DECLARED => self.declared = v,
218            n if n == attr::CONSENT_PROMPT_CHANNEL => self.has_prompt_channel = v,
219            n if n == attr::NEVER_ROLLUP => self.never_rollup = v,
220            _ => {}
221        }
222    }
223
224    fn record_debug(&mut self, f: &Field, v: &dyn std::fmt::Debug) {
225        // See the identical comment on `SpanVisitor::record_debug`: these
226        // fields all arrive as `%value` and are already unquoted.
227        let s = format!("{v:?}");
228        self.record_str(f, &s);
229    }
230}
231
232impl EventVisitor {
233    fn into_record(self) -> Option<CapDecisionRecord> {
234        if self.cap_id.is_empty() || self.decision.is_empty() {
235            return None;
236        }
237        let decision = match self.decision.as_str() {
238            "allow" => Decision4::Allow,
239            "deny" => Decision4::Deny,
240            "ask-allow" => Decision4::AskAllow,
241            "ask-deny" => Decision4::AskDeny,
242            _ => return None,
243        };
244        let actor = match self.actor.as_str() {
245            "user" => Actor::User,
246            "policy" => Actor::Policy,
247            _ => Actor::Static,
248        };
249        Some(CapDecisionRecord {
250            cap_id: self.cap_id,
251            key: self.key,
252            action: self.action,
253            decision,
254            mode: self.mode,
255            actor,
256            reason: (!self.reason.is_empty()).then_some(self.reason),
257            rule: (!self.rule.is_empty()).then_some(self.rule),
258            never_rollup: self.never_rollup,
259        })
260    }
261}
262
263struct SpanState {
264    fields: SpanFields,
265    rollup: Rollup,
266}
267
268/// Per-instantiation-span state: the envelope identity plus every capability
269/// class resolved for this component load, collected as `emit_ceiling_class`
270/// events arrive.
271struct InstantiationState {
272    component_ref: String,
273    digest: String,
274    classes: Vec<CeilingClassRecord>,
275}
276
277impl<S, W> Layer<S> for AuditLayer<W>
278where
279    S: Subscriber + for<'a> LookupSpan<'a>,
280    W: AuditWriter,
281{
282    fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) {
283        if attrs.metadata().target() != TARGET_AUDIT {
284            return;
285        }
286        let Some(span) = ctx.span(id) else { return };
287        let mut v = SpanVisitor::default();
288        attrs.record(&mut v);
289        // Two envelope kinds share this target: a tool call gets the rollup
290        // state it always had; an instantiation gets a plain vec of ceiling
291        // classes. Branching on the span *name* (not just target) matters —
292        // every audit-target span used to get a tool-call `SpanState`
293        // unconditionally, which would make an instantiation span render as
294        // a bogus tool call once it started reaching this layer at all.
295        match attrs.metadata().name() {
296            SPAN_TOOL_CALL => {
297                span.extensions_mut().insert(SpanState {
298                    fields: v.0,
299                    rollup: Rollup::new(self.rollup_cap),
300                });
301            }
302            SPAN_INSTANTIATION => {
303                span.extensions_mut().insert(InstantiationState {
304                    component_ref: v.0.component_ref,
305                    digest: v.0.digest,
306                    classes: Vec::new(),
307                });
308            }
309            _ => {}
310        }
311    }
312
313    fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) {
314        let Some(span) = ctx.span(id) else { return };
315        let mut ext = span.extensions_mut();
316        let Some(state) = ext.get_mut::<SpanState>() else {
317            return;
318        };
319        let mut v = SpanVisitor(std::mem::take(&mut state.fields));
320        values.record(&mut v);
321        state.fields = v.0;
322    }
323
324    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
325        if event.metadata().target() != TARGET_AUDIT {
326            return;
327        }
328        let mut v = EventVisitor::default();
329        event.record(&mut v);
330
331        // A credential-issue record (from `emit_credential_issue`) carries
332        // neither a capability id nor a decision, so both branches below
333        // would drop it. It is checked first, on the presence of the one
334        // field no other audit event emits — presence, not a non-empty
335        // value, so an unvalidated `kind` cannot make a secret cross
336        // unrecorded.
337        //
338        // Printed unconditionally, under `Detail::Rollup` too: a per-run
339        // count of "credentials issued" would not answer the only question
340        // an operator has here, which is *which* ones.
341        if let Some(kind) = v.credential_kind {
342            let record = CredentialIssueRecord {
343                component_ref: v.component_ref,
344                session_id: v.session_id,
345                key: v.key,
346                kind,
347            };
348            self.emit(|| render_credential_issue(&record));
349            return;
350        }
351
352        // A ceiling-class record (from `emit_ceiling_class`, inside an
353        // instantiation span) carries a capability id but no `act.decision`
354        // — a capability decision always carries both. That's the only
355        // signal available at this point to tell the two event shapes
356        // apart, so check it before falling through to `into_record`, which
357        // requires a decision and would otherwise just drop this event.
358        if !v.cap_id.is_empty() && v.decision.is_empty() {
359            let record = CeilingClassRecord {
360                cap_id: v.cap_id,
361                mode: v.mode,
362                declared: v.declared,
363                has_prompt_channel: v.has_prompt_channel,
364            };
365            // Walk the enclosing spans looking for the instantiation span's
366            // state; stop at the first match. A `for` loop, not
367            // `Iterator::any`, because there's no boolean result anyone
368            // reads — this is a search-and-push, not a predicate.
369            for span in ctx.event_scope(event).into_iter().flatten() {
370                if let Some(state) = span.extensions_mut().get_mut::<InstantiationState>() {
371                    state.classes.push(record);
372                    break;
373                }
374            }
375            return;
376        }
377
378        let Some(record) = v.into_record() else {
379            return;
380        };
381
382        // I2: a consent (semantic-class) decision must never fold into the
383        // rollup, even when it is an Allow — same reasoning
384        // `render_credential_issue`'s doc gives for a credential issue: there
385        // are few of these, each is a distinct consequential act, and *which
386        // subject* is the whole content of the decision. Treating
387        // `never_rollup` as an exception here, alongside a real Deny/Ask,
388        // both prints it immediately and (via the `is_exception()` guard
389        // below) keeps it out of the fold.
390        if record.decision.is_exception() || record.never_rollup || self.detail == Detail::Full {
391            self.emit(|| render_exception(&record));
392        }
393        if !record.decision.is_exception() && !record.never_rollup {
394            // Fold into the nearest enclosing tool-call span, if there is
395            // one. `SpanState` is installed only on TARGET_AUDIT spans, so a
396            // plain (non-audit) span nested between the event and the tool
397            // call would make a direct parent lookup miss it — walk the
398            // whole scope instead of just the immediate parent. A decision
399            // fired outside any call (instantiation) has nowhere to roll up,
400            // so it is printed instead of dropped.
401            let folded = ctx.event_scope(event).is_some_and(|mut scope| {
402                scope.any(|span| match span.extensions_mut().get_mut::<SpanState>() {
403                    Some(state) => {
404                        state
405                            .rollup
406                            .add(&record.cap_id, &record.action, record.rule.as_deref());
407                        true
408                    }
409                    None => false,
410                })
411            });
412            // Carries the instantiation-time guarantee: an allow with
413            // nowhere to fold (no enclosing tool-call span) would otherwise
414            // be silently dropped under Detail::Rollup. Detail::Full already
415            // printed it above, so this only fires under Detail::Rollup.
416            if !folded && self.detail != Detail::Full {
417                self.emit(|| render_exception(&record));
418            }
419        }
420    }
421
422    fn on_close(&self, id: span::Id, ctx: Context<'_, S>) {
423        let Some(span) = ctx.span(&id) else { return };
424        let mut ext = span.extensions_mut();
425        if let Some(state) = ext.remove::<SpanState>() {
426            drop(ext);
427            self.emit(|| render_rollup(&state.fields, &state.rollup));
428            return;
429        }
430        let Some(state) = ext.remove::<InstantiationState>() else {
431            return;
432        };
433        drop(ext);
434        let modes: Vec<(String, String)> = state
435            .classes
436            .iter()
437            .map(|c| (c.cap_id.clone(), c.mode.clone()))
438            .collect();
439        self.emit(|| render_header(&state.component_ref, &state.digest, &modes));
440        // Only a class the component actually declared, that still resolved
441        // to deny, is worth a warning — every undeclared class also resolves
442        // to deny, and flagging all of those would bury the one signal an
443        // operator needs: a capability the component asked for that nothing
444        // granted.
445        let ungranted: Vec<String> = state
446            .classes
447            .iter()
448            .filter(|c| c.declared && c.mode == "deny")
449            .map(|c| c.cap_id.clone())
450            .collect();
451        if !ungranted.is_empty() {
452            self.emit(|| render_declared_ungranted_warning(&ungranted));
453        }
454        // A declared class configured as `ask` is not actually reachable
455        // when this run has no prompt channel at all (headless / ACT-HTTP):
456        // every access degrades to deny before a human is ever asked. The
457        // header keeps showing `ask` — that is genuinely the configured
458        // policy — but this second, distinct warning names the outcome the
459        // operator will actually see, the same way the deny warning above
460        // does for a hard deny. A declared `ask` class backed by a real
461        // prompt channel (TTY / MCP elicitation) is not warned about here:
462        // nothing has been refused yet at instantiation time.
463        let ask_blocked: Vec<String> = state
464            .classes
465            .iter()
466            .filter(|c| c.declared && c.mode == "ask" && !c.has_prompt_channel)
467            .map(|c| c.cap_id.clone())
468            .collect();
469        if !ask_blocked.is_empty() {
470            self.emit(|| render_declared_ask_blocked_warning(&ask_blocked));
471        }
472    }
473}
474
475#[cfg(test)]
476mod tests {
477    use std::sync::{Arc, Mutex};
478    use std::time::Duration;
479
480    use tracing_subscriber::prelude::*;
481
482    use super::*;
483    use crate::audit::emit::{
484        emit_cap_decision, emit_ceiling_class, emit_credential_issue, finish_tool_call,
485        instantiation_span, tool_call_span,
486    };
487    use crate::audit::record::*;
488
489    #[derive(Clone, Default)]
490    struct TestWriter(Arc<Mutex<Vec<String>>>);
491
492    impl AuditWriter for TestWriter {
493        fn write_line(&self, line: &str) {
494            self.0.lock().unwrap().push(line.to_string());
495        }
496    }
497
498    fn start() -> ToolCallStart {
499        ToolCallStart {
500            component_ref: "python-eval@0.16.0".into(),
501            digest: "1f3a9c4e5d6b7a8c".into(),
502            tool: "run_python".into(),
503            args_sha256: "9e21c4aa".into(),
504            args_json: None,
505            session_id: None,
506            transport: Transport::Cli,
507            agent_id: None,
508            request_id: "req-1".into(),
509            traceparent: None,
510            tracestate: None,
511        }
512    }
513
514    fn allow(action: &str, rule: &str) -> CapDecisionRecord {
515        CapDecisionRecord {
516            cap_id: "wasi:filesystem".into(),
517            key: "/data/app.db".into(),
518            action: action.into(),
519            decision: Decision4::Allow,
520            mode: "allowlist".into(),
521            actor: Actor::Static,
522            reason: None,
523            rule: Some(rule.into()),
524            never_rollup: false,
525        }
526    }
527
528    fn deny() -> CapDecisionRecord {
529        CapDecisionRecord {
530            cap_id: "wasi:http".into(),
531            key: "evil.example.com:443".into(),
532            action: "GET".into(),
533            decision: Decision4::Deny,
534            mode: "ask".into(),
535            actor: Actor::Static,
536            reason: Some("outside ceiling".into()),
537            rule: None,
538            never_rollup: false,
539        }
540    }
541
542    /// A consent (semantic-class) decision — `never_rollup: true`. Used by
543    /// the I2 rollup-exemption tests below to prove the layer treats it like
544    /// a credential issue: printed immediately, on an Allow too, and never
545    /// folded into the tool call's rollup line.
546    fn consent_allow(key: &str) -> CapDecisionRecord {
547        CapDecisionRecord {
548            cap_id: "db:drop".into(),
549            key: key.into(),
550            action: "request".into(),
551            decision: Decision4::Allow,
552            mode: "open".into(),
553            actor: Actor::Static,
554            reason: None,
555            rule: None,
556            never_rollup: true,
557        }
558    }
559
560    fn run(f: impl FnOnce()) -> Vec<String> {
561        let w = TestWriter::default();
562        let sink = w.clone();
563        let sub = tracing_subscriber::registry().with(AuditLayer::new(w, Detail::Rollup));
564        tracing::subscriber::with_default(sub, f);
565        sink.0.lock().unwrap().clone()
566    }
567
568    fn issue() -> CredentialIssueRecord {
569        CredentialIssueRecord {
570            component_ref: "ghcr.io/actpkg/notion@0.1.0".into(),
571            session_id: "sess-7".into(),
572            key: "notion-work".into(),
573            kind: "std:fields".into(),
574        }
575    }
576
577    #[test]
578    fn a_credential_issue_reaches_output_with_no_enclosing_span_at_all() {
579        // A record must identify itself from its own fields. Emitting with
580        // no span at all is how that is pinned: all four facts have to come
581        // off the event, so no later call site can be added that renders an
582        // anonymous credential line.
583        let out = run(|| emit_credential_issue(&issue()));
584        assert_eq!(out.len(), 1, "expected one line, got {out:?}");
585        assert!(out[0].contains("notion-work"), "key missing: {}", out[0]);
586        assert!(out[0].contains("std:fields"), "kind missing: {}", out[0]);
587        assert!(
588            out[0].contains("ghcr.io/actpkg/notion@0.1.0"),
589            "component missing: {}",
590            out[0]
591        );
592        assert!(out[0].contains("sess-7"), "session missing: {}", out[0]);
593    }
594
595    #[test]
596    fn a_credential_with_an_empty_kind_is_still_audited() {
597        // `kind` comes straight off the stored record and nothing validates
598        // it, so `kind: ""` is served to the guest like any other. If the
599        // layer keyed on a non-empty value the event would fall through
600        // every branch and a secret would cross with no audit line at all.
601        let out = run(|| {
602            emit_credential_issue(&CredentialIssueRecord {
603                kind: String::new(),
604                ..issue()
605            });
606        });
607        assert_eq!(out.len(), 1, "expected one line, got {out:?}");
608        assert!(out[0].contains("notion-work"), "key missing: {}", out[0]);
609        assert!(
610            out[0].contains("ghcr.io/actpkg/notion@0.1.0"),
611            "component missing: {}",
612            out[0]
613        );
614    }
615
616    #[test]
617    fn a_credential_issue_prints_immediately_instead_of_folding_into_the_rollup() {
618        // Under Detail::Rollup an allow is folded into a count at span close.
619        // A credential issue must not be: "3 credentials issued" does not
620        // answer the only question an operator has, which is *which* ones.
621        let out = run(|| {
622            let span = tool_call_span(&start());
623            let _g = span.enter();
624            emit_credential_issue(&issue());
625            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(1));
626        });
627        assert_eq!(out.len(), 2, "issue line plus rollup line, got {out:?}");
628        assert!(
629            out[0].contains("notion-work"),
630            "the issue must print before the rollup, got {out:?}"
631        );
632        assert!(
633            !out[1].contains("notion-work"),
634            "and must not also be counted in it, got {}",
635            out[1]
636        );
637    }
638
639    #[test]
640    fn a_credential_issue_is_not_mistaken_for_a_ceiling_class_or_a_decision() {
641        // Both other branches key off `act.capability.id`, which this event
642        // does not carry; if the issue branch were removed or ordered after
643        // them the event would be silently dropped instead. Emitting all
644        // three in one run pins that each still lands in its own shape.
645        let out = run(|| {
646            let span = instantiation_span("comp", "deadbeef");
647            let _g = span.enter();
648            emit_ceiling_class(&CeilingClassRecord {
649                cap_id: "act:credentials".into(),
650                mode: "ask".into(),
651                declared: true,
652                has_prompt_channel: true,
653            });
654            emit_credential_issue(&issue());
655            emit_cap_decision(&deny());
656        });
657        let joined = out.join("\n");
658        assert!(
659            joined.contains("notion-work"),
660            "the issue line survived: {joined}"
661        );
662        assert!(
663            joined.contains("act:credentials=ask"),
664            "the header still reports the class: {joined}"
665        );
666        assert!(
667            joined.contains("evil.example.com:443"),
668            "the denial still rendered: {joined}"
669        );
670    }
671
672    #[test]
673    fn allows_produce_exactly_one_line_at_span_close() {
674        let out = run(|| {
675            let span = tool_call_span(&start());
676            let _g = span.enter();
677            for _ in 0..12 {
678                emit_cap_decision(&allow("read", "/data/**"));
679            }
680            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(1400));
681        });
682        assert_eq!(out.len(), 1, "expected a single rollup line, got {out:?}");
683        assert!(out[0].contains("12 read"), "got {}", out[0]);
684        assert!(out[0].contains("run_python"));
685        // Pins that on_record actually landed the values finish_tool_call
686        // recorded, not just that some line got printed.
687        assert!(out[0].contains("ok"), "outcome missing, got {}", out[0]);
688        assert!(
689            out[0].contains("1.4s"),
690            "humanised duration missing, got {}",
691            out[0]
692        );
693        // Pins that SpanVisitor actually captured these off the real span
694        // (not just that render_rollup can format them when handed a
695        // hand-built SpanFields directly, which is all render.rs's own
696        // tests exercise).
697        assert!(
698            out[0].contains("args:9e21c4"),
699            "args_sha256 missing, got {}",
700            out[0]
701        );
702        assert!(
703            out[0].contains("req:req-1"),
704            "request_id missing, got {}",
705            out[0]
706        );
707    }
708
709    #[test]
710    fn audit_args_replaces_the_digest_with_full_values_in_the_rollup() {
711        // Same fixture-capture concern as the session-id test below: this
712        // proves SpanVisitor's TOOL_ARGS arm actually reads the real field
713        // off the real span, not just that render_rollup can format an
714        // args_json field when handed one directly (render.rs's own tests
715        // already cover that in isolation).
716        let mut s = start();
717        s.args_json = Some(r#"{"path":"/tmp/secret.txt"}"#.into());
718        let out = run(|| {
719            let span = tool_call_span(&s);
720            let _g = span.enter();
721            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(5));
722        });
723        assert_eq!(out.len(), 1, "got {out:?}");
724        assert!(
725            out[0].contains(r#"args:{"path":"/tmp/secret.txt"}"#),
726            "full args missing, got {}",
727            out[0]
728        );
729        assert!(
730            !out[0].contains("args:9e21c4"),
731            "digest prefix must not also appear once full args are shown, got {}",
732            out[0]
733        );
734    }
735
736    #[test]
737    fn a_real_session_id_is_captured_from_the_span_and_rendered() {
738        // Every other layer.rs fixture uses session_id: None, so the
739        // SESSION_ID capture arm in SpanVisitor::record_str is otherwise
740        // never exercised end-to-end: a broken capture and "no session on
741        // this call" render identically (no "session:" clause) unless a
742        // real, non-empty id is driven through the real span.
743        let mut s = start();
744        s.session_id = Some("sess-abc123def456".into());
745        let out = run(|| {
746            let span = tool_call_span(&s);
747            let _g = span.enter();
748            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(5));
749        });
750        assert_eq!(out.len(), 1, "got {out:?}");
751        assert!(
752            out[0].contains("session:sess-abc"),
753            "session id missing, got {}",
754            out[0]
755        );
756    }
757
758    #[test]
759    fn an_allow_inside_a_non_audit_span_still_folds_into_the_enclosing_tool_call() {
760        // SpanState lives only on TARGET_AUDIT spans. A plain span nested
761        // between the event and the tool call must not break the fold — the
762        // host will instrument exactly this region in a later task.
763        let out = run(|| {
764            let span = tool_call_span(&start());
765            let _g = span.enter();
766            {
767                let inner = tracing::info_span!("some.other.span");
768                let _inner_g = inner.enter();
769                emit_cap_decision(&allow("read", "/data/**"));
770            }
771            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(10));
772        });
773        assert_eq!(out.len(), 1, "expected a single rollup line, got {out:?}");
774        assert!(out[0].contains("1 read"), "got {}", out[0]);
775    }
776
777    #[test]
778    fn a_consent_allow_never_folds_into_the_rollup_even_inside_a_tool_call() {
779        // I2: before this fix, `db:drop=allow` folded into the same rollup a
780        // filesystem read does, and a `DROP DATABASE analytics` authorized
781        // mid-call rendered as `db:drop: 1 request` — the one fact the line
782        // exists to carry (which database) thrown away. `never_rollup: true`
783        // must keep it out of the fold and print it the moment it resolves,
784        // the same way `render_credential_issue` never folds either.
785        let out = run(|| {
786            let span = tool_call_span(&start());
787            let _g = span.enter();
788            emit_cap_decision(&consent_allow("analytics"));
789            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(5));
790        });
791        assert_eq!(
792            out.len(),
793            2,
794            "the consent line plus the rollup line, got {out:?}"
795        );
796        assert!(
797            out[0].contains("analytics"),
798            "the consent decision must print immediately and name the key, got {out:?}"
799        );
800        assert!(
801            out[0].contains("db:drop"),
802            "and name the class, got {out:?}"
803        );
804        assert!(
805            !out[1].contains("db:drop") && !out[1].contains("analytics"),
806            "and must not also be counted in the rollup, got {}",
807            out[1]
808        );
809    }
810
811    #[test]
812    fn a_consent_allow_with_nowhere_to_fold_still_prints_once() {
813        // Mirrors `an_allow_outside_any_tool_call_still_reaches_the_operator`
814        // for the semantic-class case: with no enclosing tool-call span the
815        // ordinary fold path is unreachable regardless, but this pins that
816        // `never_rollup` does not cause a double-print or a drop here either.
817        let out = run(|| emit_cap_decision(&consent_allow("analytics")));
818        assert_eq!(out.len(), 1, "got {out:?}");
819        assert!(out[0].contains("db:drop"), "got {out:?}");
820    }
821
822    #[test]
823    fn a_denial_prints_immediately_and_before_the_rollup() {
824        let out = run(|| {
825            let span = tool_call_span(&start());
826            let _g = span.enter();
827            emit_cap_decision(&deny());
828            emit_cap_decision(&allow("read", "/data/**"));
829            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(10));
830        });
831        assert_eq!(out.len(), 2, "got {out:?}");
832        assert!(out[0].contains("deny"), "denial must come first: {out:?}");
833        assert!(
834            out[1].contains("run_python"),
835            "rollup must come last: {out:?}"
836        );
837    }
838
839    #[test]
840    fn full_detail_prints_every_operation() {
841        let w = TestWriter::default();
842        let sink = w.clone();
843        let sub = tracing_subscriber::registry().with(AuditLayer::new(w, Detail::Full));
844        tracing::subscriber::with_default(sub, || {
845            let span = tool_call_span(&start());
846            let _g = span.enter();
847            for _ in 0..3 {
848                emit_cap_decision(&allow("read", "/data/**"));
849            }
850            finish_tool_call(&span, Outcome::Ok, Duration::from_millis(5));
851        });
852        let out = sink.0.lock().unwrap().clone();
853        assert_eq!(out.len(), 4, "3 ops + 1 rollup, got {out:?}");
854        // Three individual operations, each naming the capability, then the
855        // rollup — not e.g. three rollups plus one exception.
856        for line in &out[..3] {
857            assert!(line.contains("wasi:filesystem"), "got {out:?}");
858        }
859        assert!(out[3].contains("run_python"), "got {out:?}");
860    }
861
862    #[test]
863    fn a_decision_outside_any_tool_call_still_reaches_the_operator() {
864        // Capability gates can fire during instantiation, before any tool
865        // call exists. Those records must not be swallowed.
866        let out = run(|| emit_cap_decision(&deny()));
867        assert_eq!(out.len(), 1, "got {out:?}");
868        assert!(out[0].contains("deny"));
869    }
870
871    #[test]
872    fn an_allow_outside_any_tool_call_still_reaches_the_operator() {
873        // Same scenario as the deny case above, but for an allow: with no
874        // enclosing tool-call span there is nowhere to fold it, so it must
875        // print immediately rather than being silently dropped.
876        let out = run(|| emit_cap_decision(&allow("read", "/data/**")));
877        assert_eq!(out.len(), 1, "got {out:?}");
878        assert!(out[0].contains("wasi:filesystem"), "got {out:?}");
879    }
880
881    #[test]
882    fn ask_allow_and_ask_deny_decode_correctly() {
883        // `EventVisitor::into_record` matches "ask-allow" / "ask-deny" by
884        // string; a typo in either arm would delete every ask outcome from
885        // the trail with no test failing. `answered` also attributes both to
886        // Actor::User, exercising that decode arm too.
887        let out = run(|| {
888            emit_cap_decision(&CapDecisionRecord::answered(
889                "wasi:filesystem",
890                "/data/x",
891                true,
892                true,
893            ));
894            emit_cap_decision(&CapDecisionRecord::answered(
895                "wasi:http",
896                "evil.example.com",
897                false,
898                true,
899            ));
900        });
901        assert_eq!(out.len(), 2, "got {out:?}");
902        assert!(out[0].contains("ask-allow"), "got {out:?}");
903        assert!(out[1].contains("ask-deny"), "got {out:?}");
904    }
905
906    #[test]
907    fn a_quote_bearing_resource_key_survives_rendering_intact() {
908        // `%value` fields route through `record_debug`, whose `Debug` output
909        // is already the unquoted Display form. A prior `trim_matches('"')`
910        // there stripped real leading/trailing quote characters out of
911        // guest-controlled data instead of normalising anything.
912        let out = run(|| {
913            emit_cap_decision(&CapDecisionRecord {
914                cap_id: "wasi:filesystem".into(),
915                key: "\"payload\".json".into(),
916                action: "read".into(),
917                decision: Decision4::Deny,
918                mode: "ask".into(),
919                actor: Actor::Static,
920                reason: Some("outside ceiling".into()),
921                rule: None,
922                never_rollup: false,
923            });
924        });
925        assert_eq!(out.len(), 1, "got {out:?}");
926        assert!(
927            out[0].contains("\"payload\".json"),
928            "quotes must survive intact, got {}",
929            out[0]
930        );
931    }
932
933    #[test]
934    fn a_call_that_never_finishes_renders_as_incomplete() {
935        // A span created and entered but closed without finish_tool_call
936        // ever being called (early return, or dropped) is exactly the case
937        // an auditor cares about — it must not render as if outcome "" and
938        // duration_ms 0 were a real completed call.
939        let out = run(|| {
940            let span = tool_call_span(&start());
941            let _g = span.enter();
942            emit_cap_decision(&allow("read", "/data/**"));
943            // Deliberately never call finish_tool_call.
944        });
945        assert_eq!(out.len(), 1, "got {out:?}");
946        assert!(out[0].contains("incomplete"), "got {}", out[0]);
947    }
948
949    #[test]
950    fn a_panic_while_rendering_does_not_poison_enforcement() {
951        // Rendering touches guest-chosen values, so it must run inside the
952        // same catch_unwind as the write — not be evaluated before it.
953        struct Silent;
954        impl AuditWriter for Silent {
955            fn write_line(&self, _l: &str) {}
956        }
957        let layer = AuditLayer::new(Silent, Detail::Rollup);
958        layer.emit(|| panic!("render exploded"));
959        // Reaching here without unwinding is the assertion.
960    }
961
962    #[test]
963    fn an_instantiation_span_renders_one_header_line() {
964        let out = run(|| {
965            let span = instantiation_span("python-eval@0.16.0", "1f3a9c4e");
966            let _g = span.enter();
967            emit_ceiling_class(&CeilingClassRecord {
968                cap_id: "wasi:filesystem".into(),
969                mode: "allowlist".into(),
970                declared: true,
971                has_prompt_channel: true,
972            });
973            // A declared `ask` class backed by a real prompt channel: not a
974            // warning case (see `a_declared_ask_class_with_a_prompt_channel_does_not_warn`)
975            // — `has_prompt_channel: true` here is what keeps this test at
976            // exactly one line.
977            emit_ceiling_class(&CeilingClassRecord {
978                cap_id: "wasi:http".into(),
979                mode: "ask".into(),
980                declared: true,
981                has_prompt_channel: true,
982            });
983        });
984        assert_eq!(out.len(), 1, "got {out:?}");
985        assert!(
986            out[0].contains("wasi:filesystem=allowlist"),
987            "got {}",
988            out[0]
989        );
990        assert!(out[0].contains("wasi:http=ask"));
991        assert!(out[0].contains("sha256:1f3a9c"));
992    }
993
994    #[test]
995    fn a_declared_but_denied_class_produces_a_warning_line() {
996        let out = run(|| {
997            let span = instantiation_span("c@1", "abcdef01");
998            let _g = span.enter();
999            emit_ceiling_class(&CeilingClassRecord {
1000                cap_id: "wasi:http".into(),
1001                mode: "deny".into(),
1002                declared: true,
1003                has_prompt_channel: true,
1004            });
1005        });
1006        assert_eq!(out.len(), 2, "header + warning, got {out:?}");
1007        assert!(out[1].contains("wasi:http"));
1008        assert!(out[1].contains("not granted"), "got {}", out[1]);
1009    }
1010
1011    #[test]
1012    fn an_undeclared_denied_class_produces_no_warning() {
1013        // Every class the component never asked for resolves to deny. Warning
1014        // on those would bury the one signal that matters.
1015        let out = run(|| {
1016            let span = instantiation_span("c@1", "abcdef01");
1017            let _g = span.enter();
1018            emit_ceiling_class(&CeilingClassRecord {
1019                cap_id: "wasi:sockets".into(),
1020                mode: "deny".into(),
1021                declared: false,
1022                has_prompt_channel: true,
1023            });
1024        });
1025        assert_eq!(out.len(), 1, "header only, got {out:?}");
1026    }
1027
1028    #[test]
1029    fn a_declared_ask_class_with_no_prompt_channel_produces_a_warning_line() {
1030        // Headless / ACT-HTTP: `ask` is the configured mode, but there is no
1031        // channel to ever answer one — every access degrades to deny before
1032        // a human is asked. The header must still show `ask` unchanged (that
1033        // is genuinely the configured policy); the warning is what names the
1034        // real outcome.
1035        let out = run(|| {
1036            let span = instantiation_span("c@1", "abcdef01");
1037            let _g = span.enter();
1038            emit_ceiling_class(&CeilingClassRecord {
1039                cap_id: "wasi:http".into(),
1040                mode: "ask".into(),
1041                declared: true,
1042                has_prompt_channel: false,
1043            });
1044        });
1045        assert_eq!(out.len(), 2, "header + warning, got {out:?}");
1046        assert!(out[0].contains("wasi:http=ask"), "got {}", out[0]);
1047        assert!(out[1].contains("wasi:http"), "got {}", out[1]);
1048        assert!(
1049            out[1].contains("denied"),
1050            "warning must name the reason, got {}",
1051            out[1]
1052        );
1053    }
1054
1055    #[test]
1056    fn a_declared_ask_class_with_a_prompt_channel_does_not_warn() {
1057        // A TTY or an MCP client offering elicitation means an `ask` really
1058        // can reach a human — nothing has been refused yet at instantiation
1059        // time, so this must not warn.
1060        let out = run(|| {
1061            let span = instantiation_span("c@1", "abcdef01");
1062            let _g = span.enter();
1063            emit_ceiling_class(&CeilingClassRecord {
1064                cap_id: "wasi:filesystem".into(),
1065                mode: "ask".into(),
1066                declared: true,
1067                has_prompt_channel: true,
1068            });
1069        });
1070        assert_eq!(out.len(), 1, "header only, got {out:?}");
1071    }
1072
1073    #[test]
1074    fn a_writer_that_panics_does_not_poison_enforcement() {
1075        struct Exploding;
1076        impl AuditWriter for Exploding {
1077            fn write_line(&self, _l: &str) {
1078                panic!("sink exploded");
1079            }
1080        }
1081        let sub = tracing_subscriber::registry().with(AuditLayer::new(Exploding, Detail::Rollup));
1082        tracing::subscriber::with_default(sub, || {
1083            emit_cap_decision(&deny());
1084        });
1085        // Reaching here without unwinding is the assertion.
1086    }
1087}