1use super::key::{
31 keyed_digest, load_or_create_digest_key, load_or_create_digest_key_at, DigestDomain,
32 TraceDigestKey,
33};
34use super::types::{
35 CacheMeta, EndpointMeta, MessageMeta, RequestAnatomy, RequestTrace, RetryClass, RetryMeta,
36 StopReason, SystemSegmentMeta, TimingStages, ToolMeta, TraceId, TraceSchemaVersion,
37 TransportKind, TransportOutcome, UsageMeta, WireMeta,
38};
39use agent_core::prompt::QualifiedModelId;
40use agent_core::TurnOutcome;
41use std::path::PathBuf;
42use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
43use std::sync::Arc;
44use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
45
46pub trait TraceSink: Send + Sync + std::fmt::Debug {
51 fn emit(&self, record: RequestTrace);
52 fn enrich_execution_events(
57 &self,
58 _request_id: &TraceId,
59 _events: Vec<super::types::ToolExecutionEvent>,
60 ) {
61 }
62 fn snapshot_for_request(&self, _request_id: &TraceId) -> Option<RequestTrace> {
65 None
66 }
67 fn enabled(&self) -> bool {
69 true
70 }
71}
72
73#[derive(Debug, Default)]
78pub struct NoopTraceSink;
79
80impl TraceSink for NoopTraceSink {
81 fn emit(&self, _record: RequestTrace) {}
82 fn enabled(&self) -> bool {
83 false
84 }
85}
86
87#[derive(Debug, Default)]
89pub struct CollectingTraceSink {
90 records: std::sync::Mutex<Vec<RequestTrace>>,
91}
92
93impl CollectingTraceSink {
94 pub fn new() -> Arc<Self> {
95 Arc::new(Self::default())
96 }
97
98 pub fn records(&self) -> Vec<RequestTrace> {
100 self.records.lock().expect("trace sink poisoned").clone()
101 }
102}
103
104impl TraceSink for CollectingTraceSink {
105 fn emit(&self, record: RequestTrace) {
106 self.records
107 .lock()
108 .expect("trace sink poisoned")
109 .push(record);
110 }
111
112 fn enrich_execution_events(
113 &self,
114 request_id: &TraceId,
115 events: Vec<super::types::ToolExecutionEvent>,
116 ) {
117 if let Some(record) = self
118 .records
119 .lock()
120 .expect("trace sink poisoned")
121 .iter_mut()
122 .rev()
123 .find(|record| &record.request_id == request_id)
124 {
125 record.execution_events = events;
126 }
127 }
128
129 fn snapshot_for_request(&self, request_id: &TraceId) -> Option<RequestTrace> {
130 self.records
131 .lock()
132 .expect("trace sink poisoned")
133 .iter()
134 .rev()
135 .find(|record| &record.request_id == request_id)
136 .cloned()
137 }
138}
139
140#[derive(Clone)]
145pub struct TraceContext {
146 sink: Arc<dyn TraceSink>,
147 session_id: TraceId,
148 key_path: Option<Arc<PathBuf>>,
150 key: Arc<tokio::sync::OnceCell<Option<Arc<TraceDigestKey>>>>,
153 key_warned: Arc<AtomicBool>,
154 degraded: Arc<AtomicU64>,
157 request_seq: Arc<AtomicU64>,
158 cache_snapshots: Arc<super::diagnostics::CacheSnapshotStore>,
161 content_capture: Option<Arc<super::controls::ContentCapture>>,
164 one_shot_gate: Option<Arc<AtomicBool>>,
172 execution_events: Arc<
176 std::sync::Mutex<std::collections::BTreeMap<String, Vec<super::types::ToolExecutionEvent>>>,
177 >,
178}
179
180impl std::fmt::Debug for TraceContext {
181 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
182 f.debug_struct("TraceContext")
183 .field("enabled", &self.sink.enabled())
184 .field("session_id", &self.session_id)
185 .finish_non_exhaustive()
186 }
187}
188
189impl Default for TraceContext {
190 fn default() -> Self {
191 Self::disabled()
192 }
193}
194
195impl TraceContext {
196 pub fn emit_execution_enriched(&self, request_id: &TraceId) {
200 self.sink
201 .enrich_execution_events(request_id, self.execution_events(request_id));
202 }
203
204 pub fn session_id(&self) -> &TraceId {
206 &self.session_id
207 }
208
209 pub fn record_execution_event(&self, event: super::types::ToolExecutionEvent) {
212 self.execution_events
213 .lock()
214 .unwrap_or_else(std::sync::PoisonError::into_inner)
215 .entry(event.request_id.as_str().to_string())
216 .or_default()
217 .push(event);
218 }
219
220 pub fn execution_events(&self, request_id: &TraceId) -> Vec<super::types::ToolExecutionEvent> {
221 self.execution_events
222 .lock()
223 .unwrap_or_else(std::sync::PoisonError::into_inner)
224 .get(request_id.as_str())
225 .cloned()
226 .unwrap_or_default()
227 }
228
229 pub fn latest_request_correlation(&self) -> Option<(TraceId, TraceId, TraceId)> {
231 let seq = self.request_seq.load(Ordering::Relaxed);
232 if seq == 0 {
233 return None;
234 }
235 let pid = std::process::id();
236 Some((
237 self.session_id.clone(),
238 TraceId::new(format!("turn-{pid}-{seq}")).ok()?,
239 TraceId::new(format!("req-{pid}-{seq}")).ok()?,
240 ))
241 }
242
243 pub fn reserve_request_correlation(&self) -> Option<RequestCorrelation> {
244 if !self.enabled() {
245 return None;
246 }
247 let seq = self.next_request_seq();
248 let pid = std::process::id();
249 Some(RequestCorrelation {
250 session_id: self.session_id.clone(),
251 turn_id: TraceId::new(format!("turn-{pid}-{seq}")).ok()?,
252 request_id: TraceId::new(format!("req-{pid}-{seq}")).ok()?,
253 })
254 }
255
256 pub fn disabled() -> Self {
258 Self::with_sink(Arc::new(NoopTraceSink))
259 }
260
261 pub fn with_sink(sink: Arc<dyn TraceSink>) -> Self {
263 static SESSION_SEQ: AtomicU64 = AtomicU64::new(0);
266 let seq = SESSION_SEQ.fetch_add(1, Ordering::Relaxed);
267 let session_id =
268 TraceId::new(format!("session-{}-{}-{seq}", std::process::id(), unix_ms_now()))
269 .expect("generated session id is valid");
270 Self {
271 sink,
272 session_id,
273 key_path: None,
274 key: Arc::new(tokio::sync::OnceCell::new()),
275 key_warned: Arc::new(AtomicBool::new(false)),
276 degraded: Arc::new(AtomicU64::new(0)),
277 request_seq: Arc::new(AtomicU64::new(0)),
278 cache_snapshots: Arc::new(super::diagnostics::CacheSnapshotStore::new()),
279 content_capture: None,
280 one_shot_gate: None,
281 execution_events: Arc::new(std::sync::Mutex::new(std::collections::BTreeMap::new())),
282 }
283 }
284
285 pub fn fork_with_sink(&self, sink: Arc<dyn TraceSink>) -> Self {
292 Self {
293 sink,
294 session_id: self.session_id.clone(),
295 key_path: self.key_path.clone(),
296 key: Arc::clone(&self.key),
297 key_warned: Arc::clone(&self.key_warned),
298 degraded: Arc::clone(&self.degraded),
299 request_seq: Arc::clone(&self.request_seq),
300 cache_snapshots: Arc::clone(&self.cache_snapshots),
301 content_capture: None,
302 one_shot_gate: None,
303 execution_events: Arc::clone(&self.execution_events),
304 }
305 }
306
307 pub fn with_content_capture(mut self, capture: Arc<super::controls::ContentCapture>) -> Self {
309 self.content_capture = Some(capture);
310 self
311 }
312
313 pub fn with_one_shot_request_gate(mut self) -> Self {
318 self.one_shot_gate = Some(Arc::new(AtomicBool::new(false)));
319 self
320 }
321
322 pub fn reopen_one_shot_for_resend(&self) {
329 if let Some(gate) = &self.one_shot_gate {
330 gate.store(false, Ordering::SeqCst);
331 }
332 }
333
334 fn pass_one_shot_gate(&self) -> bool {
337 match &self.one_shot_gate {
338 None => true,
339 Some(gate) => !gate.swap(true, Ordering::SeqCst),
340 }
341 }
342
343 pub fn cache_snapshots(&self) -> &Arc<super::diagnostics::CacheSnapshotStore> {
345 &self.cache_snapshots
346 }
347
348 pub fn capture_request_content(&self, request_id: &TraceId, body_bytes: &[u8]) {
352 if let Some(capture) = &self.content_capture {
353 capture.capture(request_id, body_bytes);
354 }
355 }
356
357 pub fn capture_unsupported(&self, reason: &str) {
365 if let Some(capture) = &self.content_capture {
366 if capture.mark_unsupported() {
367 self.note_degraded();
368 tracing::warn!(
369 reason,
370 "trace content capture unsupported on this provider path; \
371 no capture bundle was written (see /trace status degraded counter)"
372 );
373 }
374 }
375 }
376
377 pub fn with_key_path(mut self, path: PathBuf) -> Self {
379 self.key_path = Some(Arc::new(path));
380 self
381 }
382
383 pub fn enabled(&self) -> bool {
384 self.sink.enabled()
388 && self
389 .one_shot_gate
390 .as_ref()
391 .map(|gate| !gate.load(Ordering::SeqCst))
392 .unwrap_or(true)
393 }
394
395 pub fn degraded_records(&self) -> u64 {
397 self.degraded.load(Ordering::Relaxed)
398 }
399
400 pub async fn digest_key(&self) -> Option<Arc<TraceDigestKey>> {
405 self.key
406 .get_or_init(|| async {
407 let path = self.key_path.clone();
408 let loaded = tokio::task::spawn_blocking(move || match path {
409 Some(p) => load_or_create_digest_key_at(&p),
410 None => load_or_create_digest_key(),
411 })
412 .await;
413 match loaded {
414 Ok(Ok(key)) => Some(Arc::new(key)),
415 Ok(Err(err)) => {
416 self.note_key_failure(&err.to_string());
417 None
418 }
419 Err(join_err) => {
420 self.note_key_failure(&join_err.to_string());
421 None
422 }
423 }
424 })
425 .await
426 .clone()
427 }
428
429 fn note_key_failure(&self, reason: &str) {
430 self.degraded.fetch_add(1, Ordering::Relaxed);
431 if !self.key_warned.swap(true, Ordering::Relaxed) {
432 tracing::warn!(
435 reason,
436 "trace digest key unavailable — traces degrade to digest-free records"
437 );
438 }
439 }
440
441 fn note_degraded(&self) {
442 self.degraded.fetch_add(1, Ordering::Relaxed);
443 }
444
445 fn next_request_seq(&self) -> u64 {
446 self.request_seq.fetch_add(1, Ordering::Relaxed)
447 }
448}
449
450fn unix_ms_now() -> u64 {
451 SystemTime::now()
452 .duration_since(UNIX_EPOCH)
453 .map(|d| d.as_millis() as u64)
454 .unwrap_or(0)
455}
456
457#[derive(Debug, Clone, Copy)]
462pub struct AttemptClock {
463 start: Instant,
464 send_start_unix_ms: u64,
465 headers_ms: Option<u64>,
466 first_byte_ms: Option<u64>,
467 first_model_event_ms: Option<u64>,
468 stream_end_ms: Option<u64>,
469}
470
471impl AttemptClock {
472 pub fn start() -> Self {
474 Self {
475 start: Instant::now(),
476 send_start_unix_ms: unix_ms_now(),
477 headers_ms: None,
478 first_byte_ms: None,
479 first_model_event_ms: None,
480 stream_end_ms: None,
481 }
482 }
483
484 fn elapsed_ms(&self) -> u64 {
485 self.start.elapsed().as_millis() as u64
486 }
487
488 pub fn mark_headers(&mut self) {
490 if self.headers_ms.is_none() {
491 self.headers_ms = Some(self.elapsed_ms());
492 }
493 }
494
495 pub fn mark_first_byte(&mut self) {
497 if self.first_byte_ms.is_none() {
498 self.first_byte_ms = Some(self.elapsed_ms());
499 }
500 }
501
502 pub fn set_first_model_event_after_headers(&mut self, offset_ms: u64) {
505 if self.first_model_event_ms.is_none() {
506 if let Some(headers) = self.headers_ms {
507 self.first_model_event_ms = Some(headers.saturating_add(offset_ms));
508 }
509 }
510 }
511
512 pub fn mark_first_model_event(&mut self) {
518 if self.first_model_event_ms.is_none() {
519 self.first_model_event_ms = Some(self.elapsed_ms());
520 }
521 }
522
523 pub fn set_first_model_event_offset(&mut self, offset_ms: u64) {
529 if self.first_model_event_ms.is_none() {
530 self.first_model_event_ms = Some(offset_ms);
531 }
532 }
533
534 pub fn mark_stream_end(&mut self) {
536 if self.stream_end_ms.is_none() {
537 self.stream_end_ms = Some(self.elapsed_ms());
538 }
539 }
540
541 pub fn first_model_event_ms(&self) -> Option<u64> {
543 self.first_model_event_ms
544 }
545
546 pub fn stream_end_or_now_ms(&self) -> u64 {
548 self.stream_end_ms.unwrap_or_else(|| self.elapsed_ms())
549 }
550
551 fn stages(&self) -> TimingStages {
552 TimingStages {
553 send_start_unix_ms: Some(self.send_start_unix_ms),
554 headers_ms: self.headers_ms,
555 first_byte_ms: self.first_byte_ms,
556 first_model_event_ms: self.first_model_event_ms,
557 stream_end_ms: self.stream_end_ms,
558 }
559 }
560}
561
562#[derive(Debug, Clone, Default)]
568pub struct RequestStructure {
569 pub anatomy: RequestAnatomy,
570 pub wire: Option<WireMeta>,
572 pub system_segments: Vec<SystemSegmentMeta>,
573 pub messages: Vec<MessageMeta>,
574 pub tools: Vec<ToolMeta>,
575 pub cache: CacheMeta,
576 pub translation: Vec<super::types::TranslationLoss>,
579}
580
581pub fn wire_meta_from_sent_bytes(key: &TraceDigestKey, sent_bytes: &[u8]) -> WireMeta {
585 WireMeta {
586 byte_len: sent_bytes.len() as u64,
587 digest: keyed_digest(key, DigestDomain::Wire, sent_bytes),
588 }
589}
590
591#[derive(Debug, Clone, PartialEq, Eq)]
592pub struct RequestCorrelation {
593 pub session_id: TraceId,
594 pub turn_id: TraceId,
595 pub request_id: TraceId,
596}
597
598pub struct RequestTracer {
603 ctx: TraceContext,
604 session_id: TraceId,
605 turn_id: TraceId,
606 request_id: TraceId,
607 model: QualifiedModelId,
608 transport: TransportKind,
609 endpoint: EndpointMeta,
610 structure: RequestStructure,
611 retries: Vec<RetryMeta>,
612 attempt: u32,
613}
614
615impl RequestTracer {
616 pub fn begin(
620 ctx: &TraceContext,
621 correlation: Option<RequestCorrelation>,
622 model: QualifiedModelId,
623 transport: TransportKind,
624 endpoint: EndpointMeta,
625 structure: RequestStructure,
626 ) -> Option<Self> {
627 if !ctx.enabled() {
628 return None;
629 }
630 let correlation = match correlation.or_else(|| ctx.reserve_request_correlation()) {
631 Some(correlation) => correlation,
632 None => {
633 ctx.note_degraded();
634 return None;
635 }
636 };
637 let request_id = correlation.request_id;
638 let turn_id = correlation.turn_id;
639 let session_id = correlation.session_id;
640 if !ctx.pass_one_shot_gate() {
647 return None;
648 }
649 Some(Self {
650 ctx: ctx.clone(),
651 session_id,
652 turn_id,
653 request_id,
654 model,
655 transport,
656 endpoint,
657 structure,
658 retries: Vec::new(),
659 attempt: 1,
660 })
661 }
662
663 pub fn request_id(&self) -> &TraceId {
665 &self.request_id
666 }
667
668 pub fn correlation_ids(&self) -> (&TraceId, &TraceId, &TraceId) {
669 (&self.session_id, &self.turn_id, &self.request_id)
670 }
671
672 #[allow(clippy::too_many_arguments)]
676 pub fn attempt_failed(
677 &mut self,
678 clock: AttemptClock,
679 class: RetryClass,
680 delay: Duration,
681 http_status: Option<u16>,
682 provider_request_id: Option<TraceId>,
683 code: &str,
684 ) {
685 let outcome = TransportOutcome {
686 timings: clock.stages(),
687 retries: self.retries.clone(),
688 provider_request_id,
689 http_status,
690 stop_reason: None,
691 usage: None,
692 terminal: TurnOutcome::ProviderFailed {
693 code: code.to_string(),
694 correlation_id: self.request_id.as_str().to_string(),
695 },
696 };
697 self.emit_record(outcome);
698 self.structure.cache.server_diagnosis = None;
701 self.retries.push(RetryMeta {
702 attempt: self.attempt,
703 class,
704 delay_ms: delay.as_millis() as u64,
705 });
706 self.attempt += 1;
707 }
708
709 #[allow(clippy::too_many_arguments)]
711 pub fn finish(
712 self,
713 clock: AttemptClock,
714 http_status: Option<u16>,
715 provider_request_id: Option<TraceId>,
716 stop_reason: Option<StopReason>,
717 usage: Option<UsageMeta>,
718 terminal: TurnOutcome,
719 ) {
720 let outcome = TransportOutcome {
721 timings: clock.stages(),
722 retries: self.retries.clone(),
723 provider_request_id,
724 http_status,
725 stop_reason,
726 usage,
727 terminal,
728 };
729 self.emit_record(outcome);
730 }
731
732 pub fn failed_terminal(&self, code: &str) -> TurnOutcome {
735 TurnOutcome::ProviderFailed {
736 code: code.to_string(),
737 correlation_id: self.request_id.as_str().to_string(),
738 }
739 }
740
741 pub fn set_server_diagnosis(&mut self, diagnosis: Option<super::ServerCacheDiagnosis>) {
745 self.structure.cache.server_diagnosis = diagnosis;
746 }
747
748 fn emit_record(&self, outcome: TransportOutcome) {
749 let record = RequestTrace {
750 schema: TraceSchemaVersion,
751 session_id: self.session_id.clone(),
752 turn_id: self.turn_id.clone(),
753 request_id: self.request_id.clone(),
754 execution_events: self
755 .ctx
756 .execution_events
757 .lock()
758 .unwrap_or_else(std::sync::PoisonError::into_inner)
759 .get(self.request_id.as_str())
760 .cloned()
761 .unwrap_or_default(),
762 attempt: self.attempt,
763 model: self.model.clone(),
764 transport: self.transport,
765 endpoint: self.endpoint.clone(),
766 anatomy: self.structure.anatomy,
767 wire: self.structure.wire.clone(),
768 system_segments: self.structure.system_segments.clone(),
769 messages: self.structure.messages.clone(),
770 tools: self.structure.tools.clone(),
771 cache: self.structure.cache.clone(),
772 translation_losses: self.structure.translation.clone(),
773 outcome,
774 };
775 self.ctx.sink.emit(record);
776 }
777}