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 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 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 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); }
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(); 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}