agent_engine/runtime/
telemetry.rs

1//! Structured per-request API telemetry.
2//!
3//! Opt-in via the `telemetry` config key (`off` | `basic` | `full`).
4//! Writes one JSON record per API call to `~/.cache/synaps/api-log.jsonl`
5//! (mode 0600, O_NOFOLLOW — same hardening as the legacy usage log).
6//!
7//! `basic` records timing + usage + cost. `full` additionally records
8//! rate-limit headers and cache-diagnostics results when available.
9//!
10//! Writes are best-effort and non-blocking: persistence goes through the
11//! bounded background [`writer`] (Task 11, spec §6.5), so a slow or broken
12//! log path can never delay or fail the request pipeline. Failures are
13//! counted (never silent-and-invisible) with one warning per persistent
14//! failure class.
15
16use serde::Serialize;
17use std::time::{Duration, SystemTime, UNIX_EPOCH};
18
19pub mod writer;
20
21pub use writer::{
22    default_telemetry_log_path, default_trace_log_path, ShutdownOutcome, TelemetryWriter,
23    WriterOptions, WriterStats, WriterTraceSink, DEFAULT_MAX_FILE_BYTES, DEFAULT_QUEUE_CAPACITY,
24    DEFAULT_SHUTDOWN_FLUSH_TIMEOUT,
25};
26
27/// Telemetry verbosity level, parsed from the `telemetry` config key.
28#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)]
29pub enum TelemetryLevel {
30    #[default]
31    Off,
32    Basic,
33    Full,
34}
35
36impl TelemetryLevel {
37    pub fn from_str_key(s: &str) -> Self {
38        match s.trim().to_ascii_lowercase().as_str() {
39            "basic" | "on" | "1" | "true" => Self::Basic,
40            "full" => Self::Full,
41            _ => Self::Off,
42        }
43    }
44
45    pub fn enabled(&self) -> bool {
46        !matches!(self, Self::Off)
47    }
48
49    pub fn as_str(&self) -> &'static str {
50        match self {
51            Self::Off => "off",
52            Self::Basic => "basic",
53            Self::Full => "full",
54        }
55    }
56}
57
58/// Token usage for one API call, including the cache-creation TTL breakdown.
59#[derive(Debug, Clone, Default, Serialize)]
60pub struct UsageRecord {
61    pub input: u64,
62    pub output: u64,
63    pub cache_read: u64,
64    pub cache_write: u64,
65    /// Cache writes with 5-minute TTL (from `usage.cache_creation.ephemeral_5m_input_tokens`).
66    #[serde(skip_serializing_if = "Option::is_none")]
67    pub cache_write_5m: Option<u64>,
68    /// Cache writes with 1-hour TTL (from `usage.cache_creation.ephemeral_1h_input_tokens`).
69    #[serde(skip_serializing_if = "Option::is_none")]
70    pub cache_write_1h: Option<u64>,
71    /// Cache hit percentage: cache_read / (input + cache_read + cache_write) * 100.
72    pub hit_pct: f64,
73}
74
75impl UsageRecord {
76    pub fn compute_hit_pct(&mut self) {
77        let total = self.input + self.cache_read + self.cache_write;
78        self.hit_pct = if total > 0 {
79            (self.cache_read as f64 / total as f64 * 1000.0).round() / 10.0
80        } else {
81            0.0
82        };
83    }
84}
85
86/// Rate-limit headroom captured from `anthropic-ratelimit-*` response headers.
87/// Only recorded at `full` level.
88#[derive(Debug, Clone, Default, Serialize)]
89pub struct RateLimitRecord {
90    #[serde(skip_serializing_if = "Option::is_none")]
91    pub requests_limit: Option<u64>,
92    #[serde(skip_serializing_if = "Option::is_none")]
93    pub requests_remaining: Option<u64>,
94    #[serde(skip_serializing_if = "Option::is_none")]
95    pub tokens_limit: Option<u64>,
96    #[serde(skip_serializing_if = "Option::is_none")]
97    pub tokens_remaining: Option<u64>,
98    #[serde(skip_serializing_if = "Option::is_none")]
99    pub input_tokens_remaining: Option<u64>,
100    #[serde(skip_serializing_if = "Option::is_none")]
101    pub output_tokens_remaining: Option<u64>,
102    /// RFC 3339 timestamp when the most restrictive token limit resets.
103    #[serde(skip_serializing_if = "Option::is_none")]
104    pub tokens_reset: Option<String>,
105}
106
107impl RateLimitRecord {
108    pub fn is_empty(&self) -> bool {
109        self.requests_limit.is_none()
110            && self.requests_remaining.is_none()
111            && self.tokens_limit.is_none()
112            && self.tokens_remaining.is_none()
113            && self.input_tokens_remaining.is_none()
114            && self.output_tokens_remaining.is_none()
115            && self.tokens_reset.is_none()
116    }
117}
118
119/// Cache-diagnostics result (beta `cache-diagnosis-2026-04-07`).
120/// Only present when the user opted in via `cache_diagnostics = true`.
121#[derive(Debug, Clone, Serialize)]
122pub struct CacheDiagRecord {
123    /// `cache_miss_reason.type` — e.g. "system_changed", "tools_changed".
124    pub miss_reason: String,
125    /// `cache_missed_input_tokens` — estimated tokens lost after divergence.
126    #[serde(skip_serializing_if = "Option::is_none")]
127    pub missed_tokens: Option<u64>,
128}
129
130/// Request-shape context: what we sent, for correlating cache behavior.
131#[derive(Debug, Clone, Default, Serialize)]
132pub struct ContextRecord {
133    pub messages: usize,
134    pub tools: usize,
135    pub system_bytes: usize,
136    /// Indices of user messages carrying a conversational cache_control marker.
137    pub breakpoints: Vec<usize>,
138}
139
140/// One JSONL record per API call.
141#[derive(Debug, Clone, Default, Serialize)]
142pub struct TelemetryRecord {
143    /// Unix epoch milliseconds at request completion.
144    pub ts: u64,
145    #[serde(skip_serializing_if = "Option::is_none")]
146    pub request_id: Option<String>,
147    /// Anthropic message id (`msg_...`) from message_start.
148    #[serde(skip_serializing_if = "Option::is_none")]
149    pub msg_id: Option<String>,
150    pub model: String,
151    /// 1-based attempt number that succeeded (1 = no retries).
152    pub attempt: u32,
153    /// Number of refusal retries consumed (0 = no refusals). Present only when > 0.
154    #[serde(skip_serializing_if = "Option::is_none")]
155    pub refusal_retries_used: Option<u32>,
156    /// Milliseconds from request send to first SSE byte.
157    #[serde(skip_serializing_if = "Option::is_none")]
158    pub ttft_ms: Option<u64>,
159    /// Milliseconds from request send to stream close.
160    pub total_ms: u64,
161    #[serde(skip_serializing_if = "Option::is_none")]
162    pub stop_reason: Option<String>,
163    pub usage: UsageRecord,
164    #[serde(skip_serializing_if = "Option::is_none")]
165    pub ratelimit: Option<RateLimitRecord>,
166    #[serde(skip_serializing_if = "Option::is_none")]
167    pub cache_diag: Option<CacheDiagRecord>,
168    pub context: ContextRecord,
169}
170
171impl TelemetryRecord {
172    pub fn now_ms() -> u64 {
173        SystemTime::now()
174            .duration_since(UNIX_EPOCH)
175            .map(|d| d.as_millis() as u64)
176            .unwrap_or(0)
177    }
178}
179
180/// Parse a `u64` rate-limit header value.
181fn header_u64(headers: &reqwest::header::HeaderMap, name: &str) -> Option<u64> {
182    headers.get(name)?.to_str().ok()?.parse().ok()
183}
184
185/// Parse a string rate-limit header value.
186fn header_string(headers: &reqwest::header::HeaderMap, name: &str) -> Option<String> {
187    Some(headers.get(name)?.to_str().ok()?.to_string())
188}
189
190/// Extract rate-limit headroom from response headers.
191pub fn ratelimit_from_headers(headers: &reqwest::header::HeaderMap) -> RateLimitRecord {
192    RateLimitRecord {
193        requests_limit: header_u64(headers, "anthropic-ratelimit-requests-limit"),
194        requests_remaining: header_u64(headers, "anthropic-ratelimit-requests-remaining"),
195        tokens_limit: header_u64(headers, "anthropic-ratelimit-tokens-limit"),
196        tokens_remaining: header_u64(headers, "anthropic-ratelimit-tokens-remaining"),
197        input_tokens_remaining: header_u64(headers, "anthropic-ratelimit-input-tokens-remaining"),
198        output_tokens_remaining: header_u64(headers, "anthropic-ratelimit-output-tokens-remaining"),
199        tokens_reset: header_string(headers, "anthropic-ratelimit-tokens-reset"),
200    }
201}
202
203/// Extract the `request-id` response header.
204pub fn request_id_from_headers(headers: &reqwest::header::HeaderMap) -> Option<String> {
205    header_string(headers, "request-id")
206}
207
208/// Maximum delay we'll honour from any rate-limit header. A pathological reset
209/// timestamp far in the future would otherwise stall the turn indefinitely.
210pub const RETRY_DELAY_CAP: Duration = Duration::from_secs(60);
211
212/// Compute how long to wait before the next retry, consulting response headers.
213///
214/// Priority order:
215///   1. `retry-after` (integer seconds, or an HTTP-date — integer is what
216///      Anthropic sends in practice, HTTP-date is handled as a best-effort
217///      fallback).
218///   2. `anthropic-ratelimit-tokens-reset` / `anthropic-ratelimit-requests-reset`
219///      (RFC 3339 UTC timestamp) — take the *minimum* of whichever is present.
220///   3. Classic exponential back-off: `1s * 2^(attempt-1)` (1 s, 2 s, 4 s …).
221///
222/// The returned duration is capped at [`RETRY_DELAY_CAP`] so a far-future
223/// reset timestamp never hangs the turn forever. `attempt` is 1-based (first
224/// retry = 1).
225///
226/// Returns `(delay, from_header)` — the bool is `true` when a header was
227/// used (callers can emit a more informative notice message).
228pub fn retry_delay_from_headers(
229    headers: &reqwest::header::HeaderMap,
230    attempt: u32,
231) -> (Duration, bool) {
232    let now_secs = SystemTime::now()
233        .duration_since(UNIX_EPOCH)
234        .map(|d| d.as_secs())
235        .unwrap_or(0);
236
237    // ── 1. retry-after (integer seconds preferred) ──────────────────────────
238    if let Some(ra) = header_string(headers, "retry-after") {
239        let ra = ra.trim();
240        // Integer form: "30"
241        if let Ok(secs) = ra.parse::<u64>() {
242            let d = Duration::from_secs(secs).min(RETRY_DELAY_CAP);
243            return (d, true);
244        }
245        // HTTP-date form: "Wed, 11 Jun 2025 01:46:00 GMT" — parse via chrono.
246        if let Ok(dt) = chrono::DateTime::parse_from_rfc2822(ra) {
247            let reset_secs = dt.timestamp().max(0) as u64;
248            let wait = reset_secs.saturating_sub(now_secs);
249            let d = Duration::from_secs(wait).min(RETRY_DELAY_CAP);
250            return (d, true);
251        }
252    }
253
254    // ── 2. anthropic-ratelimit-*-reset (RFC 3339) ───────────────────────────
255    let mut min_wait: Option<u64> = None;
256    for name in &[
257        "anthropic-ratelimit-tokens-reset",
258        "anthropic-ratelimit-requests-reset",
259    ] {
260        if let Some(ts) = header_string(headers, name) {
261            if let Ok(dt) = chrono::DateTime::parse_from_rfc3339(ts.trim()) {
262                let reset_secs = dt.timestamp().max(0) as u64;
263                let wait = reset_secs.saturating_sub(now_secs);
264                min_wait = Some(min_wait.map_or(wait, |prev| prev.min(wait)));
265            }
266        }
267    }
268    if let Some(wait) = min_wait {
269        let d = Duration::from_secs(wait).min(RETRY_DELAY_CAP);
270        return (d, true);
271    }
272
273    // ── 3. Exponential back-off fallback ────────────────────────────────────
274    let d = Duration::from_millis(1000 * 2u64.pow(attempt.saturating_sub(1)));
275    (d, false)
276}
277
278#[cfg(test)]
279mod tests {
280    use super::*;
281
282    #[test]
283    fn level_parses_known_values() {
284        assert_eq!(TelemetryLevel::from_str_key("off"), TelemetryLevel::Off);
285        assert_eq!(TelemetryLevel::from_str_key("basic"), TelemetryLevel::Basic);
286        assert_eq!(TelemetryLevel::from_str_key("full"), TelemetryLevel::Full);
287        assert_eq!(TelemetryLevel::from_str_key("FULL"), TelemetryLevel::Full);
288        assert_eq!(TelemetryLevel::from_str_key("true"), TelemetryLevel::Basic);
289        assert_eq!(TelemetryLevel::from_str_key("garbage"), TelemetryLevel::Off);
290        assert_eq!(TelemetryLevel::from_str_key(""), TelemetryLevel::Off);
291    }
292
293    #[test]
294    fn level_enabled() {
295        assert!(!TelemetryLevel::Off.enabled());
296        assert!(TelemetryLevel::Basic.enabled());
297        assert!(TelemetryLevel::Full.enabled());
298    }
299
300    #[test]
301    fn hit_pct_computation() {
302        let mut u = UsageRecord {
303            input: 100,
304            cache_read: 800,
305            cache_write: 100,
306            ..Default::default()
307        };
308        u.compute_hit_pct();
309        assert_eq!(u.hit_pct, 80.0);
310    }
311
312    #[test]
313    fn hit_pct_zero_total() {
314        let mut u = UsageRecord::default();
315        u.compute_hit_pct();
316        assert_eq!(u.hit_pct, 0.0);
317    }
318
319    #[test]
320    fn hit_pct_rounds_to_one_decimal() {
321        let mut u = UsageRecord {
322            input: 1,
323            cache_read: 2,
324            cache_write: 0,
325            ..Default::default()
326        };
327        u.compute_hit_pct();
328        assert_eq!(u.hit_pct, 66.7);
329    }
330
331    #[test]
332    fn record_serializes_skipping_none_fields() {
333        let record = TelemetryRecord {
334            ts: 1,
335            model: "claude-sonnet-4-6".to_string(),
336            attempt: 1,
337            total_ms: 100,
338            ..Default::default()
339        };
340        let json = serde_json::to_string(&record).unwrap();
341        assert!(!json.contains("request_id"));
342        assert!(!json.contains("ratelimit"));
343        assert!(!json.contains("cache_diag"));
344        assert!(json.contains("\"model\":\"claude-sonnet-4-6\""));
345    }
346
347    #[test]
348    fn ratelimit_empty_detection() {
349        assert!(RateLimitRecord::default().is_empty());
350        let r = RateLimitRecord {
351            requests_remaining: Some(10),
352            ..Default::default()
353        };
354        assert!(!r.is_empty());
355    }
356
357    #[test]
358    fn ratelimit_parses_headers() {
359        let mut headers = reqwest::header::HeaderMap::new();
360        headers.insert(
361            "anthropic-ratelimit-requests-limit",
362            "5000".parse().unwrap(),
363        );
364        headers.insert(
365            "anthropic-ratelimit-requests-remaining",
366            "4900".parse().unwrap(),
367        );
368        headers.insert(
369            "anthropic-ratelimit-tokens-reset",
370            "2026-06-11T01:46:00Z".parse().unwrap(),
371        );
372        let r = ratelimit_from_headers(&headers);
373        assert_eq!(r.requests_limit, Some(5000));
374        assert_eq!(r.requests_remaining, Some(4900));
375        assert_eq!(r.tokens_reset.as_deref(), Some("2026-06-11T01:46:00Z"));
376        assert_eq!(r.tokens_limit, None);
377    }
378
379    #[test]
380    fn ratelimit_ignores_malformed_values() {
381        let mut headers = reqwest::header::HeaderMap::new();
382        headers.insert(
383            "anthropic-ratelimit-requests-limit",
384            "not-a-number".parse().unwrap(),
385        );
386        let r = ratelimit_from_headers(&headers);
387        assert_eq!(r.requests_limit, None);
388    }
389}
390
391#[cfg(test)]
392mod retry_delay_tests {
393    use super::*;
394    use std::time::{Duration, SystemTime, UNIX_EPOCH};
395
396    #[test]
397    fn integer_retry_after() {
398        let mut h = reqwest::header::HeaderMap::new();
399        h.insert("retry-after", "45".parse().unwrap());
400        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
401        assert_eq!(d, Duration::from_secs(45));
402        assert!(from_hdr);
403    }
404
405    #[test]
406    fn integer_retry_after_capped() {
407        let mut h = reqwest::header::HeaderMap::new();
408        h.insert("retry-after", "300".parse().unwrap()); // 5 min — beyond cap
409        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
410        assert_eq!(d, RETRY_DELAY_CAP);
411        assert!(from_hdr);
412    }
413
414    #[test]
415    fn rfc3339_reset_future() {
416        let future_secs = SystemTime::now()
417            .duration_since(UNIX_EPOCH)
418            .unwrap()
419            .as_secs()
420            + 30;
421        let dt = chrono::DateTime::<chrono::Utc>::from_timestamp(future_secs as i64, 0).unwrap();
422        let ts = dt.to_rfc3339();
423
424        let mut h = reqwest::header::HeaderMap::new();
425        h.insert("anthropic-ratelimit-tokens-reset", ts.parse().unwrap());
426        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
427        assert!(
428            d.as_secs() >= 28 && d.as_secs() <= 32,
429            "unexpected delay: {:?}",
430            d
431        );
432        assert!(from_hdr);
433    }
434
435    #[test]
436    fn rfc3339_reset_beyond_cap() {
437        let future_secs = SystemTime::now()
438            .duration_since(UNIX_EPOCH)
439            .unwrap()
440            .as_secs()
441            + 600;
442        let dt = chrono::DateTime::<chrono::Utc>::from_timestamp(future_secs as i64, 0).unwrap();
443        let ts = dt.to_rfc3339();
444
445        let mut h = reqwest::header::HeaderMap::new();
446        h.insert("anthropic-ratelimit-tokens-reset", ts.parse().unwrap());
447        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
448        assert_eq!(d, RETRY_DELAY_CAP);
449        assert!(from_hdr);
450    }
451
452    #[test]
453    fn no_headers_exponential_fallback() {
454        let h = reqwest::header::HeaderMap::new();
455        let (d1, hdr1) = retry_delay_from_headers(&h, 1);
456        let (d2, hdr2) = retry_delay_from_headers(&h, 2);
457        let (d3, hdr3) = retry_delay_from_headers(&h, 3);
458        assert_eq!(d1, Duration::from_secs(1));
459        assert_eq!(d2, Duration::from_secs(2));
460        assert_eq!(d3, Duration::from_secs(4));
461        assert!(!hdr1 && !hdr2 && !hdr3);
462    }
463
464    #[test]
465    fn prefers_retry_after_over_rfc3339() {
466        let future_secs = SystemTime::now()
467            .duration_since(UNIX_EPOCH)
468            .unwrap()
469            .as_secs()
470            + 30;
471        let dt = chrono::DateTime::<chrono::Utc>::from_timestamp(future_secs as i64, 0).unwrap();
472        let ts = dt.to_rfc3339();
473
474        let mut h = reqwest::header::HeaderMap::new();
475        h.insert("retry-after", "10".parse().unwrap());
476        h.insert("anthropic-ratelimit-tokens-reset", ts.parse().unwrap());
477        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
478        assert_eq!(d, Duration::from_secs(10));
479        assert!(from_hdr);
480    }
481
482    #[test]
483    fn min_of_multiple_ratelimit_reset_headers() {
484        // tokens-reset is sooner; requests-reset is later — should pick tokens.
485        let now = SystemTime::now()
486            .duration_since(UNIX_EPOCH)
487            .unwrap()
488            .as_secs();
489        let tokens_dt =
490            chrono::DateTime::<chrono::Utc>::from_timestamp((now + 15) as i64, 0).unwrap();
491        let requests_dt =
492            chrono::DateTime::<chrono::Utc>::from_timestamp((now + 45) as i64, 0).unwrap();
493
494        let mut h = reqwest::header::HeaderMap::new();
495        h.insert(
496            "anthropic-ratelimit-tokens-reset",
497            tokens_dt.to_rfc3339().parse().unwrap(),
498        );
499        h.insert(
500            "anthropic-ratelimit-requests-reset",
501            requests_dt.to_rfc3339().parse().unwrap(),
502        );
503        let (d, from_hdr) = retry_delay_from_headers(&h, 1);
504        assert!(
505            d.as_secs() >= 13 && d.as_secs() <= 17,
506            "should be ~15s, got {:?}",
507            d
508        );
509        assert!(from_hdr);
510    }
511}
agent_engine/runtime/telemetry.rs

agent_engine/runtime/
telemetry.rs
