featherbit/debug/
mod.rs

1//! Debug mode: per-request policy-execution tracing and the plugin sandbox.
2//!
3//! Policy development is otherwise blind — you can see the final response and
4//! aggregate metrics, but not the [`Context`](crate::context::Context) as it
5//! moves from node to node. This module records that walk.
6//!
7//! - [`trace`] — the [`Trace`]/[`NodeStep`] records and redacted snapshots.
8//! - [`diff`] — derives "what this plugin changed" from two snapshots.
9//! - [`store`] — resolved settings plus the bounded ring buffer.
10//! - [`sandbox`] — runs plugins or a named policy against a synthetic context.
11//!
12//! Tracing is opt-in per request (a trigger header) and entirely off unless
13//! `debug.enabled` is set in `system.yaml`. When it is off the only cost on the
14//! request path is one `Option` check per node in the engine loop.
15
16pub mod diff;
17pub mod sandbox;
18pub mod store;
19pub mod trace;
20
21use std::time::{Duration, SystemTime, UNIX_EPOCH};
22
23use crate::context::Context;
24
25// featherbit is a binary crate, so `pub` exports nothing externally; re-exports
26// consumed only by later increments read as unused in an intermediate build.
27#[allow(unused_imports)]
28pub use store::{DebugState, TraceSummary};
29pub use trace::{
30    CaptureOptions, ContextSnapshot, EdgeKind, NodeStep, PreviousBodies, StepOutcome, Trace,
31    TraceSource,
32};
33
34/// Accumulates steps while the engine walks a graph.
35///
36/// Created per traced execution and handed to
37/// [`CompiledGraph::execute_traced`](crate::graph::CompiledGraph::execute_traced);
38/// the engine calls [`record_step`](TraceRecorder::record_step) after each node
39/// and the caller then [`finish`](TraceRecorder::finish)es it into a [`Trace`].
40pub struct TraceRecorder {
41    opts: CaptureOptions,
42    max_steps: usize,
43    /// Bodies from the previous step, so an unchanged body is not stored once
44    /// per node. Cloning `Bytes` is a refcount bump, not a copy.
45    prev_bodies: PreviousBodies,
46    initial: Option<ContextSnapshot>,
47    steps: Vec<NodeStep>,
48    notes: Vec<String>,
49    truncated: bool,
50}
51
52impl TraceRecorder {
53    /// Starts a recording, capturing the context as it enters the graph.
54    pub fn new(ctx: &Context, opts: CaptureOptions, max_steps: usize) -> Self {
55        let initial = ContextSnapshot::capture(ctx, &opts, &PreviousBodies::default());
56        Self {
57            opts,
58            max_steps,
59            prev_bodies: PreviousBodies {
60                request: Some(ctx.request.body.clone()),
61                response: Some(ctx.response.body.clone()),
62            },
63            initial: Some(initial),
64            steps: Vec::new(),
65            notes: Vec::new(),
66            truncated: false,
67        }
68    }
69
70    /// Records one node execution. Called by the engine immediately after the
71    /// plugin returns, while the context is still in hand.
72    // Each parameter is a distinct fact the engine already has in hand;
73    // bundling them into a struct would only move the noise to the call site.
74    #[allow(clippy::too_many_arguments)]
75    pub fn record_step(
76        &mut self,
77        node_id: &str,
78        node_type: &str,
79        outcome: StepOutcome,
80        duration: Duration,
81        edge: EdgeKind,
82        next_node_id: Option<&str>,
83        ctx: &Context,
84    ) {
85        if self.steps.len() >= self.max_steps {
86            if !self.truncated {
87                self.truncated = true;
88                self.notes.push(format!(
89                    "step limit of {} reached; later nodes are not recorded",
90                    self.max_steps
91                ));
92            }
93            return;
94        }
95
96        let after = ContextSnapshot::capture(ctx, &self.opts, &self.prev_bodies);
97        self.prev_bodies = PreviousBodies {
98            request: Some(ctx.request.body.clone()),
99            response: Some(ctx.response.body.clone()),
100        };
101        if after.request.body.truncated || after.response.body.truncated {
102            let note = "a captured body was truncated".to_string();
103            if !self.notes.contains(&note) {
104                self.notes.push(note);
105            }
106        }
107
108        self.steps.push(NodeStep {
109            index: self.steps.len(),
110            node_id: node_id.to_string(),
111            node_type: node_type.to_string(),
112            outcome,
113            duration_us: duration.as_micros() as u64,
114            edge,
115            next_node_id: next_node_id.map(str::to_string),
116            after,
117        });
118    }
119
120    /// Seals the recording into a [`Trace`].
121    #[allow(clippy::too_many_arguments)]
122    pub fn finish(
123        mut self,
124        id: String,
125        seq: u64,
126        source: TraceSource,
127        route: Option<String>,
128        policy: String,
129        final_ctx: &Context,
130        duration: Duration,
131    ) -> Trace {
132        Trace {
133            id,
134            seq,
135            source,
136            started_ms: now_ms(),
137            route,
138            policy,
139            method: final_ctx.request.method.clone(),
140            path: final_ctx.request.path.clone(),
141            status: final_ctx.response.status_code,
142            duration_us: duration.as_micros() as u64,
143            captured_bodies: self.opts.capture_bodies,
144            initial: self.initial.take().expect("initial snapshot taken once"),
145            steps: std::mem::take(&mut self.steps),
146            notes: std::mem::take(&mut self.notes),
147        }
148    }
149}
150
151/// Unix milliseconds, saturating to 0 if the clock is before the epoch.
152pub fn now_ms() -> u64 {
153    SystemTime::now()
154        .duration_since(UNIX_EPOCH)
155        .map(|d| d.as_millis() as u64)
156        .unwrap_or(0)
157}
158
159/// A short, unique trace id.
160pub fn new_trace_id() -> String {
161    uuid::Uuid::new_v4().to_string()
162}
163
164#[cfg(test)]
165mod tests {
166    use super::*;
167    use crate::context::{GatewayRequest, GatewayResponse, Protocol};
168    use bytes::Bytes;
169    use std::collections::HashMap;
170
171    fn ctx() -> Context {
172        Context {
173            request: GatewayRequest {
174                method: "GET".to_string(),
175                path: "/x".to_string(),
176                host: "h".to_string(),
177                scheme: "http".to_string(),
178                headers: HashMap::new(),
179                query_params: HashMap::new(),
180                body: Bytes::new(),
181                remote_addr: "1.2.3.4:5".to_string(),
182                protocol: Protocol::Http1,
183            },
184            response: GatewayResponse {
185                status_code: 0,
186                headers: HashMap::new(),
187                body: Bytes::new(),
188            },
189            message: HashMap::new(),
190            errors: Vec::new(),
191        }
192    }
193
194    /// Records `n` successful steps against `c` — the same context the engine
195    /// would hand back, so body dedup sees the real sequence.
196    fn record_n_with(rec: &mut TraceRecorder, c: &Context, n: usize) {
197        for i in 0..n {
198            rec.record_step(
199                &format!("n{i}"),
200                "cors",
201                StepOutcome::Success,
202                Duration::from_micros(5),
203                EdgeKind::Success,
204                None,
205                c,
206            );
207        }
208    }
209
210    fn record_n(rec: &mut TraceRecorder, n: usize) {
211        record_n_with(rec, &ctx(), n);
212    }
213
214    #[test]
215    fn test_steps_are_indexed_in_order() {
216        let c = ctx();
217        let mut rec = TraceRecorder::new(&c, CaptureOptions::default(), 100);
218        record_n(&mut rec, 3);
219        let t = rec.finish(
220            "id".to_string(),
221            0,
222            TraceSource::Request,
223            Some("r".to_string()),
224            "p".to_string(),
225            &c,
226            Duration::from_millis(1),
227        );
228        assert_eq!(t.steps.len(), 3);
229        let ids: Vec<&str> = t.steps.iter().map(|s| s.node_id.as_str()).collect();
230        assert_eq!(ids, vec!["n0", "n1", "n2"]);
231        assert_eq!(t.steps[2].index, 2);
232        assert!(t.notes.is_empty());
233    }
234
235    #[test]
236    fn test_step_limit_truncates_with_one_note() {
237        let c = ctx();
238        let mut rec = TraceRecorder::new(&c, CaptureOptions::default(), 2);
239        record_n(&mut rec, 6);
240        let t = rec.finish(
241            "id".to_string(),
242            0,
243            TraceSource::Request,
244            None,
245            "p".to_string(),
246            &c,
247            Duration::from_millis(1),
248        );
249        assert_eq!(t.steps.len(), 2);
250        // The note is added once, not once per dropped step.
251        assert_eq!(t.notes.len(), 1);
252        assert!(t.notes[0].contains("step limit"));
253    }
254
255    /// The recorder must carry the body forward so consecutive identical
256    /// bodies are not stored repeatedly.
257    #[test]
258    fn test_body_dedup_across_steps() {
259        let mut c = ctx();
260        c.request.body = Bytes::from_static(b"payload");
261        let opts = CaptureOptions {
262            capture_bodies: true,
263            ..Default::default()
264        };
265        let mut rec = TraceRecorder::new(&c, opts, 100);
266        // The same body flows through both nodes, as it would when no plugin
267        // touches it.
268        record_n_with(&mut rec, &c, 2);
269        let t = rec.finish(
270            "id".to_string(),
271            0,
272            TraceSource::Request,
273            None,
274            "p".to_string(),
275            &c,
276            Duration::from_millis(1),
277        );
278        // Captured once at the start...
279        assert_eq!(t.initial.request.body.text.as_deref(), Some("payload"));
280        // ...then marked unchanged rather than repeated per node.
281        assert!(t.steps[0].after.request.body.unchanged);
282        assert!(t.steps[1].after.request.body.unchanged);
283        assert_eq!(t.steps[0].after.request.body.len, 7);
284    }
285
286    #[test]
287    fn test_finish_reports_final_status() {
288        let c = ctx();
289        let mut end = ctx();
290        end.response.status_code = 403;
291        let mut rec = TraceRecorder::new(&c, CaptureOptions::default(), 10);
292        record_n(&mut rec, 1);
293        let t = rec.finish(
294            "id".to_string(),
295            7,
296            TraceSource::Sandbox,
297            None,
298            "p".to_string(),
299            &end,
300            Duration::from_micros(250),
301        );
302        assert_eq!(t.status, 403);
303        assert_eq!(t.seq, 7);
304        assert_eq!(t.source, TraceSource::Sandbox);
305        assert_eq!(t.duration_us, 250);
306        assert!(t.route.is_none());
307    }
308}
featherbit/debug/mod.rs

featherbit/debug/
mod.rs
