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

featherbit/debug/
mod.rs
