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