Skip to main content

dataflow_rs/engine/
trace.rs

1//! # Execution Trace Module
2//!
3//! This module provides step-by-step execution tracing for debugging workflows.
4//! It captures message snapshots after each step, including which workflows/tasks
5//! were executed or skipped.
6//!
7//! [`TraceOptions`] controls what a trace-mode run records. The default
8//! reproduces the historical behaviour — a full [`Message`] snapshot per
9//! executed step — which is unbounded in message size and quadratic in task
10//! count, because each snapshot clones the accumulated audit trail. Hosts that
11//! persist traces should set a snapshot budget, an audit-trail scope, or both.
12
13use crate::engine::message::{AuditTrail, Change, Message};
14use crate::engine::utils::strip_hash_prefix;
15use chrono::{DateTime, Utc};
16use datavalue::OwnedDataValue;
17use serde::{Deserialize, Serialize};
18use serde_json::Value;
19use std::sync::Arc;
20
21/// Approximate in-memory cost charged for a single container or scalar node.
22/// One machine word, per [`TraceOptions::max_snapshot_bytes`]'s contract.
23const NODE_SIZE: usize = std::mem::size_of::<usize>();
24
25/// `skip_serializing_if` predicate — omit `false` so a complete trace keeps the
26/// historical wire shape and only a truncated one carries the flag.
27#[inline]
28fn is_false(b: &bool) -> bool {
29    !*b
30}
31
32/// Result of executing a step (workflow or task)
33///
34/// Deliberately **not** `#[non_exhaustive]`. Downstream code matches on this to
35/// classify a step, and the npm wire type mirrors it as a string union; adding a
36/// variant should break those matches at compile time rather than silently
37/// reclassify them through a `_` arm.
38#[derive(Debug, Clone, Serialize, Deserialize, PartialEq, Eq)]
39#[serde(rename_all = "lowercase")]
40pub enum StepResult {
41    /// The step was executed
42    Executed,
43    /// The step was skipped due to condition being false
44    Skipped,
45}
46
47/// How much of [`Message::audit_trail`] a step's snapshot carries.
48///
49/// This is the knob for the *quadratic* term of trace size: under
50/// [`AuditTrailScope::Full`], step `i` clones `i` audit entries, so an N-task
51/// workflow retains `N*(N+1)/2` of them.
52#[derive(Clone, Copy, Debug, Default, PartialEq, Eq, Serialize, Deserialize)]
53#[serde(rename_all = "snake_case")]
54pub enum AuditTrailScope {
55    /// Every entry accumulated so far — the historical behaviour. Total entries
56    /// across the trace grow as `N*(N+1)/2` in task count.
57    #[default]
58    Full,
59    /// Only the entry this task produced, and none for a `TaskOutcome::Skip`
60    /// step. Linear in task count, and sufficient for the `dataflow-ui` step
61    /// debugger, which reads only the last entry.
62    Own,
63    /// Empty `audit_trail` in every snapshot.
64    None,
65}
66
67/// What a trace-mode run records for each executed step.
68///
69/// [`TraceOptions::default`] reproduces the historical capture behaviour: a full
70/// [`Message`] snapshot and per-mapping contexts on every executed step, no
71/// budget, no redaction, and the whole accumulated audit trail.
72///
73/// Trace mode reads the clock twice per executed task to populate
74/// [`ExecutionStep::duration_us`]. The non-trace path
75/// ([`crate::Engine::process_message`]) is unaffected and still takes a single
76/// `Utc::now()` per message.
77#[derive(Clone, Debug)]
78pub struct TraceOptions {
79    /// Full `Message` snapshot per executed step. `true` (default) is the
80    /// historical behaviour and is what the `dataflow-ui` step debugger
81    /// requires. With `false`, [`ExecutionTrace::final_message`] returns `None`
82    /// and [`ExecutionTrace::is_success`] degenerates to `true` — inspect
83    /// `Message::errors` on the message you passed in instead.
84    pub snapshots: bool,
85
86    /// Per-mapping context snapshots for `map` tasks. `true` (default). These
87    /// are whole-context clones, one per mapping, so a multi-mapping `map` task
88    /// can snapshot more than the step's own `Message` does.
89    pub mapping_contexts: bool,
90
91    /// Per-step diff: the changes produced by this task and nothing else.
92    /// `false` (default) preserves the historical payload byte for byte.
93    ///
94    /// Prefer this over reading `audit_trail.last()`, which mis-attributes on a
95    /// `TaskOutcome::Skip` step — no audit entry is recorded for a skip, so the
96    /// last entry belongs to a different task.
97    ///
98    /// Empty when the message was built with
99    /// `MessageBuilder::capture_changes(false)`: this flag reports the diff, it
100    /// does not turn capture on.
101    pub changes: bool,
102
103    /// Soft budget over the *approximate accumulated in-memory size* of the
104    /// snapshots taken so far — container and scalar nodes counted as one
105    /// machine word, `String` contents by `str::len()`. This is **not**
106    /// serialized JSON length; measuring that would mean serializing every step,
107    /// which defeats the purpose of a pre-capture budget.
108    ///
109    /// Once exceeded, later executed steps are still recorded — ids, result,
110    /// timing, and `changes` if enabled — with `message: None`, and
111    /// [`ExecutionTrace::truncated`] returns `true`. `0` (default) is unbounded.
112    pub max_snapshot_bytes: usize,
113
114    /// Dot-paths under the message context whose subtrees are replaced with
115    /// `OwnedDataValue::Null` as the snapshot is built, via a *pruning clone*:
116    /// the redacted subtree is never cloned, so this bounds the snapshot's
117    /// memory as well as its content. The live message is untouched, so later
118    /// tasks still read the real values.
119    ///
120    /// Also applied to `mapping_contexts`, which are whole-context clones and
121    /// would otherwise carry the redacted subtree through unchanged.
122    ///
123    /// Path syntax is the [`crate::engine::utils::get_nested_value`] vocabulary:
124    /// dot segments, numeric segments index arrays, one leading `#` escapes a
125    /// numerically-named object key. Unlike `set_nested_value`, a path that does
126    /// not resolve creates nothing and is a no-op, and an empty path is ignored.
127    ///
128    /// This is a literal path list and nothing more — no value scanning, no
129    /// pattern matching, no credential heuristics. It is not a masking engine.
130    pub redact_paths: Vec<String>,
131
132    /// How much of the accumulated audit trail each snapshot carries. See
133    /// [`AuditTrailScope`]; this is the lever for trace size in task count.
134    pub snapshot_audit_trail: AuditTrailScope,
135}
136
137impl Default for TraceOptions {
138    fn default() -> Self {
139        Self {
140            snapshots: true,
141            mapping_contexts: true,
142            changes: false,
143            max_snapshot_bytes: 0,
144            redact_paths: Vec::new(),
145            snapshot_audit_trail: AuditTrailScope::Full,
146        }
147    }
148}
149
150impl TraceOptions {
151    /// Ids, result, timing and the per-task diff; no message snapshots and no
152    /// mapping contexts. A step costs a few hundred bytes plus its diff,
153    /// regardless of message size or task count.
154    ///
155    /// Note this is UI-incompatible: the `dataflow-ui` step debugger needs
156    /// snapshots to render the step view.
157    pub fn timings_only() -> Self {
158        Self {
159            snapshots: false,
160            mapping_contexts: false,
161            changes: true,
162            ..Default::default()
163        }
164    }
165
166    /// Pre-split `redact_paths` into raw segments once per trace.
167    ///
168    /// Segments stay raw so object-key matching can apply the `#` escape while
169    /// array matching parses the segment, exactly as `get_nested_value` does.
170    /// Empty paths are dropped here, which is what makes them a no-op.
171    fn redact_segments(&self) -> Vec<Vec<String>> {
172        self.redact_paths
173            .iter()
174            .filter(|p| !p.is_empty())
175            .map(|p| p.split('.').map(str::to_string).collect())
176            .collect()
177    }
178}
179
180/// Task-body timing for an executed step: when the body started and how long
181/// it ran.
182///
183/// Bundled because both executor call sites always have the pair — it is
184/// exactly what [`ExecutionStep::with_timing`] sets — and because it keeps
185/// [`ExecutionTrace::add_executed_step`] inside clippy's argument-count
186/// threshold now that the loop counter rides along too.
187#[derive(Clone, Copy, Debug)]
188pub(crate) struct StepTiming {
189    /// Wall-clock start of the task body.
190    pub started_at: DateTime<Utc>,
191    /// Task body duration in microseconds.
192    pub duration_us: u64,
193}
194
195/// A single step in the execution trace
196///
197/// `#[non_exhaustive]`: construct through [`ExecutionStep::executed`],
198/// [`ExecutionStep::task_skipped`] or [`ExecutionStep::workflow_skipped`] and
199/// chain the `with_*` methods. Field reads and `..` patterns are unaffected.
200#[derive(Debug, Clone, Serialize, Deserialize)]
201#[non_exhaustive]
202pub struct ExecutionStep {
203    /// ID of the workflow this step belongs to
204    pub workflow_id: String,
205    /// ID of the task (None for workflow-level skips)
206    pub task_id: Option<String>,
207    /// Result of the step execution
208    pub result: StepResult,
209    /// Message snapshot after this step. `None` for skipped steps, when
210    /// [`TraceOptions::snapshots`] is off, and for executed steps recorded after
211    /// [`TraceOptions::max_snapshot_bytes`] was exceeded.
212    #[serde(skip_serializing_if = "Option::is_none")]
213    pub message: Option<Message>,
214    /// Context snapshots before each mapping (map tasks only, trace mode only).
215    /// `mapping_contexts[i]` is `message.context` before `mapping[i]` executed.
216    #[serde(skip_serializing_if = "Option::is_none")]
217    pub mapping_contexts: Option<Vec<Value>>,
218    /// Wall-clock start of the task body. `Executed` steps only.
219    ///
220    /// `chrono`, not `std::time::Instant`: `Instant::now()` panics on
221    /// `wasm32-unknown-unknown`, and the wasm bindings run the trace path there.
222    #[serde(skip_serializing_if = "Option::is_none")]
223    pub started_at: Option<DateTime<Utc>>,
224    /// Task body duration in microseconds. `Executed` steps only.
225    ///
226    /// Derived from two `Utc::now()` reads, which are not monotonic: a backward
227    /// clock step clamps to `0` rather than wrapping.
228    #[serde(skip_serializing_if = "Option::is_none")]
229    pub duration_us: Option<u64>,
230    /// This task's own writes, when [`TraceOptions::changes`] is set. `Some(vec![])`
231    /// means the task wrote nothing (or change capture is off), which is
232    /// distinct from `None` meaning "not recorded".
233    #[serde(skip_serializing_if = "Option::is_none")]
234    pub changes: Option<Vec<Change>>,
235    /// Loop counter of the sweep this step belongs to, for workflows carrying
236    /// a [`crate::engine::workflow::LoopConfig`]; `None` otherwise. Group
237    /// steps by it to reconstruct per-iteration execution.
238    ///
239    /// Mirrors [`crate::engine::message::AuditTrail::loop_counter`], including
240    /// being skipped when `None` so a non-looping trace keeps its historical
241    /// wire shape.
242    #[serde(default, skip_serializing_if = "Option::is_none")]
243    pub loop_counter: Option<i64>,
244    /// Index of the element this step ran for, for a task carrying a
245    /// [`crate::engine::for_each::ForEach`]; `None` otherwise. Mirrors
246    /// [`crate::engine::message::AuditTrail::element_index`], including being
247    /// skipped when `None`.
248    #[serde(default, skip_serializing_if = "Option::is_none")]
249    pub element_index: Option<usize>,
250}
251
252impl ExecutionStep {
253    /// Create a new executed step with a message snapshot
254    pub fn executed(workflow_id: &str, task_id: &str, message: &Message) -> Self {
255        Self {
256            workflow_id: workflow_id.to_string(),
257            task_id: Some(task_id.to_string()),
258            result: StepResult::Executed,
259            message: Some(message.clone()),
260            mapping_contexts: None,
261            started_at: None,
262            duration_us: None,
263            changes: None,
264            loop_counter: None,
265            element_index: None,
266        }
267    }
268
269    /// Create a skipped task step
270    pub fn task_skipped(workflow_id: &str, task_id: &str) -> Self {
271        Self {
272            workflow_id: workflow_id.to_string(),
273            task_id: Some(task_id.to_string()),
274            result: StepResult::Skipped,
275            message: None,
276            mapping_contexts: None,
277            started_at: None,
278            duration_us: None,
279            changes: None,
280            loop_counter: None,
281            element_index: None,
282        }
283    }
284
285    /// Create a skipped workflow step
286    pub fn workflow_skipped(workflow_id: &str) -> Self {
287        Self {
288            workflow_id: workflow_id.to_string(),
289            task_id: None,
290            result: StepResult::Skipped,
291            message: None,
292            mapping_contexts: None,
293            started_at: None,
294            duration_us: None,
295            changes: None,
296            loop_counter: None,
297            element_index: None,
298        }
299    }
300
301    /// Set mapping context snapshots (for map tasks in trace mode)
302    pub fn with_mapping_contexts(mut self, contexts: Vec<Value>) -> Self {
303        self.mapping_contexts = Some(contexts);
304        self
305    }
306
307    /// Attach task-body timing. Chains after [`Self::executed`].
308    pub fn with_timing(mut self, started_at: DateTime<Utc>, duration_us: u64) -> Self {
309        self.started_at = Some(started_at);
310        self.duration_us = Some(duration_us);
311        self
312    }
313
314    /// Attach this task's own diff. Chains after [`Self::executed`].
315    pub fn with_changes(mut self, changes: Vec<Change>) -> Self {
316        self.changes = Some(changes);
317        self
318    }
319
320    /// Attach the loop counter of the sweep this step belongs to. `None` is
321    /// the non-looping case and leaves the step's JSON unchanged.
322    pub fn with_loop_counter(mut self, loop_counter: Option<i64>) -> Self {
323        self.loop_counter = loop_counter;
324        self
325    }
326
327    /// Attach the fan-out element this step ran for. `None` is the ordinary
328    /// case and leaves the step's JSON unchanged.
329    pub fn with_element_index(mut self, element_index: Option<usize>) -> Self {
330        self.element_index = element_index;
331        self
332    }
333}
334
335/// Where in a run one executed step sits: the loop sweep and the fan-out
336/// element, either of which may be absent.
337///
338/// Bundled so that stamping a second coordinate did not push
339/// [`ExecutionTrace::add_executed_step`] past clippy's argument-count limit.
340#[derive(Clone, Copy, Debug, Default)]
341pub(crate) struct StepStamp {
342    pub loop_counter: Option<i64>,
343    pub element_index: Option<usize>,
344}
345
346/// Complete execution trace containing all steps
347///
348/// `#[non_exhaustive]`: construct with [`ExecutionTrace::new`] or
349/// [`ExecutionTrace::with_options`]. `steps` stays public for reads.
350#[derive(Debug, Clone, Serialize, Deserialize)]
351#[non_exhaustive]
352pub struct ExecutionTrace {
353    /// All execution steps in order
354    pub steps: Vec<ExecutionStep>,
355
356    /// Set when `max_snapshot_bytes` was exceeded. Serialized only when `true`,
357    /// so a complete trace keeps the historical wire shape.
358    #[serde(default, skip_serializing_if = "is_false")]
359    truncated: bool,
360
361    /// Capture policy. In-memory only — a deserialized trace carries the
362    /// default, which is why `options()` is documented as the policy this trace
363    /// *records* with rather than the one it was recorded with.
364    #[serde(skip)]
365    options: TraceOptions,
366
367    /// Pre-split `options.redact_paths`, so the split cost is paid once.
368    #[serde(skip)]
369    redact_segments: Vec<Vec<String>>,
370
371    /// Approximate accumulated in-memory size of snapshots taken so far.
372    #[serde(skip)]
373    snapshot_bytes: usize,
374}
375
376impl ExecutionTrace {
377    /// Create a new empty execution trace with default capture policy.
378    pub fn new() -> Self {
379        Self::with_options(TraceOptions::default())
380    }
381
382    /// Empty trace that records according to `options`.
383    pub fn with_options(options: TraceOptions) -> Self {
384        Self {
385            steps: Vec::new(),
386            truncated: false,
387            redact_segments: options.redact_segments(),
388            options,
389            snapshot_bytes: 0,
390        }
391    }
392
393    /// The capture policy this trace records with.
394    pub fn options(&self) -> &TraceOptions {
395        &self.options
396    }
397
398    /// Whether [`TraceOptions::max_snapshot_bytes`] was exceeded, and one or
399    /// more executed steps therefore carry `message: None`, missing mapping
400    /// contexts, or both.
401    ///
402    /// The budget is shared across both: with [`TraceOptions::snapshots`] off
403    /// but [`TraceOptions::mapping_contexts`] on, this can still return `true`
404    /// from the mapping-context term alone, even though no step was ever going
405    /// to carry a `message`.
406    pub fn truncated(&self) -> bool {
407        self.truncated
408    }
409
410    /// Add a step to the trace
411    pub fn add_step(&mut self, step: ExecutionStep) {
412        self.steps.push(step);
413    }
414
415    /// Record an executed step under this trace's capture policy.
416    ///
417    /// Owns every policy decision — snapshot scope, pruning clone, audit-trail
418    /// scope, budget check, timing and diff — so the executor's two dispatch
419    /// sites do not duplicate any of it.
420    pub(crate) fn add_executed_step(
421        &mut self,
422        workflow_id: &str,
423        task_id: &str,
424        message: &Message,
425        timing: StepTiming,
426        mapping_contexts: Option<Vec<Value>>,
427        stamp: StepStamp,
428    ) {
429        let mut step = ExecutionStep {
430            workflow_id: workflow_id.to_string(),
431            task_id: Some(task_id.to_string()),
432            result: StepResult::Executed,
433            message: None,
434            mapping_contexts: None,
435            started_at: Some(timing.started_at),
436            duration_us: Some(timing.duration_us),
437            loop_counter: stamp.loop_counter,
438            element_index: stamp.element_index,
439            changes: if self.options.changes {
440                // Derived from this task's own audit entry rather than
441                // `audit_trail.last()` unconditionally — that is the
442                // mis-attribution being fixed. A `TaskOutcome::Skip` records no
443                // entry, so it correctly reports an empty diff instead of
444                // inheriting the previous task's (or another workflow's).
445                Some(
446                    own_audit_entry(message, workflow_id, task_id)
447                        .map(|e| e.changes.clone())
448                        .unwrap_or_default(),
449                )
450            } else {
451                None
452            },
453        };
454
455        if self.options.snapshots {
456            // Size is *probed* without cloning, so a snapshot that would not fit
457            // is never built. Checking after the clone would be pointless: the
458            // peak memory this budget exists to bound has already been paid.
459            let projected = self.projected_snapshot_size(message, workflow_id, task_id);
460            if self.would_exceed(projected) {
461                self.truncated = true;
462            } else {
463                self.snapshot_bytes += projected;
464                step.message = Some(self.build_snapshot(message, workflow_id, task_id));
465            }
466        }
467
468        if self.options.mapping_contexts
469            && let Some(mut contexts) = mapping_contexts
470        {
471            // These arrive already cloned by the map function, so redact
472            // first and then decide whether to retain them.
473            for ctx in &mut contexts {
474                redact_json_in_place(ctx, &self.redact_segments);
475            }
476            let size: usize = contexts.iter().map(approx_json_size).sum();
477            if self.would_exceed(size) {
478                self.truncated = true;
479            } else {
480                self.snapshot_bytes += size;
481                step.mapping_contexts = Some(contexts);
482            }
483        }
484
485        self.steps.push(step);
486    }
487
488    /// Whether retaining `additional` bytes would cross a finite budget.
489    #[inline]
490    fn would_exceed(&self, additional: usize) -> bool {
491        self.options.max_snapshot_bytes != 0
492            && self.snapshot_bytes + additional > self.options.max_snapshot_bytes
493    }
494
495    /// Approximate size the snapshot for this step would occupy, computed
496    /// without cloning anything.
497    ///
498    /// Must agree with what [`Self::build_snapshot`] actually retains; a unit
499    /// test pins the two together.
500    fn projected_snapshot_size(
501        &self,
502        message: &Message,
503        workflow_id: &str,
504        task_id: &str,
505    ) -> usize {
506        let mut size = redacted_size(&message.context, &self.redact_segments);
507        for entry in self.scoped_audit_trail(message, workflow_id, task_id) {
508            size += NODE_SIZE;
509            for change in &entry.changes {
510                size += change.path.len()
511                    + approx_owned_size(&change.old_value)
512                    + approx_owned_size(&change.new_value);
513            }
514        }
515        size
516    }
517
518    /// The audit entries this step's snapshot will carry, per
519    /// [`TraceOptions::snapshot_audit_trail`].
520    fn scoped_audit_trail<'m>(
521        &self,
522        message: &'m Message,
523        workflow_id: &str,
524        task_id: &str,
525    ) -> Vec<&'m AuditTrail> {
526        match self.options.snapshot_audit_trail {
527            AuditTrailScope::Full => message.audit_trail().iter().collect(),
528            AuditTrailScope::Own => own_audit_entry(message, workflow_id, task_id)
529                .map(|e| vec![e])
530                .unwrap_or_default(),
531            AuditTrailScope::None => Vec::new(),
532        }
533    }
534
535    /// Build this step's snapshot: context pruned per `redact_paths`, audit
536    /// trail scoped per `snapshot_audit_trail`. Returns the approximate
537    /// in-memory size charged to the budget.
538    ///
539    /// `payload` is an `Arc`, so it is shared rather than deep-cloned here —
540    /// same as the derived `Message::clone` this replaces.
541    fn build_snapshot(&self, message: &Message, workflow_id: &str, task_id: &str) -> Message {
542        let (context, _) = redacting_clone(&message.context, &self.redact_segments);
543        let audit_trail: Vec<AuditTrail> = self
544            .scoped_audit_trail(message, workflow_id, task_id)
545            .into_iter()
546            .cloned()
547            .collect();
548
549        Message {
550            id: message.id.clone(),
551            payload: Arc::clone(&message.payload),
552            context,
553            audit_trail,
554            errors: message.errors.clone(),
555            capture_changes: message.capture_changes,
556            routing_bucket: message.routing_bucket,
557            audit_mode: message.audit_mode,
558        }
559    }
560
561    /// Get the final message (from the last executed step)
562    ///
563    /// Returns `None` when [`TraceOptions::snapshots`] is off, or when every
564    /// executed step was recorded after the snapshot budget was exceeded.
565    pub fn final_message(&self) -> Option<&Message> {
566        self.steps
567            .iter()
568            .rev()
569            .find(|s| s.result == StepResult::Executed)
570            .and_then(|s| s.message.as_ref())
571    }
572
573    /// Check if execution was successful (no errors in final message)
574    ///
575    /// Degenerates to `true` when there is no snapshot to inspect — with
576    /// [`TraceOptions::snapshots`] off, read `Message::errors` on the message you
577    /// passed in instead.
578    pub fn is_success(&self) -> bool {
579        self.final_message()
580            .map(|m| m.errors.is_empty())
581            .unwrap_or(true)
582    }
583
584    /// Get number of executed steps
585    pub fn executed_count(&self) -> usize {
586        self.steps
587            .iter()
588            .filter(|s| s.result == StepResult::Executed)
589            .count()
590    }
591
592    /// Get number of skipped steps
593    pub fn skipped_count(&self) -> usize {
594        self.steps
595            .iter()
596            .filter(|s| s.result == StepResult::Skipped)
597            .count()
598    }
599}
600
601impl Default for ExecutionTrace {
602    fn default() -> Self {
603        Self::new()
604    }
605}
606
607/// The audit entry this task produced, if any.
608///
609/// The executor pushes at most one entry per task and pushes it immediately, so
610/// the last entry is this task's exactly when both its workflow and task id
611/// match. A `TaskOutcome::Skip` records none — which is why reading
612/// `audit_trail.last()` unconditionally mis-attributes the previous task's diff
613/// to a skipped step. Comparing `task_id` alone is not enough either: two
614/// workflows can share a task id (or the same task can run again in a later
615/// workflow), so a `Skip` right after a same-named task in a different
616/// workflow would otherwise inherit that other workflow's entry.
617#[inline]
618fn own_audit_entry<'m>(
619    message: &'m Message,
620    workflow_id: &str,
621    task_id: &str,
622) -> Option<&'m AuditTrail> {
623    match message.audit_trail.last() {
624        Some(entry)
625            if entry.task_id.as_ref() == task_id && entry.workflow_id.as_ref() == workflow_id =>
626        {
627            Some(entry)
628        }
629        _ => None,
630    }
631}
632
633/// Microseconds between two non-monotonic clock reads, clamped at `0`.
634///
635/// `Utc::now()` can step backwards, and `num_microseconds()` returns `None` on
636/// overflow; both collapse to `0` rather than panicking or wrapping.
637#[inline]
638pub(crate) fn duration_us_between(start: DateTime<Utc>, end: DateTime<Utc>) -> u64 {
639    (end - start)
640        .num_microseconds()
641        .unwrap_or(0)
642        .max(0)
643        .try_into()
644        .unwrap_or(0)
645}
646
647/// Deep-clone `value`, substituting `OwnedDataValue::Null` for every subtree
648/// named by `paths`, and return the approximate in-memory size of the result.
649///
650/// `paths` holds the path suffixes still in play at this node; an empty suffix
651/// means this node is itself a redaction target, so its subtree is never
652/// cloned. A suffix that matches nothing is dropped, which is what makes an
653/// unresolvable path a no-op rather than a `set_nested_value`-style create.
654fn redacting_clone(value: &OwnedDataValue, paths: &[Vec<String>]) -> (OwnedDataValue, usize) {
655    let refs: Vec<&[String]> = paths.iter().map(|p| p.as_slice()).collect();
656    redacting_clone_inner(value, &refs)
657}
658
659/// Narrow `paths` to the child suffixes that still apply under object key
660/// `key` — the entries whose head segment (after the `#`-prefix escape)
661/// matches `key`, each with that head segment dropped. Shared by every
662/// redact/size walker below so the "does this path element apply here"
663/// filter has one definition instead of one copy per walker per value type.
664fn narrow_for_object_key<'a>(paths: &[&'a [String]], key: &str) -> Vec<&'a [String]> {
665    paths
666        .iter()
667        .filter(|p| strip_hash_prefix(&p[0]) == key)
668        .map(|p| &p[1..])
669        .collect()
670}
671
672/// Same as [`narrow_for_object_key`] but for an array index: the entries
673/// whose head segment parses as `idx`.
674fn narrow_for_array_index<'a>(paths: &[&'a [String]], idx: usize) -> Vec<&'a [String]> {
675    paths
676        .iter()
677        .filter(|p| p[0].parse::<usize>() == Ok(idx))
678        .map(|p| &p[1..])
679        .collect()
680}
681
682fn redacting_clone_inner(value: &OwnedDataValue, paths: &[&[String]]) -> (OwnedDataValue, usize) {
683    // An exhausted suffix names this node: redact without descending.
684    if paths.iter().any(|p| p.is_empty()) {
685        return (OwnedDataValue::Null, NODE_SIZE);
686    }
687
688    match value {
689        OwnedDataValue::Object(pairs) => {
690            let mut out = Vec::with_capacity(pairs.len());
691            let mut size = NODE_SIZE;
692            for (key, child) in pairs {
693                let sub = narrow_for_object_key(paths, key);
694                let (cloned, child_size) = redacting_clone_inner(child, &sub);
695                size += key.len() + child_size;
696                out.push((key.clone(), cloned));
697            }
698            (OwnedDataValue::Object(out), size)
699        }
700        OwnedDataValue::Array(items) => {
701            let mut out = Vec::with_capacity(items.len());
702            let mut size = NODE_SIZE;
703            for (idx, child) in items.iter().enumerate() {
704                let sub = narrow_for_array_index(paths, idx);
705                let (cloned, child_size) = redacting_clone_inner(child, &sub);
706                size += child_size;
707                out.push(cloned);
708            }
709            (OwnedDataValue::Array(out), size)
710        }
711        // Scalars: any leftover suffix cannot resolve, so it is dropped.
712        OwnedDataValue::String(s) => (value.clone(), NODE_SIZE + s.len()),
713        other => (other.clone(), NODE_SIZE),
714    }
715}
716
717/// Size [`redacting_clone`] would produce, computed without cloning.
718///
719/// Exists so the snapshot budget can decline a capture *before* paying for it.
720/// Must stay in step with `redacting_clone`; `redacted_size_agrees_with_redacting_clone`
721/// pins that.
722fn redacted_size(value: &OwnedDataValue, paths: &[Vec<String>]) -> usize {
723    let refs: Vec<&[String]> = paths.iter().map(|p| p.as_slice()).collect();
724    redacted_size_inner(value, &refs)
725}
726
727fn redacted_size_inner(value: &OwnedDataValue, paths: &[&[String]]) -> usize {
728    if paths.iter().any(|p| p.is_empty()) {
729        return NODE_SIZE;
730    }
731    match value {
732        OwnedDataValue::Object(pairs) => {
733            let mut size = NODE_SIZE;
734            for (key, child) in pairs {
735                let sub = narrow_for_object_key(paths, key);
736                size += key.len() + redacted_size_inner(child, &sub);
737            }
738            size
739        }
740        OwnedDataValue::Array(items) => {
741            let mut size = NODE_SIZE;
742            for (idx, child) in items.iter().enumerate() {
743                let sub = narrow_for_array_index(paths, idx);
744                size += redacted_size_inner(child, &sub);
745            }
746            size
747        }
748        OwnedDataValue::String(s) => NODE_SIZE + s.len(),
749        _ => NODE_SIZE,
750    }
751}
752
753/// Approximate in-memory size of an `OwnedDataValue`, on the same scale as
754/// [`redacting_clone`].
755fn approx_owned_size(value: &OwnedDataValue) -> usize {
756    match value {
757        OwnedDataValue::Object(pairs) => {
758            NODE_SIZE
759                + pairs
760                    .iter()
761                    .map(|(k, v)| k.len() + approx_owned_size(v))
762                    .sum::<usize>()
763        }
764        OwnedDataValue::Array(items) => {
765            NODE_SIZE + items.iter().map(approx_owned_size).sum::<usize>()
766        }
767        OwnedDataValue::String(s) => NODE_SIZE + s.len(),
768        _ => NODE_SIZE,
769    }
770}
771
772/// Null out every subtree named by `paths` in a `serde_json::Value`, in place.
773///
774/// Mirrors [`redacting_clone`]'s path semantics so `mapping_contexts` are
775/// redacted the same way message snapshots are. In place because the caller
776/// already owns the value — there is no second clone to save.
777fn redact_json_in_place(value: &mut Value, paths: &[Vec<String>]) {
778    let refs: Vec<&[String]> = paths.iter().map(|p| p.as_slice()).collect();
779    redact_json_inner(value, &refs);
780}
781
782fn redact_json_inner(value: &mut Value, paths: &[&[String]]) {
783    if paths.is_empty() {
784        return;
785    }
786    if paths.iter().any(|p| p.is_empty()) {
787        *value = Value::Null;
788        return;
789    }
790
791    match value {
792        Value::Object(map) => {
793            for (key, child) in map.iter_mut() {
794                let sub = narrow_for_object_key(paths, key);
795                redact_json_inner(child, &sub);
796            }
797        }
798        Value::Array(items) => {
799            for (idx, child) in items.iter_mut().enumerate() {
800                let sub = narrow_for_array_index(paths, idx);
801                redact_json_inner(child, &sub);
802            }
803        }
804        _ => {}
805    }
806}
807
808/// Approximate in-memory size of a `serde_json::Value`, on the same scale as
809/// [`approx_owned_size`].
810fn approx_json_size(value: &Value) -> usize {
811    match value {
812        Value::Object(map) => {
813            NODE_SIZE
814                + map
815                    .iter()
816                    .map(|(k, v)| k.len() + approx_json_size(v))
817                    .sum::<usize>()
818        }
819        Value::Array(items) => NODE_SIZE + items.iter().map(approx_json_size).sum::<usize>(),
820        Value::String(s) => NODE_SIZE + s.len(),
821        _ => NODE_SIZE,
822    }
823}
824
825#[cfg(test)]
826mod tests {
827    use super::*;
828    use serde_json::json;
829
830    fn dv(v: serde_json::Value) -> OwnedDataValue {
831        OwnedDataValue::from(&v)
832    }
833
834    fn segments(paths: &[&str]) -> Vec<Vec<String>> {
835        TraceOptions {
836            redact_paths: paths.iter().map(|s| s.to_string()).collect(),
837            ..Default::default()
838        }
839        .redact_segments()
840    }
841
842    #[test]
843    fn test_step_result_serialization() {
844        assert_eq!(
845            serde_json::to_string(&StepResult::Executed).unwrap(),
846            "\"executed\""
847        );
848        assert_eq!(
849            serde_json::to_string(&StepResult::Skipped).unwrap(),
850            "\"skipped\""
851        );
852    }
853
854    #[test]
855    fn test_execution_step_executed() {
856        let message = Message::from_value(&json!({"test": "data"}));
857        let step = ExecutionStep::executed("workflow1", "task1", &message);
858
859        assert_eq!(step.workflow_id, "workflow1");
860        assert_eq!(step.task_id, Some("task1".to_string()));
861        assert_eq!(step.result, StepResult::Executed);
862        assert!(step.message.is_some());
863    }
864
865    #[test]
866    fn test_execution_step_task_skipped() {
867        let step = ExecutionStep::task_skipped("workflow1", "task1");
868
869        assert_eq!(step.workflow_id, "workflow1");
870        assert_eq!(step.task_id, Some("task1".to_string()));
871        assert_eq!(step.result, StepResult::Skipped);
872        assert!(step.message.is_none());
873    }
874
875    #[test]
876    fn test_execution_step_workflow_skipped() {
877        let step = ExecutionStep::workflow_skipped("workflow1");
878
879        assert_eq!(step.workflow_id, "workflow1");
880        assert_eq!(step.task_id, None);
881        assert_eq!(step.result, StepResult::Skipped);
882        assert!(step.message.is_none());
883    }
884
885    #[test]
886    fn test_execution_step_with_mapping_contexts() {
887        let message = Message::from_value(&json!({"test": "data"}));
888        let contexts = vec![json!({"data": {"a": 1}}), json!({"data": {"a": 1, "b": 2}})];
889
890        let step = ExecutionStep::executed("workflow1", "task1", &message)
891            .with_mapping_contexts(contexts.clone());
892
893        assert_eq!(step.mapping_contexts, Some(contexts));
894
895        // Verify serialization includes mapping_contexts
896        let serialized = serde_json::to_value(&step).unwrap();
897        assert!(serialized.get("mapping_contexts").is_some());
898        assert_eq!(serialized["mapping_contexts"].as_array().unwrap().len(), 2);
899    }
900
901    #[test]
902    fn test_execution_step_without_mapping_contexts_serialization() {
903        let message = Message::from_value(&json!({"test": "data"}));
904        let step = ExecutionStep::executed("workflow1", "task1", &message);
905
906        // Every optional field is None, so all are omitted in serialization.
907        let serialized = serde_json::to_value(&step).unwrap();
908        assert!(serialized.get("mapping_contexts").is_none());
909        assert!(serialized.get("started_at").is_none());
910        assert!(serialized.get("duration_us").is_none());
911        assert!(serialized.get("changes").is_none());
912    }
913
914    #[test]
915    fn test_execution_trace() {
916        let mut trace = ExecutionTrace::new();
917        let message = Message::from_value(&json!({"test": "data"}));
918
919        trace.add_step(ExecutionStep::workflow_skipped("workflow0"));
920        trace.add_step(ExecutionStep::executed("workflow1", "task1", &message));
921        trace.add_step(ExecutionStep::task_skipped("workflow1", "task2"));
922
923        assert_eq!(trace.steps.len(), 3);
924        assert_eq!(trace.executed_count(), 1);
925        assert_eq!(trace.skipped_count(), 2);
926        assert!(trace.final_message().is_some());
927        assert!(trace.is_success());
928    }
929
930    #[test]
931    fn default_options_reproduce_historical_capture() {
932        let o = TraceOptions::default();
933        assert!(o.snapshots);
934        assert!(o.mapping_contexts);
935        assert!(!o.changes);
936        assert_eq!(o.max_snapshot_bytes, 0);
937        assert!(o.redact_paths.is_empty());
938        assert_eq!(o.snapshot_audit_trail, AuditTrailScope::Full);
939    }
940
941    #[test]
942    fn timings_only_drops_snapshots_and_keeps_the_diff() {
943        let o = TraceOptions::timings_only();
944        assert!(!o.snapshots);
945        assert!(!o.mapping_contexts);
946        assert!(o.changes);
947    }
948
949    #[test]
950    fn a_complete_trace_does_not_serialize_the_truncated_flag() {
951        let trace = ExecutionTrace::new();
952        let serialized = serde_json::to_value(&trace).unwrap();
953        assert!(
954            serialized.get("truncated").is_none(),
955            "a complete trace keeps the historical wire shape"
956        );
957        assert!(!trace.truncated());
958    }
959
960    #[test]
961    fn a_trace_deserializes_from_a_payload_without_the_truncated_flag() {
962        let trace: ExecutionTrace = serde_json::from_value(json!({ "steps": [] })).unwrap();
963        assert!(!trace.truncated());
964    }
965
966    #[test]
967    fn duration_clamps_a_backward_clock_step_to_zero() {
968        let start = Utc::now();
969        let earlier = start - chrono::Duration::seconds(5);
970        assert_eq!(duration_us_between(start, earlier), 0);
971        assert_eq!(duration_us_between(start, start), 0);
972        assert_eq!(
973            duration_us_between(start, start + chrono::Duration::microseconds(1500)),
974            1500
975        );
976    }
977
978    #[test]
979    fn redaction_nulls_only_the_named_subtree() {
980        let ctx = dv(json!({"data": {"secret": {"k": "v"}, "keep": 1}}));
981        let (out, _) = redacting_clone(&ctx, &segments(&["data.secret"]));
982        assert_eq!(
983            serde_json::Value::from(&out),
984            json!({"data": {"secret": null, "keep": 1}})
985        );
986    }
987
988    #[test]
989    fn redaction_of_an_unresolvable_path_creates_nothing() {
990        // `set_nested_value` would pad the array to index 99 with nulls; this
991        // must not.
992        let ctx = dv(json!({"data": {"items": [1, 2, 3]}}));
993        let (out, _) = redacting_clone(&ctx, &segments(&["data.items.99"]));
994        assert_eq!(
995            serde_json::Value::from(&out),
996            json!({"data": {"items": [1, 2, 3]}})
997        );
998    }
999
1000    #[test]
1001    fn redaction_through_a_non_container_is_a_noop() {
1002        let ctx = dv(json!({"data": {"name": "alice"}}));
1003        let (out, _) = redacting_clone(&ctx, &segments(&["data.name.first"]));
1004        assert_eq!(
1005            serde_json::Value::from(&out),
1006            json!({"data": {"name": "alice"}})
1007        );
1008    }
1009
1010    #[test]
1011    fn an_empty_redact_path_is_ignored() {
1012        let ctx = dv(json!({"data": {"a": 1}}));
1013        let (out, _) = redacting_clone(&ctx, &segments(&[""]));
1014        assert_eq!(serde_json::Value::from(&out), json!({"data": {"a": 1}}));
1015    }
1016
1017    #[test]
1018    fn redaction_honours_the_hash_escape() {
1019        // `data.#20` names the object key "20"; `data.20` indexes an array.
1020        let obj = dv(json!({"data": {"20": "secret", "other": 1}}));
1021        let (out, _) = redacting_clone(&obj, &segments(&["data.#20"]));
1022        assert_eq!(
1023            serde_json::Value::from(&out),
1024            json!({"data": {"20": null, "other": 1}})
1025        );
1026
1027        let arr = dv(json!({"data": [0, 1, 2]}));
1028        let (out, _) = redacting_clone(&arr, &segments(&["data.1"]));
1029        assert_eq!(serde_json::Value::from(&out), json!({"data": [0, null, 2]}));
1030
1031        // The escaped form does not index an array.
1032        let (out, _) = redacting_clone(&arr, &segments(&["data.#1"]));
1033        assert_eq!(serde_json::Value::from(&out), json!({"data": [0, 1, 2]}));
1034    }
1035
1036    #[test]
1037    fn nested_and_duplicated_redact_paths_are_safe() {
1038        let ctx = dv(json!({"data": {"a": {"b": 1, "c": 2}}}));
1039
1040        let (out, _) = redacting_clone(&ctx, &segments(&["data.a", "data.a.b"]));
1041        assert_eq!(serde_json::Value::from(&out), json!({"data": {"a": null}}));
1042
1043        let (out, _) = redacting_clone(&ctx, &segments(&["data.a", "data.a"]));
1044        assert_eq!(serde_json::Value::from(&out), json!({"data": {"a": null}}));
1045    }
1046
1047    #[test]
1048    fn redaction_matches_unicode_keys_and_sizes_strings_by_bytes() {
1049        let ctx = dv(json!({"data": {"café": "secret", "keep": "née"}}));
1050        let (out, size) = redacting_clone(&ctx, &segments(&["data.café"]));
1051        assert_eq!(
1052            serde_json::Value::from(&out),
1053            json!({"data": {"café": null, "keep": "née"}})
1054        );
1055
1056        // "née" is 4 bytes, 3 chars — the budget counts bytes.
1057        let (_, unredacted) = redacting_clone(&ctx, &segments(&[]));
1058        assert!(unredacted > size, "redacting must lower the counted size");
1059        assert!(
1060            approx_owned_size(&dv(json!("née"))) == NODE_SIZE + 4,
1061            "str::len() bytes, not chars().count()"
1062        );
1063    }
1064
1065    #[test]
1066    fn redacted_size_agrees_with_redacting_clone() {
1067        // The budget probes with `redacted_size` and then builds with
1068        // `redacting_clone`; if they drift, the budget stops meaning anything.
1069        let shapes = [
1070            json!({}),
1071            json!({"data": {"a": 1, "b": "hello"}}),
1072            json!({"data": {"items": [1, "two", {"three": 3}], "nested": {"x": {"y": "z"}}}}),
1073            json!({"data": {"secret": {"deep": [1, 2, 3]}, "keep": "café"}}),
1074        ];
1075        let path_sets: [&[&str]; 4] = [&[], &["data.secret"], &["data.items.1"], &["data.nope"]];
1076
1077        for shape in &shapes {
1078            for paths in path_sets {
1079                let v = dv(shape.clone());
1080                let segs = segments(paths);
1081                let (_, cloned_size) = redacting_clone(&v, &segs);
1082                assert_eq!(
1083                    redacted_size(&v, &segs),
1084                    cloned_size,
1085                    "probe and clone disagree for {shape:?} with {paths:?}"
1086                );
1087            }
1088        }
1089    }
1090
1091    #[test]
1092    fn redaction_applies_to_mapping_contexts_too() {
1093        let mut ctx = json!({"data": {"secret": {"k": "v"}, "keep": 1}});
1094        redact_json_in_place(&mut ctx, &segments(&["data.secret"]));
1095        assert_eq!(ctx, json!({"data": {"secret": null, "keep": 1}}));
1096    }
1097
1098    #[test]
1099    fn json_redaction_shares_the_owned_path_semantics() {
1100        let mut arr = json!({"data": {"items": [1, 2, 3]}});
1101        redact_json_in_place(&mut arr, &segments(&["data.items.99"]));
1102        assert_eq!(arr, json!({"data": {"items": [1, 2, 3]}}));
1103
1104        let mut scalar = json!({"data": {"name": "alice"}});
1105        redact_json_in_place(&mut scalar, &segments(&["data.name.first"]));
1106        assert_eq!(scalar, json!({"data": {"name": "alice"}}));
1107
1108        let mut hash = json!({"data": {"20": "secret"}});
1109        redact_json_in_place(&mut hash, &segments(&["data.#20"]));
1110        assert_eq!(hash, json!({"data": {"20": null}}));
1111    }
1112
1113    #[test]
1114    fn execution_step_loop_counter_defaults_to_none_on_every_constructor() {
1115        assert_eq!(
1116            ExecutionStep::executed("w", "t", &Message::from_value(&json!({}))).loop_counter,
1117            None
1118        );
1119        assert_eq!(ExecutionStep::task_skipped("w", "t").loop_counter, None);
1120        assert_eq!(ExecutionStep::workflow_skipped("w").loop_counter, None);
1121    }
1122
1123    #[test]
1124    fn with_loop_counter_sets_and_clears_the_field() {
1125        let step = ExecutionStep::task_skipped("w", "t").with_loop_counter(Some(3));
1126        assert_eq!(step.loop_counter, Some(3));
1127        // Passing None must clear rather than be a no-op, so the non-looping
1128        // caller can chain unconditionally.
1129        assert_eq!(step.with_loop_counter(None).loop_counter, None);
1130    }
1131
1132    #[test]
1133    fn execution_step_loop_counter_is_absent_from_json_when_none() {
1134        // A non-looping trace must keep the historical wire shape byte for
1135        // byte — dataflow-ui parses these.
1136        let step = ExecutionStep::task_skipped("w", "t");
1137        let json = serde_json::to_value(&step).expect("should serialize");
1138        assert!(json.get("loop_counter").is_none());
1139
1140        let looped = ExecutionStep::task_skipped("w", "t").with_loop_counter(Some(0));
1141        assert_eq!(
1142            serde_json::to_value(&looped).expect("should serialize")["loop_counter"],
1143            json!(0),
1144            "counter 0 must serialize, not be elided as a default"
1145        );
1146    }
1147
1148    #[test]
1149    fn execution_step_without_a_loop_counter_key_deserializes() {
1150        // Trace JSON written before loops existed must still round-trip.
1151        let step: ExecutionStep = serde_json::from_value(json!({
1152            "workflow_id": "w",
1153            "task_id": "t",
1154            "result": "skipped"
1155        }))
1156        .expect("legacy trace JSON should deserialize");
1157        assert_eq!(step.loop_counter, None);
1158        assert_eq!(step.workflow_id, "w");
1159    }
1160
1161    #[test]
1162    fn add_executed_step_records_the_timing_bundle_and_the_loop_counter() {
1163        let mut trace = ExecutionTrace::with_options(TraceOptions::timings_only());
1164        let started_at = Utc::now();
1165        trace.add_executed_step(
1166            "w",
1167            "t",
1168            &Message::from_value(&json!({})),
1169            StepTiming {
1170                started_at,
1171                duration_us: 42,
1172            },
1173            None,
1174            StepStamp {
1175                loop_counter: Some(7),
1176                element_index: Some(2),
1177            },
1178        );
1179
1180        let step = &trace.steps[0];
1181        assert_eq!(step.started_at, Some(started_at));
1182        assert_eq!(step.duration_us, Some(42));
1183        assert_eq!(step.loop_counter, Some(7));
1184        assert_eq!(step.element_index, Some(2));
1185        assert_eq!(step.result, StepResult::Executed);
1186    }
1187
1188    #[test]
1189    fn execution_step_element_index_is_absent_from_json_when_none() {
1190        let plain = ExecutionStep::task_skipped("w", "t");
1191        let json = serde_json::to_value(&plain).expect("should serialize");
1192        assert!(
1193            json.get("element_index").is_none(),
1194            "an ordinary step keeps its wire shape"
1195        );
1196
1197        let fanned = ExecutionStep::task_skipped("w", "t").with_element_index(Some(3));
1198        assert_eq!(
1199            serde_json::to_value(&fanned).expect("should serialize")["element_index"],
1200            json!(3)
1201        );
1202
1203        let back: ExecutionStep = serde_json::from_value(json).expect("should deserialize");
1204        assert_eq!(back.element_index, None, "a step without the key loads");
1205    }
1206}