1use crate::db::DbPool;
2use crate::error::{AppError, AppResult, ErrorCode};
3use crate::telemetry_attrs::RuntimeSpanAttributes;
4use crate::{ExecutionContext, TraceContext};
5use async_trait::async_trait;
6use chrono::{DateTime, Utc};
7use serde::{Deserialize, Serialize};
8use serde_json::{Map, Value, json};
9use std::collections::BTreeSet;
10use std::fmt::Debug;
11use std::future::Future;
12use std::sync::Arc;
13use std::sync::atomic::{AtomicU64, Ordering};
14use std::time::Duration;
15use tokio::sync::mpsc;
16use tokio::task::JoinHandle;
17use tracing::field::{Field, Visit};
18use tracing::instrument::WithSubscriber as _;
19use tracing::span::{Attributes, Id, Record};
20use tracing::subscriber::Interest;
21use tracing::{Dispatch, Metadata};
22use tracing::{Event, Subscriber};
23use tracing_core::span::Current;
24use uuid::Uuid;
25
26pub const EXECUTION_LOG_TARGET: &str = "lenso::execution";
27const EXECUTION_LOG_CHANNEL_CAPACITY: usize = 128;
28const EXECUTION_LOG_DRAIN_TIMEOUT: Duration = Duration::from_millis(100);
29const MAX_EXECUTION_LOG_BODY_BYTES: usize = 4 * 1024;
30const MAX_EXECUTION_LOG_ATTRIBUTES_BYTES: usize = 16 * 1024;
31const MAX_EXECUTION_LOG_SCOPE_ATTRIBUTE_BYTES: usize = 1024;
32const MAX_EXECUTION_LOG_REDACTED_FIELDS: usize = 128;
33const MAX_EXECUTION_LOG_REDACTED_FIELD_BYTES: usize = 4 * 1024;
34const REDACTED_VALUE: &str = "[REDACTED]";
35const REDACTED_FIELDS_TRUNCATED: &str = "[truncated]";
36const SENSITIVE_ATTRIBUTE_TERMS: [&str; 10] = [
37 "authorization",
38 "cookie",
39 "password",
40 "passwd",
41 "secret",
42 "token",
43 "apikey",
44 "accesskey",
45 "credential",
46 "email",
47];
48
49#[derive(Debug, Clone, Copy, PartialEq, Eq, Deserialize, Serialize)]
50#[serde(rename_all = "snake_case")]
51#[doc(hidden)]
52pub enum ExecutionLogSeverity {
53 Trace,
54 Debug,
55 Info,
56 Warn,
57 Error,
58}
59
60impl ExecutionLogSeverity {
61 fn as_str(self) -> &'static str {
62 match self {
63 Self::Trace => "trace",
64 Self::Debug => "debug",
65 Self::Info => "info",
66 Self::Warn => "warn",
67 Self::Error => "error",
68 }
69 }
70}
71
72#[derive(Debug, Clone)]
73#[doc(hidden)]
74pub struct ExecutionLogRecord {
75 correlation_id: String,
76 story_id: String,
77 execution_id: String,
78 execution_type: String,
79 execution_name: String,
80 severity: ExecutionLogSeverity,
81 body: String,
82 attributes: Value,
83 trace: TraceContext,
84 service_name: String,
85 redacted_fields: Vec<String>,
86 occurred_at: DateTime<Utc>,
87}
88
89impl ExecutionLogRecord {
90 pub(crate) fn from_runtime_attrs(
91 attrs: RuntimeSpanAttributes,
92 severity: ExecutionLogSeverity,
93 body: impl Into<String>,
94 ) -> Self {
95 let execution_id = attrs
96 .function_run_id
97 .clone()
98 .or_else(|| attrs.outbox_event_id.clone())
99 .unwrap_or_else(|| attrs.story_id.clone());
100
101 Self {
102 correlation_id: attrs.correlation_id,
103 story_id: attrs.story_id,
104 execution_id,
105 execution_type: attrs.execution_kind,
106 execution_name: attrs.execution_name,
107 severity,
108 body: body.into(),
109 attributes: Value::Object(Map::default()),
110 trace: TraceContext::default(),
111 service_name: "lenso".to_owned(),
112 redacted_fields: Vec::new(),
113 occurred_at: Utc::now(),
114 }
115 }
116
117 pub(crate) fn with_attributes(mut self, attributes: Value) -> Self {
118 self.attributes = attributes;
119 self
120 }
121
122 pub(crate) fn with_trace(mut self, trace: TraceContext) -> Self {
123 self.trace = trace;
124 self
125 }
126}
127
128impl ExecutionLogRecord {
129 #[cfg(test)]
130 fn attributes(&self) -> &Value {
131 &self.attributes
132 }
133
134 #[cfg(test)]
135 fn redacted_fields(&self) -> &[String] {
136 &self.redacted_fields
137 }
138}
139
140#[doc(hidden)]
141pub async fn insert_execution_log_projection(
142 pool: &DbPool,
143 record: ExecutionLogRecord,
144) -> AppResult<String> {
145 let id = next_execution_log_id();
146 sqlx::query(
147 r#"
148 insert into platform.execution_logs (
149 id,
150 correlation_id,
151 story_id,
152 execution_id,
153 execution_type,
154 execution_name,
155 occurred_at,
156 severity,
157 body,
158 attributes,
159 trace_id,
160 span_id,
161 service_name,
162 redacted_fields
163 )
164 values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14)
165 "#,
166 )
167 .bind(&id)
168 .bind(&record.correlation_id)
169 .bind(&record.story_id)
170 .bind(&record.execution_id)
171 .bind(&record.execution_type)
172 .bind(&record.execution_name)
173 .bind(record.occurred_at)
174 .bind(record.severity.as_str())
175 .bind(&record.body)
176 .bind(normalize_attributes(record.attributes))
177 .bind(&record.trace.trace_id)
178 .bind(&record.trace.span_id)
179 .bind(&record.service_name)
180 .bind(&record.redacted_fields)
181 .execute(pool)
182 .await
183 .map_err(map_execution_log_error)?;
184
185 Ok(id)
186}
187
188#[async_trait]
194#[doc(hidden)]
195pub trait ExecutionLogWriter: Debug + Send + Sync {
196 async fn write_execution_log(&self, record: ExecutionLogRecord) -> AppResult<String>;
197}
198
199#[derive(Debug, Clone)]
200#[doc(hidden)]
201pub struct PostgresExecutionLogWriter {
202 pool: DbPool,
203}
204
205impl PostgresExecutionLogWriter {
206 pub fn new(pool: DbPool) -> Self {
207 Self { pool }
208 }
209}
210
211#[async_trait]
212impl ExecutionLogWriter for PostgresExecutionLogWriter {
213 async fn write_execution_log(&self, record: ExecutionLogRecord) -> AppResult<String> {
214 insert_execution_log_projection(&self.pool, record).await
215 }
216}
217
218#[derive(Debug, Clone)]
219#[doc(hidden)]
220pub struct ExecutionLogScope {
221 correlation_id: String,
222 story_id: String,
223 execution_id: String,
224 execution_type: String,
225 execution_name: String,
226 trace: TraceContext,
227 service_name: String,
228 protected_attributes: Map<String, Value>,
229}
230
231impl ExecutionLogScope {
232 pub fn function(
233 context: &ExecutionContext,
234 service_name: impl Into<String>,
235 workload_id: impl Into<String>,
236 ) -> Self {
237 let mut protected_attributes = Map::new();
238 let mut scope_truncated = false;
239 protected_attributes.insert(
240 "lenso.correlation_id".to_owned(),
241 bounded_scope_attribute(&context.correlation_id.0, &mut scope_truncated),
242 );
243 protected_attributes.insert(
244 "lenso.story_id".to_owned(),
245 bounded_scope_attribute(&context.correlation_id.0, &mut scope_truncated),
246 );
247 protected_attributes.insert(
248 "lenso.function_run_id".to_owned(),
249 bounded_scope_attribute(&context.execution_id.0, &mut scope_truncated),
250 );
251 protected_attributes.insert(
252 "lenso.execution.kind".to_owned(),
253 Value::String("function_run".to_owned()),
254 );
255 protected_attributes.insert(
256 "lenso.execution.name".to_owned(),
257 bounded_scope_attribute(&context.function_name, &mut scope_truncated),
258 );
259 protected_attributes.insert(
260 "lenso.execution.attempt".to_owned(),
261 Value::from(context.attempt),
262 );
263 protected_attributes.insert(
264 "lenso.execution.queue".to_owned(),
265 bounded_scope_attribute(&context.queue, &mut scope_truncated),
266 );
267 let workload_id = workload_id.into();
268 protected_attributes.insert(
269 "lenso.workload.id".to_owned(),
270 bounded_scope_attribute(&workload_id, &mut scope_truncated),
271 );
272 if let Some(tenant_id) = context.tenant_id.as_ref() {
273 protected_attributes.insert(
274 "lenso.tenant.id".to_owned(),
275 bounded_scope_attribute(&tenant_id.0, &mut scope_truncated),
276 );
277 }
278 if scope_truncated {
279 protected_attributes.insert("lenso.log.scope_truncated".to_owned(), Value::Bool(true));
280 }
281
282 Self {
283 correlation_id: context.correlation_id.0.clone(),
284 story_id: context.correlation_id.0.clone(),
285 execution_id: context.execution_id.0.clone(),
286 execution_type: "function_run".to_owned(),
287 execution_name: context.function_name.clone(),
288 trace: context.trace.clone(),
289 service_name: service_name.into(),
290 protected_attributes,
291 }
292 }
293
294 fn record(
295 &self,
296 severity: ExecutionLogSeverity,
297 body: String,
298 mut attributes: Map<String, Value>,
299 ) -> ExecutionLogRecord {
300 let mut redactions = RedactionTracker::default();
301 sanitize_attributes(&mut attributes, "", &mut redactions);
302 let body = if body_contains_sensitive_content(&body) {
303 redactions.record("body");
304 REDACTED_VALUE.to_owned()
305 } else {
306 body
307 };
308 let redacted_fields = redactions.finish();
309 let (body, body_truncated) = truncate_utf8(body, MAX_EXECUTION_LOG_BODY_BYTES);
310 let mut protected_attributes = self.protected_attributes.clone();
311 if body_truncated {
312 protected_attributes.insert("lenso.log.body_truncated".to_owned(), Value::Bool(true));
313 }
314 let attributes = bound_attributes(attributes, protected_attributes);
315 ExecutionLogRecord {
316 correlation_id: self.correlation_id.clone(),
317 story_id: self.story_id.clone(),
318 execution_id: self.execution_id.clone(),
319 execution_type: self.execution_type.clone(),
320 execution_name: self.execution_name.clone(),
321 severity,
322 body,
323 attributes: Value::Object(attributes),
324 trace: self.trace.clone(),
325 service_name: self.service_name.clone(),
326 redacted_fields,
327 occurred_at: Utc::now(),
328 }
329 }
330}
331
332#[derive(Debug, Clone, Copy, PartialEq, Eq)]
333#[doc(hidden)]
334pub enum ExecutionLogCaptureStatus {
335 Complete,
336 Partial,
337 Disabled,
338}
339
340#[derive(Debug, Clone, Copy, PartialEq, Eq)]
341#[doc(hidden)]
342pub struct ExecutionLogCaptureReport {
343 pub status: ExecutionLogCaptureStatus,
344 pub observed: u64,
345 pub persisted: u64,
346 pub dropped: u64,
347 pub write_failures: u64,
348}
349
350impl ExecutionLogCaptureReport {
351 fn disabled() -> Self {
352 Self {
353 status: ExecutionLogCaptureStatus::Disabled,
354 observed: 0,
355 persisted: 0,
356 dropped: 0,
357 write_failures: 0,
358 }
359 }
360}
361
362#[derive(Debug, Clone)]
363struct ExecutionLogCaptureContext {
364 scope: Arc<ExecutionLogScope>,
365 sender: mpsc::Sender<ExecutionLogRecord>,
366 observed: Arc<AtomicU64>,
367 dropped: Arc<AtomicU64>,
368}
369
370#[derive(Debug)]
371struct AbortTaskOnDrop<T> {
372 handle: JoinHandle<T>,
373}
374
375impl<T> AbortTaskOnDrop<T> {
376 fn new(handle: JoinHandle<T>) -> Self {
377 Self { handle }
378 }
379}
380
381impl<T> Drop for AbortTaskOnDrop<T> {
382 fn drop(&mut self) {
383 self.handle.abort();
384 }
385}
386
387tokio::task_local! {
388 static EXECUTION_LOG_CAPTURE: ExecutionLogCaptureContext;
389}
390
391#[doc(hidden)]
395pub async fn capture_execution_logs<F>(
396 scope: ExecutionLogScope,
397 writer: Option<Arc<dyn ExecutionLogWriter>>,
398 future: F,
399) -> (F::Output, ExecutionLogCaptureReport)
400where
401 F: Future,
402{
403 let Some(writer) = writer else {
404 let host_dispatch = tracing::dispatcher::get_default(Clone::clone);
405 let capture_dispatch = ExecutionLogCaptureSubscriber::new(host_dispatch);
406 return (
407 future.with_subscriber(capture_dispatch).await,
408 ExecutionLogCaptureReport::disabled(),
409 );
410 };
411 let (sender, mut receiver) = mpsc::channel(EXECUTION_LOG_CHANNEL_CAPACITY);
412 let observed = Arc::new(AtomicU64::new(0));
413 let dropped = Arc::new(AtomicU64::new(0));
414 let persisted = Arc::new(AtomicU64::new(0));
415 let write_failures = Arc::new(AtomicU64::new(0));
416 let capture = ExecutionLogCaptureContext {
417 scope: Arc::new(scope),
418 sender,
419 observed: observed.clone(),
420 dropped: dropped.clone(),
421 };
422 let host_dispatch = tracing::dispatcher::get_default(Clone::clone);
423 let drain_persisted = persisted.clone();
424 let drain_write_failures = write_failures.clone();
425 let drain_host_dispatch = host_dispatch.clone();
426 let drain = async move {
427 while let Some(record) = receiver.recv().await {
428 tracing::dispatcher::with_default(&drain_host_dispatch, || {
429 emit_sanitized_execution_log(&record);
430 });
431 match writer.write_execution_log(record).await {
432 Ok(_) => {
433 drain_persisted.fetch_add(1, Ordering::Relaxed);
434 }
435 Err(error) => {
436 drain_write_failures.fetch_add(1, Ordering::Relaxed);
437 tracing::warn!(
438 error = ?error,
439 "failed to persist structured execution log"
440 );
441 }
442 }
443 }
444 };
445
446 let mut drain = AbortTaskOnDrop::new(tokio::spawn(drain));
447 let capture_dispatch = ExecutionLogCaptureSubscriber::new(host_dispatch);
448 let output = EXECUTION_LOG_CAPTURE
449 .scope(capture, future.with_subscriber(capture_dispatch))
450 .await;
451 let drain_timed_out = tokio::time::timeout(EXECUTION_LOG_DRAIN_TIMEOUT, &mut drain.handle)
452 .await
453 .is_err();
454 if drain_timed_out {
455 drain.handle.abort();
456 let _ = (&mut drain.handle).await;
457 }
458
459 let observed = observed.load(Ordering::Relaxed);
460 let persisted = persisted.load(Ordering::Relaxed);
461 let write_failures = write_failures.load(Ordering::Relaxed);
462 let directly_dropped = dropped.load(Ordering::Relaxed);
463 let abandoned = observed.saturating_sub(
464 directly_dropped
465 .saturating_add(persisted)
466 .saturating_add(write_failures),
467 );
468 let dropped = directly_dropped.saturating_add(abandoned);
469 let status = if dropped == 0 && write_failures == 0 && !drain_timed_out {
470 ExecutionLogCaptureStatus::Complete
471 } else {
472 ExecutionLogCaptureStatus::Partial
473 };
474
475 (
476 output,
477 ExecutionLogCaptureReport {
478 status,
479 observed,
480 persisted,
481 dropped,
482 write_failures,
483 },
484 )
485}
486
487#[derive(Debug, Clone)]
496struct ExecutionLogCaptureSubscriber {
497 inner: Dispatch,
498}
499
500impl ExecutionLogCaptureSubscriber {
501 fn new(inner: Dispatch) -> Self {
502 Self { inner }
503 }
504}
505
506impl Subscriber for ExecutionLogCaptureSubscriber {
507 fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
508 if metadata.target() == EXECUTION_LOG_TARGET {
509 Interest::always()
510 } else {
511 self.inner.register_callsite(metadata)
512 }
513 }
514
515 fn enabled(&self, metadata: &Metadata<'_>) -> bool {
516 metadata.target() == EXECUTION_LOG_TARGET || self.inner.enabled(metadata)
517 }
518
519 fn max_level_hint(&self) -> Option<tracing::metadata::LevelFilter> {
520 None
521 }
522
523 fn new_span(&self, span: &Attributes<'_>) -> Id {
524 self.inner.new_span(span)
525 }
526
527 fn record(&self, span: &Id, values: &Record<'_>) {
528 self.inner.record(span, values);
529 }
530
531 fn record_follows_from(&self, span: &Id, follows: &Id) {
532 self.inner.record_follows_from(span, follows);
533 }
534
535 fn event(&self, event: &Event<'_>) {
536 if event.metadata().target() == EXECUTION_LOG_TARGET {
537 capture_execution_log_event(event);
538 } else {
539 self.inner.event(event);
540 }
541 }
542
543 fn enter(&self, span: &Id) {
544 self.inner.enter(span);
545 }
546
547 fn exit(&self, span: &Id) {
548 self.inner.exit(span);
549 }
550
551 fn clone_span(&self, id: &Id) -> Id {
552 self.inner.clone_span(id)
553 }
554
555 fn try_close(&self, id: Id) -> bool {
556 self.inner.try_close(id)
557 }
558
559 fn current_span(&self) -> Current {
560 self.inner.current_span()
561 }
562}
563
564fn capture_execution_log_event(event: &Event<'_>) {
565 let mut visitor = ExecutionLogEventVisitor::default();
566 event.record(&mut visitor);
567 let body = visitor
568 .body
569 .unwrap_or_else(|| event.metadata().name().to_owned());
570 let severity = severity_from_level(*event.metadata().level());
571 let _ = EXECUTION_LOG_CAPTURE.try_with(|capture| {
572 capture.observed.fetch_add(1, Ordering::Relaxed);
573 let record = capture.scope.record(severity, body, visitor.attributes);
574 if capture.sender.try_send(record).is_err() {
575 capture.dropped.fetch_add(1, Ordering::Relaxed);
576 }
577 });
578}
579
580#[derive(Debug, Default)]
581struct ExecutionLogEventVisitor {
582 body: Option<String>,
583 attributes: Map<String, Value>,
584}
585
586impl ExecutionLogEventVisitor {
587 fn record_value(&mut self, field: &Field, value: Value) {
588 let name = field.name();
589 if name == "message" {
590 self.body = value
591 .as_str()
592 .map(ToOwned::to_owned)
593 .or_else(|| Some(value.to_string()));
594 return;
595 }
596 if is_reserved_attribute(name) {
597 return;
598 }
599 if name == "attributes" {
600 if let Some(raw) = value.as_str()
601 && raw.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES
602 && let Ok(Value::Object(attributes)) = serde_json::from_str::<Value>(raw)
603 {
604 self.attributes.extend(attributes);
605 return;
606 }
607 self.attributes.insert(
608 "attributes".to_owned(),
609 Value::String(REDACTED_VALUE.to_owned()),
610 );
611 return;
612 }
613 self.attributes.insert(name.to_owned(), value);
614 }
615}
616
617impl Visit for ExecutionLogEventVisitor {
618 fn record_f64(&mut self, field: &Field, value: f64) {
619 self.record_value(field, Value::from(value));
620 }
621
622 fn record_i64(&mut self, field: &Field, value: i64) {
623 self.record_value(field, Value::from(value));
624 }
625
626 fn record_u64(&mut self, field: &Field, value: u64) {
627 self.record_value(field, Value::from(value));
628 }
629
630 fn record_i128(&mut self, field: &Field, value: i128) {
631 self.record_value(field, Value::String(value.to_string()));
632 }
633
634 fn record_u128(&mut self, field: &Field, value: u128) {
635 self.record_value(field, Value::String(value.to_string()));
636 }
637
638 fn record_bool(&mut self, field: &Field, value: bool) {
639 self.record_value(field, Value::Bool(value));
640 }
641
642 fn record_str(&mut self, field: &Field, value: &str) {
643 self.record_value(field, Value::String(value.to_owned()));
644 }
645
646 fn record_bytes(&mut self, field: &Field, value: &[u8]) {
647 self.record_value(field, Value::String(format!("{value:?}")));
648 }
649
650 fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
651 self.record_value(field, Value::String(format!("{value:?}")));
652 }
653}
654
655fn severity_from_level(level: tracing::Level) -> ExecutionLogSeverity {
656 match level {
657 tracing::Level::TRACE => ExecutionLogSeverity::Trace,
658 tracing::Level::DEBUG => ExecutionLogSeverity::Debug,
659 tracing::Level::INFO => ExecutionLogSeverity::Info,
660 tracing::Level::WARN => ExecutionLogSeverity::Warn,
661 tracing::Level::ERROR => ExecutionLogSeverity::Error,
662 }
663}
664
665fn emit_sanitized_execution_log(record: &ExecutionLogRecord) {
666 let attributes = record.attributes.to_string();
667 match record.severity {
668 ExecutionLogSeverity::Trace => tracing::trace!(
669 target: "lenso::execution::sanitized",
670 {
671 lenso.correlation_id = %(&record.correlation_id),
672 lenso.story_id = %(&record.story_id),
673 lenso.execution.id = %(&record.execution_id),
674 lenso.execution.kind = %(&record.execution_type),
675 lenso.execution.name = %(&record.execution_name),
676 attributes = %attributes,
677 },
678 "{}", record.body
679 ),
680 ExecutionLogSeverity::Debug => tracing::debug!(
681 target: "lenso::execution::sanitized",
682 {
683 lenso.correlation_id = %(&record.correlation_id),
684 lenso.story_id = %(&record.story_id),
685 lenso.execution.id = %(&record.execution_id),
686 lenso.execution.kind = %(&record.execution_type),
687 lenso.execution.name = %(&record.execution_name),
688 attributes = %attributes,
689 },
690 "{}", record.body
691 ),
692 ExecutionLogSeverity::Info => tracing::info!(
693 target: "lenso::execution::sanitized",
694 {
695 lenso.correlation_id = %(&record.correlation_id),
696 lenso.story_id = %(&record.story_id),
697 lenso.execution.id = %(&record.execution_id),
698 lenso.execution.kind = %(&record.execution_type),
699 lenso.execution.name = %(&record.execution_name),
700 attributes = %attributes,
701 },
702 "{}", record.body
703 ),
704 ExecutionLogSeverity::Warn => tracing::warn!(
705 target: "lenso::execution::sanitized",
706 {
707 lenso.correlation_id = %(&record.correlation_id),
708 lenso.story_id = %(&record.story_id),
709 lenso.execution.id = %(&record.execution_id),
710 lenso.execution.kind = %(&record.execution_type),
711 lenso.execution.name = %(&record.execution_name),
712 attributes = %attributes,
713 },
714 "{}", record.body
715 ),
716 ExecutionLogSeverity::Error => tracing::error!(
717 target: "lenso::execution::sanitized",
718 {
719 lenso.correlation_id = %(&record.correlation_id),
720 lenso.story_id = %(&record.story_id),
721 lenso.execution.id = %(&record.execution_id),
722 lenso.execution.kind = %(&record.execution_type),
723 lenso.execution.name = %(&record.execution_name),
724 attributes = %attributes,
725 },
726 "{}", record.body
727 ),
728 }
729}
730
731#[derive(Debug, Default)]
732struct RedactionTracker {
733 fields: BTreeSet<String>,
734 bytes: usize,
735 truncated: bool,
736}
737
738impl RedactionTracker {
739 fn record(&mut self, path: &str) {
740 if self.fields.contains(path) {
741 return;
742 }
743 if self.fields.len() >= MAX_EXECUTION_LOG_REDACTED_FIELDS
744 || self.bytes.saturating_add(path.len()) > MAX_EXECUTION_LOG_REDACTED_FIELD_BYTES
745 {
746 self.truncated = true;
747 return;
748 }
749 self.bytes += path.len();
750 self.fields.insert(path.to_owned());
751 }
752
753 fn finish(self) -> Vec<String> {
754 let mut fields = self.fields.into_iter().collect::<Vec<_>>();
755 if self.truncated {
756 fields.push(REDACTED_FIELDS_TRUNCATED.to_owned());
757 }
758 fields
759 }
760}
761
762fn sanitize_attributes(
763 attributes: &mut Map<String, Value>,
764 parent: &str,
765 redactions: &mut RedactionTracker,
766) {
767 attributes.retain(|key, value| {
768 let path = if parent.is_empty() {
769 key.clone()
770 } else {
771 format!("{parent}.{key}")
772 };
773 if is_reserved_attribute(key) {
774 return false;
775 }
776 if is_sensitive_attribute(key) {
777 *value = Value::String(REDACTED_VALUE.to_owned());
778 redactions.record(&path);
779 return true;
780 }
781 sanitize_value(value, &path, redactions);
782 true
783 });
784}
785
786fn sanitize_value(value: &mut Value, path: &str, redactions: &mut RedactionTracker) {
787 match value {
788 Value::Object(attributes) => sanitize_attributes(attributes, path, redactions),
789 Value::Array(values) => {
790 for (index, value) in values.iter_mut().enumerate() {
791 sanitize_value(value, &format!("{path}[{index}]"), redactions);
792 }
793 }
794 _ => {}
795 }
796}
797
798fn is_reserved_attribute(name: &str) -> bool {
799 name.to_ascii_lowercase().starts_with("lenso.")
800}
801
802fn is_sensitive_attribute(name: &str) -> bool {
803 let normalized = normalize_sensitive_identifier(name);
804 SENSITIVE_ATTRIBUTE_TERMS
805 .iter()
806 .any(|sensitive| normalized.contains(sensitive))
807}
808
809fn normalize_sensitive_identifier(value: &str) -> String {
810 value
811 .chars()
812 .filter(char::is_ascii_alphanumeric)
813 .flat_map(char::to_lowercase)
814 .collect()
815}
816
817fn body_contains_sensitive_content(body: &str) -> bool {
818 if body.split_whitespace().any(|token| {
819 token
820 .trim_matches(|character: char| !character.is_ascii_alphabetic())
821 .eq_ignore_ascii_case("bearer")
822 }) {
823 return true;
824 }
825
826 let normalized_assignments = body
827 .chars()
828 .filter(|character| character.is_ascii_alphanumeric() || matches!(character, ':' | '='))
829 .flat_map(char::to_lowercase)
830 .collect::<String>();
831 let has_sensitive_assignment = SENSITIVE_ATTRIBUTE_TERMS.iter().any(|sensitive| {
832 normalized_assignments
833 .match_indices(sensitive)
834 .any(|(offset, _)| {
835 normalized_assignments[offset + sensitive.len()..].starts_with([':', '='])
836 })
837 });
838 has_sensitive_assignment || body.split_whitespace().any(looks_like_email)
839}
840
841fn looks_like_email(token: &str) -> bool {
842 let token = token.trim_matches(|character: char| {
843 !character.is_ascii_alphanumeric() && !matches!(character, '@' | '.' | '_' | '-' | '+')
844 });
845 let Some((local, domain)) = token.split_once('@') else {
846 return false;
847 };
848 !local.is_empty()
849 && domain
850 .split_once('.')
851 .is_some_and(|(name, suffix)| !name.is_empty() && !suffix.is_empty())
852}
853
854fn truncate_utf8(mut value: String, max_bytes: usize) -> (String, bool) {
855 if value.len() <= max_bytes {
856 return (value, false);
857 }
858 let mut end = max_bytes;
859 while !value.is_char_boundary(end) {
860 end -= 1;
861 }
862 value.truncate(end);
863 (value, true)
864}
865
866fn bounded_scope_attribute(value: &str, truncated: &mut bool) -> Value {
867 let (value, did_truncate) =
868 truncate_json_string(value, MAX_EXECUTION_LOG_SCOPE_ATTRIBUTE_BYTES);
869 *truncated |= did_truncate;
870 Value::String(value)
871}
872
873fn truncate_json_string(value: &str, max_encoded_bytes: usize) -> (String, bool) {
874 let mut bounded = String::new();
875 let mut encoded_bytes = 2_usize;
876 for character in value.chars() {
877 let character_bytes = match character {
878 '"' | '\\' | '\u{08}' | '\u{0C}' | '\n' | '\r' | '\t' => 2,
879 '\u{00}'..='\u{1F}' => 6,
880 _ => character.len_utf8(),
881 };
882 if encoded_bytes.saturating_add(character_bytes) > max_encoded_bytes {
883 return (bounded, true);
884 }
885 bounded.push(character);
886 encoded_bytes += character_bytes;
887 }
888 (bounded, false)
889}
890
891fn bound_attributes(
892 attributes: Map<String, Value>,
893 protected_attributes: Map<String, Value>,
894) -> Map<String, Value> {
895 let protected_len = serialized_json_object_len(&protected_attributes).unwrap_or(usize::MAX);
896 let caller_entries_len = attributes.iter().try_fold(0_usize, |total, (key, value)| {
897 serialized_json_entry_len(key, value).and_then(|entry| total.checked_add(entry))
898 });
899 let caller_commas = attributes.len().saturating_sub(1);
900 let combined_len = protected_len
901 .checked_add(caller_entries_len.unwrap_or(usize::MAX))
902 .and_then(|total| total.checked_add(caller_commas))
903 .and_then(|total| {
904 total.checked_add(usize::from(
905 !protected_attributes.is_empty() && !attributes.is_empty(),
906 ))
907 });
908 if combined_len.is_some_and(|len| len <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES) {
909 let mut combined = attributes;
910 combined.extend(protected_attributes);
911 return combined;
912 }
913
914 let mut bounded = protected_attributes;
915 bounded.insert(
916 "lenso.log.attributes_truncated".to_owned(),
917 Value::Bool(true),
918 );
919 let mut serialized_len = serialized_json_object_len(&bounded).unwrap_or(usize::MAX);
920 for (key, value) in attributes {
921 let added = serialized_json_entry_len(&key, &value)
922 .and_then(|entry| entry.checked_add(usize::from(!bounded.is_empty())));
923 if added
924 .and_then(|entry| serialized_len.checked_add(entry))
925 .is_some_and(|candidate| candidate <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES)
926 {
927 serialized_len += added.expect("checked attribute entry length");
928 bounded.insert(key, value);
929 }
930 }
931 debug_assert!(
932 serde_json::to_vec(&bounded)
933 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES),
934 "bounded execution log attributes must stay within the storage budget"
935 );
936 bounded
937}
938
939fn serialized_json_object_len(attributes: &Map<String, Value>) -> Option<usize> {
940 attributes
941 .iter()
942 .try_fold(2_usize, |total, (key, value)| {
943 serialized_json_entry_len(key, value).and_then(|entry| total.checked_add(entry))
944 })
945 .and_then(|total| total.checked_add(attributes.len().saturating_sub(1)))
946}
947
948fn serialized_json_entry_len(key: &str, value: &Value) -> Option<usize> {
949 serde_json::to_vec(key)
950 .ok()?
951 .len()
952 .checked_add(1)?
953 .checked_add(serde_json::to_vec(value).ok()?.len())
954}
955
956fn normalize_attributes(attributes: Value) -> Value {
957 match attributes {
958 Value::Object(_) => attributes,
959 other => json!({ "value": other }),
960 }
961}
962
963fn next_execution_log_id() -> String {
964 format!("elog_{}", Uuid::now_v7())
965}
966
967fn map_execution_log_error(source: sqlx::Error) -> AppError {
968 let unavailable = matches!(
969 &source,
970 sqlx::Error::Io(_)
971 | sqlx::Error::Tls(_)
972 | sqlx::Error::PoolTimedOut
973 | sqlx::Error::PoolClosed
974 | sqlx::Error::WorkerCrashed
975 ) || matches!(
976 &source,
977 sqlx::Error::Database(error)
978 if error.code().is_some_and(|code| {
979 code.starts_with("08")
980 || code.starts_with("53")
981 || matches!(code.as_ref(), "57P01" | "57P02" | "57P03")
982 })
983 );
984 let error = AppError::new(
985 if unavailable {
986 ErrorCode::ExternalDependency
987 } else {
988 ErrorCode::Internal
989 },
990 "Execution log operation failed",
991 )
992 .with_source(source);
993 if unavailable {
994 error.retryable()
995 } else {
996 error
997 }
998}
999
1000#[derive(Debug, Clone)]
1001pub struct ExecutionLogRow {
1002 pub id: String,
1003 pub correlation_id: String,
1004 pub story_id: String,
1005 pub execution_id: String,
1006 pub execution_type: String,
1007 pub execution_name: String,
1008 pub occurred_at: DateTime<Utc>,
1009 pub severity: String,
1010 pub body: String,
1011 pub attributes: Value,
1012 pub trace_id: Option<String>,
1013 pub span_id: Option<String>,
1014 pub service_name: String,
1015 pub redacted_fields: Vec<String>,
1016}
1017
1018#[derive(Debug, Clone, Default, PartialEq, Eq)]
1019pub struct ExecutionLogQuery {
1020 pub execution_id: String,
1021 pub occurred_before: Option<DateTime<Utc>>,
1022 pub limit: i64,
1023}
1024
1025#[async_trait]
1026pub trait ExecutionLogProvider: Debug + Send + Sync {
1027 async fn query_execution_logs(
1028 &self,
1029 query: ExecutionLogQuery,
1030 ) -> AppResult<Vec<ExecutionLogRow>>;
1031}
1032
1033#[derive(Debug, Clone)]
1034pub struct PostgresExecutionLogProvider {
1035 pool: DbPool,
1036}
1037
1038impl PostgresExecutionLogProvider {
1039 pub fn new(pool: DbPool) -> Self {
1040 Self { pool }
1041 }
1042}
1043
1044#[async_trait]
1045impl ExecutionLogProvider for PostgresExecutionLogProvider {
1046 async fn query_execution_logs(
1047 &self,
1048 query: ExecutionLogQuery,
1049 ) -> AppResult<Vec<ExecutionLogRow>> {
1050 let mut rows = sqlx::query_as::<_, ExecutionLogTuple>(
1051 r#"
1052 select *
1053 from (
1054 select
1055 concat('elog_outbox_enqueued_', id) as id,
1056 correlation_id,
1057 correlation_id as story_id,
1058 id as execution_id,
1059 'outbox_event'::text as execution_type,
1060 event_name as execution_name,
1061 created_at as occurred_at,
1062 'info'::text as severity,
1063 'Outbox event enqueued'::text as body,
1064 jsonb_build_object(
1065 'event_name', event_name,
1066 'event_version', event_version,
1067 'aggregate_type', aggregate_type,
1068 'aggregate_id', aggregate_id,
1069 'source_module', source_module
1070 ) as attributes,
1071 headers #>> '{trace,trace_id}' as trace_id,
1072 headers #>> '{trace,span_id}' as span_id,
1073 source_module as service_name,
1074 array[]::text[] as redacted_fields
1075 from platform.outbox
1076 where id = $1
1077
1078 union all
1079
1080 select
1081 id,
1082 correlation_id,
1083 story_id,
1084 execution_id,
1085 execution_type,
1086 execution_name,
1087 occurred_at,
1088 severity,
1089 body,
1090 attributes,
1091 trace_id,
1092 span_id,
1093 service_name,
1094 redacted_fields
1095 from platform.execution_logs
1096 where execution_id = $1
1097 ) execution_log_rows
1098 where ($2::timestamptz is null or occurred_at < $2)
1099 order by occurred_at desc, id desc
1100 limit $3
1101 "#,
1102 )
1103 .bind(query.execution_id)
1104 .bind(query.occurred_before)
1105 .bind(query.limit)
1106 .fetch_all(&self.pool)
1107 .await
1108 .map_err(map_execution_log_error)?
1109 .into_iter()
1110 .map(Into::into)
1111 .collect::<Vec<_>>();
1112
1113 rows.reverse();
1114 Ok(rows)
1115 }
1116}
1117
1118type ExecutionLogTuple = (
1119 String,
1120 String,
1121 String,
1122 String,
1123 String,
1124 String,
1125 DateTime<Utc>,
1126 String,
1127 String,
1128 Value,
1129 Option<String>,
1130 Option<String>,
1131 String,
1132 Vec<String>,
1133);
1134
1135impl From<ExecutionLogTuple> for ExecutionLogRow {
1136 fn from(row: ExecutionLogTuple) -> Self {
1137 let (
1138 id,
1139 correlation_id,
1140 story_id,
1141 execution_id,
1142 execution_type,
1143 execution_name,
1144 occurred_at,
1145 severity,
1146 body,
1147 attributes,
1148 trace_id,
1149 span_id,
1150 service_name,
1151 redacted_fields,
1152 ) = row;
1153
1154 Self {
1155 id,
1156 correlation_id,
1157 story_id,
1158 execution_id,
1159 execution_type,
1160 execution_name,
1161 occurred_at,
1162 severity,
1163 body,
1164 attributes,
1165 trace_id,
1166 span_id,
1167 service_name,
1168 redacted_fields,
1169 }
1170 }
1171}
1172
1173#[cfg(test)]
1174mod tests {
1175 use super::*;
1176 use crate::{
1177 ActorContext, CorrelationId, ExecutionContext, ExecutionId, TenantId, TraceContext,
1178 };
1179 use std::sync::Mutex;
1180 use tracing_subscriber::layer::{Context, SubscriberExt as _};
1181
1182 #[test]
1183 fn execution_log_store_availability_errors_remain_typed_and_retryable() {
1184 let error = map_execution_log_error(sqlx::Error::PoolClosed);
1185
1186 assert_eq!(error.code, ErrorCode::ExternalDependency);
1187 assert!(error.retryable);
1188 }
1189
1190 #[test]
1191 fn execution_log_store_corruption_errors_fail_closed() {
1192 let error = map_execution_log_error(sqlx::Error::Protocol(
1193 "invalid execution log row".to_owned(),
1194 ));
1195
1196 assert_eq!(error.code, ErrorCode::Internal);
1197 assert!(!error.retryable);
1198 }
1199
1200 #[derive(Debug, Clone)]
1201 struct RecordingLayer {
1202 events: Arc<Mutex<Vec<ObservedEvent>>>,
1203 }
1204
1205 #[derive(Debug, Clone)]
1206 struct ObservedEvent {
1207 target: String,
1208 fields: String,
1209 }
1210
1211 #[derive(Debug, Default)]
1212 struct ObservedEventVisitor {
1213 fields: Vec<String>,
1214 }
1215
1216 impl Visit for ObservedEventVisitor {
1217 fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
1218 self.fields.push(format!("{}={value:?}", field.name()));
1219 }
1220 }
1221
1222 impl<S> tracing_subscriber::Layer<S> for RecordingLayer
1223 where
1224 S: Subscriber,
1225 {
1226 fn on_event(&self, event: &Event<'_>, _context: Context<'_, S>) {
1227 let mut visitor = ObservedEventVisitor::default();
1228 event.record(&mut visitor);
1229 self.events
1230 .lock()
1231 .expect("observed events lock should not be poisoned")
1232 .push(ObservedEvent {
1233 target: event.metadata().target().to_owned(),
1234 fields: visitor.fields.join(" "),
1235 });
1236 }
1237 }
1238
1239 #[derive(Debug, Default)]
1240 struct MemoryExecutionLogWriter {
1241 records: Mutex<Vec<ExecutionLogRecord>>,
1242 }
1243
1244 #[async_trait]
1245 impl ExecutionLogWriter for MemoryExecutionLogWriter {
1246 async fn write_execution_log(&self, record: ExecutionLogRecord) -> AppResult<String> {
1247 self.records
1248 .lock()
1249 .expect("execution log records lock should not be poisoned")
1250 .push(record);
1251 Ok("elog_test".to_owned())
1252 }
1253 }
1254
1255 #[derive(Debug)]
1256 struct StalledExecutionLogWriter;
1257
1258 #[async_trait]
1259 impl ExecutionLogWriter for StalledExecutionLogWriter {
1260 async fn write_execution_log(&self, _record: ExecutionLogRecord) -> AppResult<String> {
1261 tokio::time::sleep(Duration::from_secs(60)).await;
1262 Ok("elog_unreachable".to_owned())
1263 }
1264 }
1265
1266 #[derive(Debug)]
1267 struct CancellationAwareExecutionLogWriter {
1268 started: Arc<tokio::sync::Notify>,
1269 cancelled: Arc<tokio::sync::Notify>,
1270 }
1271
1272 #[derive(Debug)]
1273 struct NotifyOnDrop(Arc<tokio::sync::Notify>);
1274
1275 impl Drop for NotifyOnDrop {
1276 fn drop(&mut self) {
1277 self.0.notify_one();
1278 }
1279 }
1280
1281 #[async_trait]
1282 impl ExecutionLogWriter for CancellationAwareExecutionLogWriter {
1283 async fn write_execution_log(&self, _record: ExecutionLogRecord) -> AppResult<String> {
1284 let _notify_on_drop = NotifyOnDrop(self.cancelled.clone());
1285 self.started.notify_one();
1286 std::future::pending::<()>().await;
1287 unreachable!("cancellation-aware writer should be cancelled")
1288 }
1289 }
1290
1291 fn scope() -> ExecutionLogScope {
1292 scope_with_identity("fnrun_real", "corr_real")
1293 }
1294
1295 fn scope_with_identity(execution_id: &str, correlation_id: &str) -> ExecutionLogScope {
1296 ExecutionLogScope::function(
1297 &ExecutionContext {
1298 execution_id: ExecutionId(execution_id.to_owned()),
1299 function_name: "inventory.reserve.v1".to_owned(),
1300 attempt: 2,
1301 queue: "inventory".to_owned(),
1302 correlation_id: CorrelationId::new(correlation_id),
1303 causation_id: Some("httpreq_real".to_owned()),
1304 actor: ActorContext::System,
1305 tenant_id: Some(TenantId("tenant_real".to_owned())),
1306 trace: TraceContext {
1307 trace_id: Some("trace_real".to_owned()),
1308 span_id: Some("span_real".to_owned()),
1309 baggage: Vec::new(),
1310 },
1311 deadline: None,
1312 },
1313 "inventory-service",
1314 "worker-a",
1315 )
1316 }
1317
1318 #[test]
1319 fn recursively_redacts_sensitive_values_and_drops_caller_runtime_fields() {
1320 let record = scope().record(
1321 ExecutionLogSeverity::Info,
1322 "checked reservation".to_owned(),
1323 serde_json::from_value::<Map<String, Value>>(json!({
1324 "authorization": "Bearer secret",
1325 "customerEmail": "person@example.test",
1326 "nested": {
1327 "access_key_id": "access-secret",
1328 "safe": "kept"
1329 },
1330 "lenso.execution.id": "fnrun_forged"
1331 }))
1332 .expect("attributes should decode"),
1333 );
1334
1335 assert!(record.attributes().get("lenso.execution.id").is_none());
1336 assert_eq!(record.attributes()["authorization"], REDACTED_VALUE);
1337 assert_eq!(record.attributes()["customerEmail"], REDACTED_VALUE);
1338 assert_eq!(
1339 record.attributes()["nested"]["access_key_id"],
1340 REDACTED_VALUE
1341 );
1342 assert_eq!(record.attributes()["nested"]["safe"], "kept");
1343 assert_eq!(record.attributes()["lenso.function_run_id"], "fnrun_real");
1344 assert_eq!(record.attributes()["lenso.story_id"], "corr_real");
1345 assert!(
1346 record
1347 .redacted_fields()
1348 .iter()
1349 .any(|field| field == "nested.access_key_id")
1350 );
1351 }
1352
1353 #[test]
1354 fn redacts_body_credentials_across_identifier_styles_and_whitespace() {
1355 for body in [
1356 "accessKey=secret",
1357 "access-key = secret",
1358 "api_key: secret",
1359 "Authorization: Bearer secret",
1360 "Bearer\nsecret",
1361 ] {
1362 let record = scope().record(ExecutionLogSeverity::Info, body.to_owned(), Map::new());
1363
1364 assert_eq!(record.body, REDACTED_VALUE, "body must be redacted: {body}");
1365 assert!(record.redacted_fields().iter().any(|field| field == "body"));
1366 }
1367 }
1368
1369 #[test]
1370 fn high_cardinality_redaction_metadata_and_attributes_remain_bounded() {
1371 let attributes = (0..2_000)
1372 .map(|index| {
1373 (
1374 format!("password_{index}"),
1375 Value::String("secret".to_owned()),
1376 )
1377 })
1378 .collect::<Map<_, _>>();
1379 let record = scope().record(
1380 ExecutionLogSeverity::Info,
1381 "bounded redactions".to_owned(),
1382 attributes,
1383 );
1384
1385 assert!(record.redacted_fields().len() <= MAX_EXECUTION_LOG_REDACTED_FIELDS + 1);
1386 assert!(
1387 record
1388 .redacted_fields()
1389 .iter()
1390 .any(|field| field == REDACTED_FIELDS_TRUNCATED)
1391 );
1392 assert!(
1393 serde_json::to_vec(record.attributes())
1394 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES)
1395 );
1396 }
1397
1398 #[test]
1399 fn caller_attribute_limit_never_drops_runtime_scope() {
1400 let record = scope().record(
1401 ExecutionLogSeverity::Info,
1402 "bounded".to_owned(),
1403 Map::from_iter([
1404 ("huge".to_owned(), Value::String("x".repeat(32 * 1024))),
1405 (
1406 "lenso.function_run_id".to_owned(),
1407 Value::String("fnrun_forged".to_owned()),
1408 ),
1409 ]),
1410 );
1411
1412 assert_eq!(record.attributes()["lenso.function_run_id"], "fnrun_real");
1413 assert_eq!(record.attributes()["lenso.story_id"], "corr_real");
1414 assert_eq!(
1415 record.attributes()["lenso.execution.name"],
1416 "inventory.reserve.v1"
1417 );
1418 assert_eq!(record.attributes()["lenso.log.attributes_truncated"], true);
1419 assert!(
1420 serde_json::to_vec(record.attributes())
1421 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES)
1422 );
1423 }
1424
1425 #[test]
1426 fn oversized_runtime_scope_is_bounded_without_changing_canonical_identity() {
1427 let oversized_id = format!("fnrun_{}", "x".repeat(32 * 1024));
1428 let scope = scope_with_identity(&oversized_id, "corr_real");
1429 let record = scope.record(
1430 ExecutionLogSeverity::Info,
1431 "bounded scope".to_owned(),
1432 Map::new(),
1433 );
1434
1435 assert_eq!(record.execution_id, oversized_id);
1436 assert_eq!(record.attributes()["lenso.log.scope_truncated"], true);
1437 assert!(
1438 serde_json::to_vec(record.attributes())
1439 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES)
1440 );
1441 }
1442
1443 #[test]
1444 fn escaped_runtime_scope_is_bounded_by_serialized_json_bytes() {
1445 let escaped = "\u{0001}".repeat(32 * 1024);
1446 let execution_id = format!("fnrun_{escaped}");
1447 let scope = ExecutionLogScope::function(
1448 &ExecutionContext {
1449 execution_id: ExecutionId(execution_id.clone()),
1450 function_name: escaped.clone(),
1451 attempt: 1,
1452 queue: escaped.clone(),
1453 correlation_id: CorrelationId::new(escaped.clone()),
1454 causation_id: None,
1455 actor: ActorContext::System,
1456 tenant_id: Some(TenantId(escaped.clone())),
1457 trace: TraceContext::default(),
1458 deadline: None,
1459 },
1460 "inventory-service",
1461 escaped,
1462 );
1463 let record = scope.record(
1464 ExecutionLogSeverity::Info,
1465 "bounded escaped scope".to_owned(),
1466 Map::new(),
1467 );
1468
1469 assert_eq!(record.execution_id, execution_id);
1470 assert_eq!(record.attributes()["lenso.log.scope_truncated"], true);
1471 assert!(
1472 serde_json::to_vec(record.attributes())
1473 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_ATTRIBUTES_BYTES)
1474 );
1475 for key in [
1476 "lenso.correlation_id",
1477 "lenso.story_id",
1478 "lenso.function_run_id",
1479 "lenso.execution.name",
1480 "lenso.execution.queue",
1481 "lenso.workload.id",
1482 "lenso.tenant.id",
1483 ] {
1484 assert!(
1485 serde_json::to_vec(&record.attributes()[key])
1486 .is_ok_and(|bytes| bytes.len() <= MAX_EXECUTION_LOG_SCOPE_ATTRIBUTE_BYTES),
1487 "{key} must fit the serialized scope-attribute budget"
1488 );
1489 }
1490 }
1491
1492 #[tokio::test]
1493 async fn execution_log_capture_withholds_raw_events_and_forwards_sanitized_events_to_host() {
1494 let observed_events = Arc::new(Mutex::new(Vec::new()));
1495 let subscriber = tracing_subscriber::registry().with(RecordingLayer {
1496 events: observed_events.clone(),
1497 });
1498 let writer = Arc::new(MemoryExecutionLogWriter::default());
1499
1500 let (output, report) = async {
1501 capture_execution_logs(scope(), Some(writer.clone()), async {
1502 let span = tracing::info_span!(target: "inventory", "handler_span");
1503 let span_id = span.id().expect("host subscriber should create a span id");
1504 let _entered = span.enter();
1505 assert_eq!(tracing::Span::current().id(), Some(span_id));
1506 tracing::info!(target: "inventory", "ordinary host event");
1507 tracing::info!(
1508 target: EXECUTION_LOG_TARGET,
1509 attributes = %json!({
1510 "nested": { "password": "raw-attribute-secret" },
1511 "lenso.execution.id": "fnrun_forged"
1512 }),
1513 "Authorization: Bearer raw-body-secret"
1514 );
1515 42
1516 })
1517 .await
1518 }
1519 .with_subscriber(subscriber)
1520 .await;
1521
1522 assert_eq!(output, 42);
1523 assert_eq!(report.status, ExecutionLogCaptureStatus::Complete);
1524 assert_eq!(report.observed, 1);
1525 assert_eq!(report.persisted, 1);
1526
1527 let records = writer
1528 .records
1529 .lock()
1530 .expect("execution log records lock should not be poisoned");
1531 assert_eq!(records.len(), 1);
1532 assert_eq!(records[0].execution_id, "fnrun_real");
1533 assert_eq!(records[0].body, REDACTED_VALUE);
1534 assert_eq!(records[0].attributes["nested"]["password"], REDACTED_VALUE);
1535 assert!(
1536 records[0]
1537 .redacted_fields
1538 .iter()
1539 .any(|field| field == "body")
1540 );
1541 drop(records);
1542
1543 let observed_events = observed_events
1544 .lock()
1545 .expect("observed events lock should not be poisoned");
1546 assert_eq!(
1547 observed_events
1548 .iter()
1549 .filter(|event| event.target == "inventory")
1550 .count(),
1551 1
1552 );
1553 assert_eq!(
1554 observed_events
1555 .iter()
1556 .filter(|event| event.target == EXECUTION_LOG_TARGET)
1557 .count(),
1558 0
1559 );
1560 assert_eq!(
1561 observed_events
1562 .iter()
1563 .filter(|event| event.target == "lenso::execution::sanitized")
1564 .count(),
1565 1
1566 );
1567 assert!(observed_events.iter().all(|event| {
1568 !event.fields.contains("raw-body-secret")
1569 && !event.fields.contains("raw-attribute-secret")
1570 }));
1571 }
1572
1573 #[tokio::test]
1574 async fn unsupported_attribute_payloads_are_redacted_before_capture_or_forwarding() {
1575 let observed_events = Arc::new(Mutex::new(Vec::new()));
1576 let subscriber = tracing_subscriber::registry().with(RecordingLayer {
1577 events: observed_events.clone(),
1578 });
1579 let writer = Arc::new(MemoryExecutionLogWriter::default());
1580
1581 let ((), report) = async {
1582 capture_execution_logs(scope(), Some(writer.clone()), async {
1583 tracing::info!(
1584 target: EXECUTION_LOG_TARGET,
1585 attributes = ?json!({ "password": "debug-secret" }),
1586 "debug attributes"
1587 );
1588 tracing::info!(
1589 target: EXECUTION_LOG_TARGET,
1590 attributes = "{\"password\":\"malformed-secret\"",
1591 "malformed attributes"
1592 );
1593 })
1594 .await
1595 }
1596 .with_subscriber(subscriber)
1597 .await;
1598
1599 assert_eq!(report.status, ExecutionLogCaptureStatus::Complete);
1600 assert_eq!(report.persisted, 2);
1601 let records = writer
1602 .records
1603 .lock()
1604 .expect("execution log records lock should not be poisoned");
1605 assert_eq!(records.len(), 2);
1606 assert!(
1607 records
1608 .iter()
1609 .all(|record| record.attributes["attributes"] == REDACTED_VALUE)
1610 );
1611 drop(records);
1612 let observed_events = observed_events
1613 .lock()
1614 .expect("observed events lock should not be poisoned");
1615 assert!(observed_events.iter().all(|event| {
1616 !event.fields.contains("debug-secret") && !event.fields.contains("malformed-secret")
1617 }));
1618 }
1619
1620 #[tokio::test]
1621 async fn missing_writer_withholds_raw_events_and_reports_capture_disabled() {
1622 let observed_events = Arc::new(Mutex::new(Vec::new()));
1623 let subscriber = tracing_subscriber::registry().with(RecordingLayer {
1624 events: observed_events.clone(),
1625 });
1626 let (output, report) = async {
1627 capture_execution_logs(scope(), None, async {
1628 tracing::info!(target: "inventory", "ordinary host event");
1629 tracing::info!(
1630 target: EXECUTION_LOG_TARGET,
1631 "password=disabled-writer-secret"
1632 );
1633 42
1634 })
1635 .await
1636 }
1637 .with_subscriber(subscriber)
1638 .await;
1639
1640 assert_eq!(output, 42);
1641 assert_eq!(report.status, ExecutionLogCaptureStatus::Disabled);
1642 assert_eq!(report.observed, 0);
1643 let observed_events = observed_events
1644 .lock()
1645 .expect("observed events lock should not be poisoned");
1646 assert_eq!(observed_events.len(), 1);
1647 assert_eq!(observed_events[0].target, "inventory");
1648 assert!(!observed_events[0].fields.contains("disabled-writer-secret"));
1649 }
1650
1651 #[tokio::test]
1652 async fn host_level_filter_does_not_disable_info_execution_log_capture() {
1653 let writer = Arc::new(MemoryExecutionLogWriter::default());
1654 let subscriber =
1655 tracing_subscriber::registry().with(tracing_subscriber::filter::LevelFilter::WARN);
1656
1657 let ((), report) = async {
1658 capture_execution_logs(scope(), Some(writer.clone()), async {
1659 tracing::info!(target: EXECUTION_LOG_TARGET, "captured below host level");
1660 })
1661 .await
1662 }
1663 .with_subscriber(subscriber)
1664 .await;
1665
1666 assert_eq!(report.status, ExecutionLogCaptureStatus::Complete);
1667 assert_eq!(report.observed, 1);
1668 assert_eq!(report.persisted, 1);
1669 assert_eq!(
1670 writer
1671 .records
1672 .lock()
1673 .expect("execution log records lock should not be poisoned")[0]
1674 .body,
1675 "captured below host level"
1676 );
1677 }
1678
1679 #[tokio::test]
1680 async fn concurrent_execution_log_scopes_do_not_mix_runtime_identity() {
1681 let writer_a = Arc::new(MemoryExecutionLogWriter::default());
1682 let writer_b = Arc::new(MemoryExecutionLogWriter::default());
1683
1684 let (capture_a, capture_b) = tokio::join!(
1685 capture_execution_logs(
1686 scope_with_identity("fnrun_a", "corr_a"),
1687 Some(writer_a.clone()),
1688 async {
1689 tokio::task::yield_now().await;
1690 tracing::info!(target: EXECUTION_LOG_TARGET, "scope a");
1691 },
1692 ),
1693 capture_execution_logs(
1694 scope_with_identity("fnrun_b", "corr_b"),
1695 Some(writer_b.clone()),
1696 async {
1697 tracing::info!(target: EXECUTION_LOG_TARGET, "scope b");
1698 tokio::task::yield_now().await;
1699 },
1700 ),
1701 );
1702
1703 assert_eq!(capture_a.1.status, ExecutionLogCaptureStatus::Complete);
1704 assert_eq!(capture_b.1.status, ExecutionLogCaptureStatus::Complete);
1705 let records_a = writer_a
1706 .records
1707 .lock()
1708 .expect("execution log records lock should not be poisoned");
1709 let records_b = writer_b
1710 .records
1711 .lock()
1712 .expect("execution log records lock should not be poisoned");
1713 assert_eq!(records_a.len(), 1);
1714 assert_eq!(records_b.len(), 1);
1715 assert_eq!(records_a[0].execution_id, "fnrun_a");
1716 assert_eq!(records_a[0].correlation_id, "corr_a");
1717 assert_eq!(records_b[0].execution_id, "fnrun_b");
1718 assert_eq!(records_b[0].correlation_id, "corr_b");
1719 }
1720
1721 #[tokio::test]
1722 async fn stalled_writer_drops_bounded_logs_without_changing_output() {
1723 let started = std::time::Instant::now();
1724 let (output, report) =
1725 capture_execution_logs(scope(), Some(Arc::new(StalledExecutionLogWriter)), async {
1726 for sequence in 0..300_u64 {
1727 tracing::info!(
1728 target: EXECUTION_LOG_TARGET,
1729 sequence,
1730 "bounded execution event"
1731 );
1732 }
1733 42
1734 })
1735 .await;
1736
1737 assert_eq!(output, 42);
1738 assert_eq!(report.status, ExecutionLogCaptureStatus::Partial);
1739 assert_eq!(report.observed, 300);
1740 assert_eq!(report.persisted, 0);
1741 assert_eq!(report.dropped, 300);
1742 assert_eq!(report.write_failures, 0);
1743 assert!(started.elapsed() < Duration::from_secs(1));
1744 }
1745
1746 #[tokio::test]
1747 async fn cancelling_capture_aborts_the_in_flight_writer() {
1748 let started = Arc::new(tokio::sync::Notify::new());
1749 let cancelled = Arc::new(tokio::sync::Notify::new());
1750 let writer = Arc::new(CancellationAwareExecutionLogWriter {
1751 started: started.clone(),
1752 cancelled: cancelled.clone(),
1753 });
1754 let capture = tokio::spawn(capture_execution_logs(scope(), Some(writer), async {
1755 tracing::info!(target: EXECUTION_LOG_TARGET, "wait for cancellation");
1756 std::future::pending::<()>().await;
1757 }));
1758
1759 tokio::time::timeout(Duration::from_secs(1), started.notified())
1760 .await
1761 .expect("writer should begin processing");
1762 capture.abort();
1763 let _ = capture.await;
1764 tokio::time::timeout(Duration::from_secs(1), cancelled.notified())
1765 .await
1766 .expect("cancelling capture should abort its writer task");
1767 }
1768}