Skip to main content

saddle_observability/
chain.rs

1use std::{error::Error, fmt, time::Instant};
2
3use saddle_core::{CallContext, ErrorKind, SaddleError};
4use serde_json::{Value, json};
5
6use crate::{EventLevel, Observer, OutputStage, logger::LogRecord};
7
8const MAX_IDENTITY_BYTES: usize = 256;
9
10#[derive(Clone, Debug, Eq, PartialEq)]
11pub enum ChainFieldError {
12    Empty,
13    TooLong,
14    ControlCharacter,
15    UnsafeAuthority,
16    ZeroAttempt,
17}
18
19impl fmt::Display for ChainFieldError {
20    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
21        f.write_str(match self {
22            Self::Empty => "observability identity must not be empty",
23            Self::TooLong => "observability identity exceeds 256 bytes",
24            Self::ControlCharacter => "observability identity contains a control character",
25            Self::UnsafeAuthority => "outbound authority must be a credential-free target label",
26            Self::ZeroAttempt => "attempt must be greater than zero",
27        })
28    }
29}
30
31impl Error for ChainFieldError {}
32
33macro_rules! safe_identity {
34    ($name:ident) => {
35        #[derive(Clone, Debug, Eq, PartialEq)]
36        pub struct $name(String);
37
38        impl $name {
39            pub fn new(value: impl Into<String>) -> Result<Self, ChainFieldError> {
40                validate_identity(value.into()).map(Self)
41            }
42
43            pub fn as_str(&self) -> &str {
44                &self.0
45            }
46        }
47    };
48}
49
50safe_identity!(RequestIdentity);
51safe_identity!(RouteIdentity);
52safe_identity!(BottleneckIdentity);
53safe_identity!(RejectReason);
54
55#[derive(Clone, Debug, Eq, PartialEq)]
56pub struct OutboundAuthority(String);
57
58impl OutboundAuthority {
59    pub fn new(value: impl Into<String>) -> Result<Self, ChainFieldError> {
60        let value = validate_identity(value.into())?;
61        if value.contains(['@', '?', '#', '/', '\\']) || value.contains("://") {
62            return Err(ChainFieldError::UnsafeAuthority);
63        }
64        Ok(Self(value))
65    }
66}
67
68fn validate_identity(value: String) -> Result<String, ChainFieldError> {
69    if value.is_empty() {
70        return Err(ChainFieldError::Empty);
71    }
72    if value.len() > MAX_IDENTITY_BYTES {
73        return Err(ChainFieldError::TooLong);
74    }
75    if value.chars().any(char::is_control) {
76        return Err(ChainFieldError::ControlCharacter);
77    }
78    Ok(value)
79}
80
81#[derive(Clone, Copy, Debug, Eq, PartialEq)]
82pub enum Stage {
83    Ingress,
84    Admission,
85    Handler,
86    Database,
87    ProfuseContract,
88    Response,
89    ResourceFinalization,
90}
91
92impl Stage {
93    const fn as_str(self) -> &'static str {
94        match self {
95            Self::Ingress => "ingress",
96            Self::Admission => "admission",
97            Self::Handler => "handler",
98            Self::Database => "database",
99            Self::ProfuseContract => "profuse_contract",
100            Self::Response => "response",
101            Self::ResourceFinalization => "resource_finalization",
102        }
103    }
104}
105
106#[derive(Clone, Copy, Debug, Eq, PartialEq)]
107pub enum StageOutcome {
108    Success,
109    Failure,
110    Rejected,
111    Cancelled,
112}
113
114/// DB owning-driver facts, not an inference from HTTP or connection disposal.
115#[derive(Clone, Copy, Debug, Eq, PartialEq)]
116pub enum TransactionOutcome {
117    /// COMMIT acknowledgement was received, even if the client later disconnects.
118    Committed,
119    /// No possible commit was entered. This does not prove rollback acknowledgement.
120    Rejected,
121    /// COMMIT may have executed but its acknowledgement is unavailable.
122    Unknown,
123}
124
125impl TransactionOutcome {
126    const fn as_str(self) -> &'static str {
127        match self {
128            Self::Committed => "Committed",
129            Self::Rejected => "Rejected",
130            Self::Unknown => "Unknown",
131        }
132    }
133}
134
135/// Same-request/scope carrier checked by Core and transported by Runtime.
136/// It is consumed once; it is not proof of transaction outcome or log durability.
137pub type TransactionTerminalObservation =
138    saddle_core::DbScopeTerminalObservation<(Observer, CallContext, EventContext)>;
139
140impl StageOutcome {
141    const fn as_str(self) -> &'static str {
142        match self {
143            Self::Success => "success",
144            Self::Failure => "failure",
145            Self::Rejected => "rejected",
146            Self::Cancelled => "cancelled",
147        }
148    }
149}
150
151#[derive(Clone, Debug, Eq, PartialEq)]
152pub struct EventContext {
153    request: RequestIdentity,
154    route: RouteIdentity,
155    attempt: u32,
156}
157
158impl EventContext {
159    pub(crate) fn diagnostic_request(&self) -> &str {
160        self.request.as_str()
161    }
162    pub(crate) fn diagnostic_route(&self) -> &str {
163        self.route.as_str()
164    }
165    pub fn new(
166        request: RequestIdentity,
167        route: RouteIdentity,
168        attempt: u32,
169    ) -> Result<Self, ChainFieldError> {
170        if attempt == 0 {
171            return Err(ChainFieldError::ZeroAttempt);
172        }
173        Ok(Self {
174            request,
175            route,
176            attempt,
177        })
178    }
179}
180
181pub struct ActiveStage {
182    observer: Observer,
183    context: CallContext,
184    parent_span: String,
185    stage: Stage,
186    request: RequestIdentity,
187    route: RouteIdentity,
188    attempt: u32,
189    started_at: Instant,
190    finished: bool,
191}
192
193impl Observer {
194    /// DB owning driver calls once before returning its result/physical receipt.
195    /// Uses the carrier's observer/context, with no caller-supplied scope or sink.
196    /// Queue loss preserves the DB result; a missing log remains NOT_PROVEN.
197    ///
198    /// ```compile_fail
199    /// use saddle_observability::{Observer, TransactionOutcome, TransactionTerminalObservation};
200    /// fn replay(observation: TransactionTerminalObservation) {
201    ///     Observer::record_transaction_terminal(observation, TransactionOutcome::Committed);
202    ///     Observer::record_transaction_terminal(observation, TransactionOutcome::Rejected);
203    /// }
204    /// ```
205    pub fn record_transaction_terminal(
206        observation: TransactionTerminalObservation,
207        outcome: TransactionOutcome,
208    ) {
209        let ((observer, context, event_context), scope) = observation.into_log_parts();
210        let mut record = base_record(
211            &context,
212            if outcome == TransactionOutcome::Committed {
213                EventLevel::Info
214            } else {
215                EventLevel::Error
216            },
217            "database_transaction_terminal",
218            "database",
219        );
220        add_event_context(&mut record, &event_context);
221        // Core's concrete Serialize-only payload has exactly one numeric field.
222        // A serialization failure drops this attempt; it never changes DB outcome.
223        let Ok(Value::Object(fields)) = serde_json::to_value(scope) else {
224            return;
225        };
226        record.data.extend(fields);
227        record.data.insert(
228            "transaction_outcome".into(),
229            Value::String(outcome.as_str().into()),
230        );
231        record
232            .data
233            .insert("outcome".into(), Value::String(outcome.as_str().into()));
234        observer.emit(record);
235    }
236
237    pub fn record_lifecycle_timeout(
238        &self,
239        application: &str,
240        stage: LifecycleTimeoutStage,
241        elapsed_ms: u64,
242    ) {
243        let Ok((call, _)) = self.start_external_call_checked(
244            application,
245            "runtime",
246            "lifecycle",
247            stage.as_str(),
248            None,
249        ) else {
250            return;
251        };
252        let mut record = base_record(
253            call.context(),
254            EventLevel::Error,
255            "framework.lifecycle.timeout",
256            "lifecycle",
257        );
258        record
259            .data
260            .insert("timeout_stage".into(), Value::String(stage.as_str().into()));
261        record.data.insert("elapsed_ms".into(), json!(elapsed_ms));
262        record
263            .data
264            .insert("outcome".into(), Value::String("timeout".into()));
265        self.emit(record);
266        call.fail(&SaddleError::new(
267            ErrorKind::Infrastructure,
268            "runtime.lifecycle_timeout",
269            "managed lifecycle deadline elapsed",
270        ));
271    }
272
273    pub fn start_stage(
274        &self,
275        parent: &CallContext,
276        stage: Stage,
277        event_context: EventContext,
278    ) -> ActiveStage {
279        let context = CallContext::new(
280            parent.application().clone(),
281            parent.module().clone(),
282            parent.service().clone(),
283            parent.operation().clone(),
284            parent.trace_id(),
285            self.new_span_id(),
286        )
287        .with_trace_correlation_id(parent.trace_correlation_id().clone())
288        .with_rpc_correlation_id(parent.rpc_correlation_id().cloned());
289        let active = ActiveStage {
290            observer: self.clone(),
291            context,
292            parent_span: parent.span_id().to_string(),
293            stage,
294            request: event_context.request,
295            route: event_context.route,
296            attempt: event_context.attempt,
297            started_at: Instant::now(),
298            finished: false,
299        };
300        active.emit_started();
301        active
302    }
303
304    pub fn record_capacity(
305        &self,
306        context: &CallContext,
307        event_context: &EventContext,
308        value: CapacityObservation,
309    ) {
310        self.inner
311            .metrics
312            .capacity(value.dimension, value.used, value.reject_reason.is_some());
313        let mut record = base_record(context, EventLevel::Info, "framework.capacity", "admission");
314        add_event_context(&mut record, event_context);
315        if let Some(dimension) = value.dimension {
316            record.data.insert(
317                "capacity_dimension".into(),
318                Value::String(dimension.as_str().into()),
319            );
320        }
321        record.data.insert("budget".into(), json!(value.budget));
322        record.data.insert("limit".into(), json!(value.limit));
323        record.data.insert("used".into(), json!(value.used));
324        record
325            .data
326            .insert("elapsed_ms".into(), json!(value.elapsed_ms));
327        record
328            .data
329            .insert("bottleneck".into(), Value::String(value.bottleneck.0));
330        record.data.insert(
331            "outcome".into(),
332            Value::String(
333                if value.reject_reason.is_some() {
334                    "rejected"
335                } else {
336                    "accepted"
337                }
338                .into(),
339            ),
340        );
341        if let Some(reason) = value.reject_reason {
342            record
343                .data
344                .insert("reject_reason".into(), Value::String(reason.0));
345        }
346        self.emit(record);
347    }
348
349    pub fn record_database_disposition(
350        &self,
351        context: &CallContext,
352        event_context: &EventContext,
353        disposition: DatabaseDisposition,
354    ) {
355        self.inner.metrics.database(disposition);
356        let mut record = base_record(
357            context,
358            EventLevel::Info,
359            "framework.database.disposition",
360            "database",
361        );
362        add_event_context(&mut record, event_context);
363        record.data.insert(
364            "db_disposition".into(),
365            Value::String(disposition.as_str().into()),
366        );
367        record
368            .data
369            .insert("outcome".into(), Value::String(disposition.as_str().into()));
370        self.emit(record);
371    }
372
373    pub fn record_resource_finalization(
374        &self,
375        context: &CallContext,
376        event_context: &EventContext,
377        disposition: DatabaseDisposition,
378        elapsed_ms: u64,
379    ) {
380        let mut record = base_record(
381            context,
382            EventLevel::Info,
383            "framework.resource.finalized",
384            "resource_finalization",
385        );
386        add_event_context(&mut record, event_context);
387        record.data.insert("elapsed_ms".into(), json!(elapsed_ms));
388        record
389            .data
390            .insert("credit".into(), Value::String("released".into()));
391        record.data.insert(
392            "db_disposition".into(),
393            Value::String(disposition.as_str().into()),
394        );
395        record
396            .data
397            .insert("outcome".into(), Value::String("success".into()));
398        self.emit(record);
399    }
400
401    pub fn record_outbound(
402        &self,
403        context: &CallContext,
404        event_context: &EventContext,
405        observation: OutboundObservation,
406    ) {
407        self.inner.metrics.outbound(observation.result);
408        let mut record = base_record(
409            context,
410            EventLevel::Info,
411            "framework.outbound",
412            "profuse_contract",
413        );
414        add_event_context(&mut record, event_context);
415        record
416            .data
417            .insert("zone".into(), Value::String(observation.zone.0));
418        record
419            .data
420            .insert("authority".into(), Value::String(observation.authority.0));
421        record.data.insert(
422            "outbound_result".into(),
423            Value::String(observation.result.as_str().into()),
424        );
425        record.data.insert(
426            "outcome".into(),
427            Value::String(observation.result.as_str().into()),
428        );
429        self.emit(record);
430    }
431
432    pub fn record_lifecycle(
433        &self,
434        context: &CallContext,
435        event_context: &EventContext,
436        state: LifecycleState,
437        health: Health,
438    ) {
439        self.inner.metrics.lifecycle(state, health);
440        let mut record = base_record(
441            context,
442            if health == Health::Healthy {
443                EventLevel::Info
444            } else {
445                EventLevel::Error
446            },
447            "framework.lifecycle",
448            "resource_finalization",
449        );
450        add_event_context(&mut record, event_context);
451        record
452            .data
453            .insert("lifecycle".into(), Value::String(state.as_str().into()));
454        record
455            .data
456            .insert("health".into(), Value::String(health.as_str().into()));
457        record
458            .data
459            .insert("outcome".into(), Value::String(health.as_str().into()));
460        self.emit(record);
461    }
462
463    pub fn record_logger_health(
464        &self,
465        context: &CallContext,
466        event_context: &EventContext,
467        dropped: u64,
468        failure: Option<OutputStage>,
469    ) {
470        self.inner.metrics.logger_output(failure.is_some());
471        let mut record = base_record(
472            context,
473            if failure.is_some() || dropped > 0 {
474                EventLevel::Error
475            } else {
476                EventLevel::Info
477            },
478            "framework.logger.health",
479            "logger",
480        );
481        add_event_context(&mut record, event_context);
482        record.data.insert("logger_dropped".into(), json!(dropped));
483        record.data.insert(
484            "logger_health".into(),
485            Value::String(
486                if failure.is_some() {
487                    "output_failed"
488                } else {
489                    "healthy"
490                }
491                .into(),
492            ),
493        );
494        record.data.insert(
495            "outcome".into(),
496            Value::String(
497                if failure.is_some() {
498                    "failure"
499                } else {
500                    "success"
501                }
502                .into(),
503            ),
504        );
505        if let Some(stage) = failure {
506            record.data.insert(
507                "output_failed".into(),
508                Value::String(format!("{stage:?}").to_ascii_lowercase()),
509            );
510        }
511        self.emit(record);
512    }
513}
514
515#[derive(Clone, Copy, Debug, Eq, PartialEq)]
516pub enum LifecycleTimeoutStage {
517    ComponentStart,
518    RequestDrain,
519    ComponentShutdown,
520    PostDriverFinalization,
521}
522
523impl LifecycleTimeoutStage {
524    const fn as_str(self) -> &'static str {
525        match self {
526            Self::ComponentStart => "component_start",
527            Self::RequestDrain => "request_drain",
528            Self::ComponentShutdown => "component_shutdown",
529            Self::PostDriverFinalization => "post_driver_finalization",
530        }
531    }
532}
533
534impl ActiveStage {
535    pub fn context(&self) -> &CallContext {
536        &self.context
537    }
538    pub fn succeed(mut self) {
539        self.finish(StageOutcome::Success, None);
540    }
541    pub fn reject(mut self, error: &SaddleError) {
542        self.finish(StageOutcome::Rejected, Some(error));
543    }
544    pub fn fail(mut self, error: &SaddleError) {
545        self.finish(StageOutcome::Failure, Some(error));
546    }
547
548    fn emit_started(&self) {
549        let mut record = self.record(EventLevel::Info, "framework.stage.started");
550        record
551            .data
552            .insert("outcome".into(), Value::String("started".into()));
553        self.observer.emit(record);
554    }
555
556    fn finish(&mut self, outcome: StageOutcome, error: Option<&SaddleError>) {
557        if self.finished {
558            return;
559        }
560        let mut record = self.record(
561            if outcome == StageOutcome::Success {
562                EventLevel::Info
563            } else {
564                EventLevel::Error
565            },
566            "framework.stage.finished",
567        );
568        record
569            .data
570            .insert("outcome".into(), Value::String(outcome.as_str().into()));
571        let elapsed_ms = u64::try_from(self.started_at.elapsed().as_millis()).unwrap_or(u64::MAX);
572        record.data.insert("elapsed_ms".into(), json!(elapsed_ms));
573        if let Some(error) = error {
574            record
575                .data
576                .insert("error_code".into(), Value::String(error.code().to_owned()));
577            record.data.insert(
578                "error_kind".into(),
579                Value::String(error_kind(error.kind()).into()),
580            );
581        }
582        self.observer
583            .inner
584            .metrics
585            .stage_finished(self.stage, outcome, elapsed_ms);
586        self.observer.emit(record);
587        self.finished = true;
588    }
589
590    fn record(&self, level: EventLevel, event: &'static str) -> LogRecord {
591        let mut record = base_record(&self.context, level, event, self.stage.as_str());
592        record.parent = Some(self.parent_span.clone());
593        record.parent_span_id = Some(self.parent_span.clone());
594        record.data.insert(
595            "request_identity".into(),
596            Value::String(self.request.0.clone()),
597        );
598        record
599            .data
600            .insert("route".into(), Value::String(self.route.0.clone()));
601        record.data.insert("attempt".into(), json!(self.attempt));
602        record.data.insert("elapsed_ms".into(), json!(0));
603        record
604            .data
605            .insert("error_code".into(), Value::String("none".into()));
606        record
607    }
608}
609
610impl Drop for ActiveStage {
611    fn drop(&mut self) {
612        self.finish(StageOutcome::Cancelled, None);
613    }
614}
615
616pub struct CapacityObservation {
617    dimension: Option<CapacityDimension>,
618    budget: u64,
619    limit: u64,
620    used: u64,
621    bottleneck: BottleneckIdentity,
622    reject_reason: Option<RejectReason>,
623    elapsed_ms: u64,
624}
625
626impl CapacityObservation {
627    pub fn accepted(budget: u64, limit: u64, used: u64, bottleneck: BottleneckIdentity) -> Self {
628        Self {
629            dimension: None,
630            budget,
631            limit,
632            used,
633            bottleneck,
634            reject_reason: None,
635            elapsed_ms: 0,
636        }
637    }
638    pub fn rejected(
639        budget: u64,
640        limit: u64,
641        used: u64,
642        bottleneck: BottleneckIdentity,
643        reason: RejectReason,
644    ) -> Self {
645        Self {
646            dimension: None,
647            budget,
648            limit,
649            used,
650            bottleneck,
651            reject_reason: Some(reason),
652            elapsed_ms: 0,
653        }
654    }
655
656    pub fn accepted_dimension(
657        dimension: CapacityDimension,
658        budget: u64,
659        limit: u64,
660        used: u64,
661        bottleneck: BottleneckIdentity,
662        elapsed_ms: u64,
663    ) -> Self {
664        Self {
665            dimension: Some(dimension),
666            budget,
667            limit,
668            used,
669            bottleneck,
670            reject_reason: None,
671            elapsed_ms,
672        }
673    }
674
675    pub fn rejected_dimension(
676        dimension: CapacityDimension,
677        budget: u64,
678        limit: u64,
679        used: u64,
680        bottleneck: BottleneckIdentity,
681        reason: RejectReason,
682        elapsed_ms: u64,
683    ) -> Self {
684        Self {
685            dimension: Some(dimension),
686            budget,
687            limit,
688            used,
689            bottleneck,
690            reject_reason: Some(reason),
691            elapsed_ms,
692        }
693    }
694}
695
696#[derive(Clone, Copy, Debug, Eq, PartialEq)]
697pub enum CapacityDimension {
698    Cpu,
699    Memory,
700    Database,
701    ProfuseContract,
702}
703
704impl CapacityDimension {
705    const fn as_str(self) -> &'static str {
706        match self {
707            Self::Cpu => "cpu",
708            Self::Memory => "memory",
709            Self::Database => "database",
710            Self::ProfuseContract => "profuse_contract",
711        }
712    }
713}
714
715#[derive(Clone, Copy, Debug, Eq, PartialEq)]
716pub enum DatabaseDisposition {
717    NotUsed,
718    Returned,
719    Discarded,
720}
721impl DatabaseDisposition {
722    const fn as_str(self) -> &'static str {
723        match self {
724            Self::NotUsed => "not_used",
725            Self::Returned => "returned",
726            Self::Discarded => "discarded",
727        }
728    }
729}
730
731pub struct OutboundObservation {
732    zone: RouteIdentity,
733    authority: OutboundAuthority,
734    result: OutboundResult,
735}
736impl OutboundObservation {
737    pub fn new(zone: RouteIdentity, authority: OutboundAuthority, result: OutboundResult) -> Self {
738        Self {
739            zone,
740            authority,
741            result,
742        }
743    }
744}
745
746#[derive(Clone, Copy, Debug, Eq, PartialEq)]
747pub enum OutboundResult {
748    Success,
749    Failure,
750    Rejected,
751    Timeout,
752}
753impl OutboundResult {
754    const fn as_str(self) -> &'static str {
755        match self {
756            Self::Success => "success",
757            Self::Failure => "failure",
758            Self::Rejected => "rejected",
759            Self::Timeout => "timeout",
760        }
761    }
762}
763
764#[derive(Clone, Copy, Debug, Eq, PartialEq)]
765pub enum LifecycleState {
766    Starting,
767    Running,
768    Draining,
769    Stopped,
770}
771impl LifecycleState {
772    const fn as_str(self) -> &'static str {
773        match self {
774            Self::Starting => "starting",
775            Self::Running => "running",
776            Self::Draining => "draining",
777            Self::Stopped => "stopped",
778        }
779    }
780}
781
782#[derive(Clone, Copy, Debug, Eq, PartialEq)]
783pub enum Health {
784    Healthy,
785    Degraded,
786    Failed,
787}
788impl Health {
789    const fn as_str(self) -> &'static str {
790        match self {
791            Self::Healthy => "healthy",
792            Self::Degraded => "degraded",
793            Self::Failed => "failed",
794        }
795    }
796}
797
798fn base_record(
799    context: &CallContext,
800    level: EventLevel,
801    event: &'static str,
802    stage: &'static str,
803) -> LogRecord {
804    let mut record = LogRecord::new(level, event);
805    record.trace_id = Some(context.trace_correlation_id().to_string());
806    record.span = Some(stage.into());
807    record.span_id = Some(context.span_id().to_string());
808    record
809        .data
810        .insert("timestamp".into(), json!(record.timestamp_unix_ms));
811    record
812        .data
813        .insert("stage".into(), Value::String(stage.into()));
814    record.data.insert(
815        "rpc_id".into(),
816        context
817            .rpc_correlation_id()
818            .map(|rpc| Value::String(rpc.as_str().into()))
819            .unwrap_or(Value::Null),
820    );
821    record.data.insert(
822        "request".into(),
823        Value::String(context.operation().to_string()),
824    );
825    record
826}
827
828fn add_event_context(record: &mut LogRecord, context: &EventContext) {
829    record.data.insert(
830        "request_identity".into(),
831        Value::String(context.request.0.clone()),
832    );
833    record
834        .data
835        .insert("route".into(), Value::String(context.route.0.clone()));
836    record.data.insert("attempt".into(), json!(context.attempt));
837    record.data.insert("elapsed_ms".into(), json!(0));
838    record
839        .data
840        .insert("error_code".into(), Value::String("none".into()));
841}
842
843const fn error_kind(kind: ErrorKind) -> &'static str {
844    match kind {
845        ErrorKind::InvalidArgument => "invalid_argument",
846        ErrorKind::NotFound => "not_found",
847        ErrorKind::Conflict => "conflict",
848        ErrorKind::Business => "business",
849        ErrorKind::Unavailable => "unavailable",
850        ErrorKind::Infrastructure => "infrastructure",
851        ErrorKind::Internal => "internal",
852        _ => "unknown",
853    }
854}
855
856#[cfg(test)]
857mod tests {
858    use std::{
859        future::Future,
860        io,
861        sync::{Arc, Mutex},
862        task::{Context, Poll, Wake, Waker},
863        thread,
864    };
865
866    use super::*;
867    use crate::ObserverConfig;
868
869    #[derive(Clone, Default)]
870    struct Capture(Arc<Mutex<Vec<u8>>>);
871
872    impl io::Write for Capture {
873        fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
874            self.0.lock().unwrap().extend_from_slice(bytes);
875            Ok(bytes.len())
876        }
877        fn flush(&mut self) -> io::Result<()> {
878            Ok(())
879        }
880    }
881
882    struct ThreadWaker(thread::Thread);
883    impl Wake for ThreadWaker {
884        fn wake(self: Arc<Self>) {
885            self.0.unpark();
886        }
887    }
888
889    fn block_on<T>(future: impl Future<Output = T>) -> T {
890        let waker = Waker::from(Arc::new(ThreadWaker(thread::current())));
891        let mut context = Context::from_waker(&waker);
892        let mut future = std::pin::pin!(future);
893        loop {
894            match future.as_mut().poll(&mut context) {
895                Poll::Ready(output) => return output,
896                Poll::Pending => thread::park(),
897            }
898        }
899    }
900
901    fn event_context(attempt: u32) -> EventContext {
902        EventContext::new(
903            RequestIdentity::new("request-7").unwrap(),
904            RouteIdentity::new("orders.create").unwrap(),
905            attempt,
906        )
907        .unwrap()
908    }
909
910    #[test]
911    fn transaction_terminal_serial_scope_schema_and_foreign_restore() {
912        let capture = Capture::default();
913        let observer = Observer::with_writer(ObserverConfig::default(), capture.clone()).unwrap();
914        let (root, _) = observer
915            .start_external_call_with_rpc(
916                "shop",
917                "entry",
918                "orders",
919                "create",
920                Some("safe-trace"),
921                saddle_core::RpcCorrelationId::new("0").unwrap(),
922            )
923            .unwrap();
924        let (startup, issuer) =
925            saddle_core::DbPhysicalDispositionIssuer::issue().into_startup_and_request_issuer();
926        let process = startup.into_process_capability();
927        let (mut request, mut execution) = issuer.issue_request().unwrap();
928        let (_, foreign) = issuer.issue_request().unwrap();
929        for outcome in [
930            TransactionOutcome::Committed,
931            TransactionOutcome::Rejected,
932            TransactionOutcome::Unknown,
933        ] {
934            let observation = request
935                .take_scope_observation(
936                    &execution,
937                    (observer.clone(), root.context().clone(), event_context(1)),
938                )
939                .ok()
940                .unwrap();
941            let observation = observation.bind_terminal(&foreign).err().unwrap();
942            let observation = observation.bind_terminal(&execution).ok().unwrap();
943            Observer::record_transaction_terminal(observation, outcome);
944            assert!(request.take_scope_observation(&execution, ()).is_err());
945            let physical = process.connection_returned(execution, ()).ok().unwrap();
946            let (next, _, _) = saddle_core::pair_db_physical_disposition(physical, request)
947                .ok()
948                .unwrap()
949                .into_scope_continuation();
950            (request, execution) = next.into_next_scope().ok().unwrap();
951        }
952        block_on(observer.flush()).unwrap();
953        let rows: Vec<_> = records(&capture)
954            .into_iter()
955            .filter(|r| r["event"] == "database_transaction_terminal")
956            .collect();
957        assert_eq!(rows.len(), 3);
958        for (index, outcome) in ["Committed", "Rejected", "Unknown"].into_iter().enumerate() {
959            let row = &rows[index];
960            assert_eq!(row["transaction_scope"], index);
961            assert_eq!(row["transaction_outcome"], outcome);
962            assert_eq!(row["trace_id"], "safe-trace");
963            assert_eq!(row["rpc_id"], "0");
964            assert_eq!(row["span_id"], root.context().span_id().to_string());
965            assert_ne!(row["rpc_id"], row["span_id"]);
966            assert_eq!(row["request_identity"], "request-7");
967            assert_eq!(row["route"], "orders.create");
968            let mut keys: Vec<_> = row
969                .as_object()
970                .unwrap()
971                .keys()
972                .map(String::as_str)
973                .collect();
974            keys.sort_unstable();
975            let mut expected = vec![
976                "timestamp_unix_ms",
977                "timestamp",
978                "level",
979                "event",
980                "stage",
981                "trace_id",
982                "rpc_id",
983                "span",
984                "span_id",
985                "request",
986                "request_identity",
987                "route",
988                "attempt",
989                "elapsed_ms",
990                "error_code",
991                "outcome",
992                "transaction_scope",
993                "transaction_outcome",
994            ];
995            expected.sort_unstable();
996            assert_eq!(keys, expected); // No SQL/parameters/business error or arbitrary fields.
997        }
998        root.succeed();
999        block_on(observer.shutdown()).unwrap();
1000    }
1001
1002    #[test]
1003    fn transaction_terminal_full_queue_never_waits_for_writer() {
1004        use std::sync::mpsc;
1005        use std::time::Duration;
1006        struct PausedWriter {
1007            entered: Option<mpsc::Sender<()>>,
1008            release: mpsc::Receiver<()>,
1009        }
1010        impl io::Write for PausedWriter {
1011            fn write(&mut self, bytes: &[u8]) -> io::Result<usize> {
1012                if let Some(entered) = self.entered.take() {
1013                    entered.send(()).unwrap();
1014                    self.release.recv().unwrap();
1015                }
1016                Ok(bytes.len())
1017            }
1018            fn flush(&mut self) -> io::Result<()> {
1019                Ok(())
1020            }
1021        }
1022        let (entered, reached) = mpsc::channel();
1023        let (release, gate) = mpsc::channel();
1024        let observer = Observer::with_writer(
1025            ObserverConfig { queue_capacity: 1 },
1026            PausedWriter {
1027                entered: Some(entered),
1028                release: gate,
1029            },
1030        )
1031        .unwrap();
1032        let (root, _) = observer.start_external_call("shop", "entry", "orders", "create", None);
1033        reached.recv_timeout(Duration::from_secs(5)).unwrap();
1034        observer.emit(LogRecord::new(EventLevel::Info, "fill"));
1035        let (_, issuer) =
1036            saddle_core::DbPhysicalDispositionIssuer::issue().into_startup_and_request_issuer();
1037        let (mut request, execution) = issuer.issue_request().unwrap();
1038        let observation = request
1039            .take_scope_observation(
1040                &execution,
1041                (observer.clone(), root.context().clone(), event_context(1)),
1042            )
1043            .ok()
1044            .unwrap()
1045            .bind_terminal(&execution)
1046            .ok()
1047            .unwrap();
1048        let (done, completion) = mpsc::channel();
1049        let emitter = thread::spawn(move || {
1050            Observer::record_transaction_terminal(observation, TransactionOutcome::Unknown);
1051            done.send(()).unwrap();
1052        });
1053        let result = completion.recv_timeout(Duration::from_secs(2));
1054        let dropped = observer.dropped_events();
1055        release.send(()).unwrap(); // Release even if a regression blocked the emitter.
1056        emitter.join().unwrap();
1057        assert!(result.is_ok());
1058        assert_eq!(dropped, 1);
1059        let _ = block_on(observer.flush());
1060        root.succeed();
1061        let _ = block_on(observer.shutdown());
1062    }
1063
1064    fn records(capture: &Capture) -> Vec<Value> {
1065        String::from_utf8(capture.0.lock().unwrap().clone())
1066            .unwrap()
1067            .lines()
1068            .map(|line| serde_json::from_str(line).unwrap())
1069            .collect()
1070    }
1071
1072    #[test]
1073    fn lifecycle_timeout_is_typed_and_contains_no_application_payload() {
1074        let capture = Capture::default();
1075        let observer = Observer::with_writer(ObserverConfig::default(), capture.clone()).unwrap();
1076        observer.record_lifecycle_timeout(
1077            "profusegw",
1078            LifecycleTimeoutStage::ComponentShutdown,
1079            30_000,
1080        );
1081        block_on(observer.flush()).unwrap();
1082
1083        let records = records(&capture);
1084        let timeout = records
1085            .iter()
1086            .find(|record| record["event"] == "framework.lifecycle.timeout")
1087            .unwrap();
1088        assert_eq!(timeout["timeout_stage"], "component_shutdown");
1089        assert_eq!(timeout["elapsed_ms"], 30_000);
1090        assert_eq!(timeout["outcome"], "timeout");
1091        assert!(timeout.get("payload").is_none());
1092    }
1093
1094    #[test]
1095    fn stage_chain_is_correlated_ordered_and_has_one_terminal() {
1096        let capture = Capture::default();
1097        let observer = Observer::with_writer(ObserverConfig::default(), capture.clone()).unwrap();
1098        let (root, _) = observer.start_external_call(
1099            "shop",
1100            "entry",
1101            "orders",
1102            "create",
1103            Some("00112233445566778899aabbccddeeff"),
1104        );
1105        let stages = [
1106            Stage::Ingress,
1107            Stage::Admission,
1108            Stage::Handler,
1109            Stage::Database,
1110            Stage::ProfuseContract,
1111            Stage::Response,
1112            Stage::ResourceFinalization,
1113        ];
1114        for (index, stage) in stages.into_iter().enumerate() {
1115            observer
1116                .start_stage(root.context(), stage, event_context((index + 1) as u32))
1117                .succeed();
1118        }
1119        drop(observer.start_stage(root.context(), Stage::Handler, event_context(8)));
1120        root.succeed();
1121        block_on(observer.flush()).unwrap();
1122
1123        let records = records(&capture);
1124        let stage_records: Vec<_> = records
1125            .iter()
1126            .filter(|value| {
1127                value["event"]
1128                    .as_str()
1129                    .unwrap()
1130                    .starts_with("framework.stage.")
1131            })
1132            .collect();
1133        assert_eq!(stage_records.len(), 16);
1134        for pair in stage_records.chunks_exact(2) {
1135            assert_eq!(pair[0]["event"], "framework.stage.started");
1136            assert_eq!(pair[1]["event"], "framework.stage.finished");
1137            assert_eq!(pair[0]["rpc_id"], pair[1]["rpc_id"]);
1138            assert_eq!(pair[0]["trace_id"], "00112233445566778899aabbccddeeff");
1139            for field in [
1140                "timestamp_unix_ms",
1141                "timestamp",
1142                "level",
1143                "event",
1144                "stage",
1145                "trace_id",
1146                "rpc_id",
1147                "request_identity",
1148                "route",
1149                "attempt",
1150                "outcome",
1151                "error_code",
1152            ] {
1153                assert!(pair[0].get(field).is_some(), "missing {field}");
1154            }
1155            assert!(pair[1].get("elapsed_ms").is_some());
1156        }
1157        assert_eq!(stage_records.last().unwrap()["outcome"], "cancelled");
1158    }
1159
1160    #[test]
1161    fn closed_observations_have_common_fields_and_no_sensitive_payload() {
1162        let capture = Capture::default();
1163        let observer = Observer::with_writer(ObserverConfig::default(), capture.clone()).unwrap();
1164        let (root, _) = observer.start_external_call("shop", "entry", "orders", "create", None);
1165        let common = event_context(1);
1166        observer.record_capacity(
1167            root.context(),
1168            &common,
1169            CapacityObservation::rejected(
1170                100,
1171                80,
1172                80,
1173                BottleneckIdentity::new("request_slots").unwrap(),
1174                RejectReason::new("limit_reached").unwrap(),
1175            ),
1176        );
1177        observer.record_database_disposition(
1178            root.context(),
1179            &common,
1180            DatabaseDisposition::Returned,
1181        );
1182        observer.record_outbound(
1183            root.context(),
1184            &common,
1185            OutboundObservation::new(
1186                RouteIdentity::new("cn-hz-a").unwrap(),
1187                OutboundAuthority::new("inventory-service").unwrap(),
1188                OutboundResult::Success,
1189            ),
1190        );
1191        observer.record_lifecycle(
1192            root.context(),
1193            &common,
1194            LifecycleState::Draining,
1195            Health::Healthy,
1196        );
1197        observer.record_logger_health(root.context(), &common, 3, Some(OutputStage::Record));
1198        root.succeed();
1199        let _ = block_on(observer.flush());
1200
1201        let records: Vec<_> = records(&capture)
1202            .into_iter()
1203            .filter(|value| {
1204                matches!(
1205                    value["event"].as_str(),
1206                    Some(
1207                        "framework.capacity"
1208                            | "framework.database.disposition"
1209                            | "framework.outbound"
1210                            | "framework.lifecycle"
1211                            | "framework.logger.health"
1212                    )
1213                )
1214            })
1215            .collect();
1216        assert_eq!(records.len(), 5);
1217        for record in records {
1218            for field in [
1219                "timestamp_unix_ms",
1220                "timestamp",
1221                "level",
1222                "event",
1223                "stage",
1224                "trace_id",
1225                "rpc_id",
1226                "request_identity",
1227                "route",
1228                "attempt",
1229                "elapsed_ms",
1230                "outcome",
1231                "error_code",
1232            ] {
1233                assert!(record.get(field).is_some(), "missing {field}");
1234            }
1235            let encoded = serde_json::to_string(&record).unwrap();
1236            for forbidden in [
1237                "request_body",
1238                "response_body",
1239                "cookie",
1240                "session",
1241                "token",
1242                "password",
1243                "connection_string",
1244                "db_value",
1245            ] {
1246                assert!(!encoded.contains(forbidden));
1247            }
1248        }
1249    }
1250
1251    #[test]
1252    fn fixed_metrics_snapshot_tracks_closed_low_cardinality_events() {
1253        let observer = Observer::with_writer(ObserverConfig::default(), io::sink()).unwrap();
1254        let (root, _) = observer.start_external_call("shop", "entry", "orders", "create", None);
1255        let common = event_context(1);
1256        observer
1257            .start_stage(root.context(), Stage::Response, event_context(1))
1258            .succeed();
1259        observer.record_capacity(
1260            root.context(),
1261            &common,
1262            CapacityObservation::rejected_dimension(
1263                CapacityDimension::Database,
1264                100,
1265                80,
1266                80,
1267                BottleneckIdentity::new("database_slots").unwrap(),
1268                RejectReason::new("limit_reached").unwrap(),
1269                2,
1270            ),
1271        );
1272        observer.record_database_disposition(
1273            root.context(),
1274            &common,
1275            DatabaseDisposition::Discarded,
1276        );
1277        observer.record_outbound(
1278            root.context(),
1279            &common,
1280            OutboundObservation::new(
1281                RouteIdentity::new("cn-hz-a").unwrap(),
1282                OutboundAuthority::new("inventory-service").unwrap(),
1283                OutboundResult::Timeout,
1284            ),
1285        );
1286        observer.record_logger_health(root.context(), &common, 3, Some(OutputStage::Record));
1287        observer.record_lifecycle(
1288            root.context(),
1289            &common,
1290            LifecycleState::Running,
1291            Health::Healthy,
1292        );
1293
1294        let snapshot = observer.metrics_snapshot();
1295        assert_eq!(snapshot.requests(StageOutcome::Success), 1);
1296        assert_eq!(
1297            snapshot.stage_latency(Stage::Response).iter().sum::<u64>(),
1298            1
1299        );
1300        assert_eq!(
1301            snapshot.capacity_rejected(Some(CapacityDimension::Database)),
1302            1
1303        );
1304        assert_eq!(
1305            snapshot.capacity_used(Some(CapacityDimension::Database)),
1306            80
1307        );
1308        assert_eq!(snapshot.database(DatabaseDisposition::Discarded), 1);
1309        assert_eq!(snapshot.outbound(OutboundResult::Timeout), 1);
1310        assert_eq!(snapshot.logger_dropped(), 0);
1311        assert_eq!(snapshot.logger_output_failed(), 1);
1312        assert_eq!(snapshot.lifecycle(), LifecycleState::Running);
1313        assert_eq!(snapshot.health(), Health::Healthy);
1314        assert!(snapshot.ready());
1315        root.succeed();
1316    }
1317
1318    #[test]
1319    fn typed_capacity_and_resource_terminal_preserve_closed_schema() {
1320        let capture = Capture::default();
1321        let observer = Observer::with_writer(ObserverConfig::default(), capture.clone()).unwrap();
1322        let (root, _) = observer.start_external_call("shop", "entry", "orders", "create", None);
1323        let common = event_context(1);
1324        observer.record_capacity(
1325            root.context(),
1326            &common,
1327            CapacityObservation::rejected_dimension(
1328                CapacityDimension::Database,
1329                4,
1330                2,
1331                2,
1332                BottleneckIdentity::new("database").unwrap(),
1333                RejectReason::new("at_limit").unwrap(),
1334                17,
1335            ),
1336        );
1337        observer.record_resource_finalization(
1338            root.context(),
1339            &common,
1340            DatabaseDisposition::NotUsed,
1341            23,
1342        );
1343        root.succeed();
1344        block_on(observer.flush()).unwrap();
1345
1346        let records = records(&capture);
1347        let capacity = records
1348            .iter()
1349            .find(|record| record["event"] == "framework.capacity")
1350            .unwrap();
1351        assert_eq!(capacity["capacity_dimension"], "database");
1352        assert_eq!(capacity["budget"], 4);
1353        assert_eq!(capacity["limit"], 2);
1354        assert_eq!(capacity["used"], 2);
1355        assert_eq!(capacity["bottleneck"], "database");
1356        assert_eq!(capacity["reject_reason"], "at_limit");
1357        assert_eq!(capacity["elapsed_ms"], 17);
1358
1359        let terminal = records
1360            .iter()
1361            .find(|record| record["event"] == "framework.resource.finalized")
1362            .unwrap();
1363        assert_eq!(terminal["stage"], "resource_finalization");
1364        assert_eq!(terminal["credit"], "released");
1365        assert_eq!(terminal["db_disposition"], "not_used");
1366        assert_eq!(terminal["elapsed_ms"], 23);
1367        assert_eq!(terminal["outcome"], "success");
1368        assert_eq!(capacity["trace_id"], terminal["trace_id"]);
1369        assert_eq!(capacity["rpc_id"], terminal["rpc_id"]);
1370        assert_eq!(capacity["request_identity"], terminal["request_identity"]);
1371        assert_eq!(capacity["route"], terminal["route"]);
1372        assert_eq!(capacity["attempt"], terminal["attempt"]);
1373    }
1374
1375    #[test]
1376    fn unsafe_or_unbounded_identifiers_and_zero_attempt_are_rejected() {
1377        assert_eq!(RequestIdentity::new(""), Err(ChainFieldError::Empty));
1378        assert_eq!(
1379            RouteIdentity::new("x".repeat(257)),
1380            Err(ChainFieldError::TooLong)
1381        );
1382        assert_eq!(
1383            RejectReason::new("bad\nreason"),
1384            Err(ChainFieldError::ControlCharacter)
1385        );
1386        for unsafe_value in ["https://user:secret@host/path", "host/path", "host?token=x"] {
1387            assert_eq!(
1388                OutboundAuthority::new(unsafe_value),
1389                Err(ChainFieldError::UnsafeAuthority)
1390            );
1391        }
1392        assert_eq!(
1393            EventContext::new(
1394                RequestIdentity::new("r").unwrap(),
1395                RouteIdentity::new("route").unwrap(),
1396                0
1397            ),
1398            Err(ChainFieldError::ZeroAttempt),
1399        );
1400    }
1401}