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#[derive(Clone, Copy, Debug, Eq, PartialEq)]
116pub enum TransactionOutcome {
117 Committed,
119 Rejected,
121 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
135pub 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 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 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); }
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(); 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}