codex_helper_core/
logging.rs

1use std::fs;
2use std::path::PathBuf;
3use std::sync::atomic::{AtomicU64, Ordering};
4use std::sync::{Mutex, OnceLock};
5use std::time::{SystemTime, UNIX_EPOCH};
6
7use base64::Engine;
8use serde::{Deserialize, Serialize};
9use serde_json::Value as JsonValue;
10
11use crate::config::proxy_home_dir;
12use crate::local_log_store::{LogRetention, append_line};
13use crate::policy_actions::PolicyAction;
14use crate::provider_signals::ProviderSignal;
15use crate::state::{RouteDecisionProvenance, SessionIdentitySource};
16use crate::usage::UsageMetrics;
17
18#[path = "logging/control_trace.rs"]
19mod control_trace_impl;
20
21use control_trace_impl::append_control_trace_payload;
22pub use control_trace_impl::{
23    ControlTraceDetail, ControlTraceLogEntry, control_trace_path, log_retry_trace,
24    read_recent_control_trace_entries,
25};
26
27#[derive(Debug, Clone, Copy)]
28pub struct HttpDebugOptions {
29    pub enabled: bool,
30    pub all: bool,
31    pub max_body_bytes: usize,
32}
33
34#[derive(Debug, Clone, Copy)]
35pub struct HttpWarnOptions {
36    pub enabled: bool,
37    pub all: bool,
38    pub max_body_bytes: usize,
39}
40
41pub fn should_log_request_body_preview() -> bool {
42    // Default OFF: request bodies can be large and often contain sensitive data.
43    // Enable explicitly when debugging request payload issues.
44    env_bool_default("CODEX_HELPER_HTTP_LOG_REQUEST_BODY", false)
45}
46
47pub fn now_ms() -> u64 {
48    SystemTime::now()
49        .duration_since(UNIX_EPOCH)
50        .map(|d| d.as_millis() as u64)
51        .unwrap_or(0)
52}
53
54pub fn request_trace_id(service: &str, request_id: u64) -> String {
55    let service = service.trim();
56    if service.is_empty() {
57        format!("request-{request_id}")
58    } else {
59        format!("{service}-{request_id}")
60    }
61}
62
63fn env_bool(key: &str) -> bool {
64    let Ok(v) = std::env::var(key) else {
65        return false;
66    };
67    matches!(
68        v.trim().to_ascii_lowercase().as_str(),
69        "1" | "true" | "yes" | "y" | "on"
70    )
71}
72
73fn env_bool_default(key: &str, default: bool) -> bool {
74    match std::env::var(key) {
75        Ok(v) => matches!(
76            v.trim().to_ascii_lowercase().as_str(),
77            "1" | "true" | "yes" | "y" | "on"
78        ),
79        Err(_) => default,
80    }
81}
82
83pub fn http_debug_options() -> HttpDebugOptions {
84    static OPT: OnceLock<HttpDebugOptions> = OnceLock::new();
85    *OPT.get_or_init(|| {
86        let enabled = env_bool("CODEX_HELPER_HTTP_DEBUG");
87        let all = env_bool("CODEX_HELPER_HTTP_DEBUG_ALL");
88        let max_body_bytes = std::env::var("CODEX_HELPER_HTTP_DEBUG_BODY_MAX")
89            .ok()
90            .and_then(|s| s.trim().parse::<usize>().ok())
91            .filter(|&n| n > 0)
92            .unwrap_or(64 * 1024);
93        HttpDebugOptions {
94            enabled,
95            all,
96            max_body_bytes,
97        }
98    })
99}
100
101pub fn http_warn_options() -> HttpWarnOptions {
102    static OPT: OnceLock<HttpWarnOptions> = OnceLock::new();
103    *OPT.get_or_init(|| {
104        // Default ON: for non-2xx, record a small header/body preview to help debug upstream errors.
105        // Set CODEX_HELPER_HTTP_WARN=0 to disable.
106        let enabled = env_bool_default("CODEX_HELPER_HTTP_WARN", true);
107        let all = env_bool_default("CODEX_HELPER_HTTP_WARN_ALL", false);
108        let max_body_bytes = std::env::var("CODEX_HELPER_HTTP_WARN_BODY_MAX")
109            .ok()
110            .and_then(|s| s.trim().parse::<usize>().ok())
111            .filter(|&n| n > 0)
112            .unwrap_or(8 * 1024);
113        HttpWarnOptions {
114            enabled,
115            all,
116            max_body_bytes,
117        }
118    })
119}
120
121pub fn should_include_http_debug(status_code: u16) -> bool {
122    let opt = http_debug_options();
123    if !opt.enabled {
124        return false;
125    }
126    if opt.all {
127        return true;
128    }
129    !(200..300).contains(&status_code)
130}
131
132pub fn should_include_http_warn(status_code: u16) -> bool {
133    let opt = http_warn_options();
134    if !opt.enabled {
135        return false;
136    }
137    if opt.all {
138        return true;
139    }
140    !(200..300).contains(&status_code)
141}
142
143#[derive(Debug, Serialize, Clone)]
144pub struct HeaderEntry {
145    pub name: String,
146    pub value: String,
147}
148
149#[derive(Debug, Serialize, Clone)]
150pub struct AuthResolutionLog {
151    /// Where the upstream `Authorization` header value came from (never includes the secret).
152    #[serde(skip_serializing_if = "Option::is_none")]
153    pub authorization: Option<String>,
154    /// Where the upstream `X-API-Key` header value came from (never includes the secret).
155    #[serde(skip_serializing_if = "Option::is_none")]
156    pub x_api_key: Option<String>,
157}
158
159#[derive(Debug, Serialize, Clone)]
160pub struct BodyPreview {
161    #[serde(skip_serializing_if = "Option::is_none")]
162    pub content_type: Option<String>,
163    pub encoding: String,
164    pub data: String,
165    pub truncated: bool,
166    pub original_len: usize,
167}
168
169fn normalize_content_type(content_type: Option<&str>) -> Option<&str> {
170    let ct = content_type?.trim();
171    let (base, _) = ct.split_once(';').unwrap_or((ct, ""));
172    let base = base.trim();
173    if base.is_empty() { None } else { Some(base) }
174}
175
176fn is_textual_content_type(content_type: Option<&str>) -> bool {
177    let Some(ct) = normalize_content_type(content_type) else {
178        return false;
179    };
180    ct.starts_with("text/")
181        || ct == "application/json"
182        || ct.ends_with("+json")
183        || ct == "application/x-www-form-urlencoded"
184        || ct == "application/xml"
185        || ct.ends_with("+xml")
186        || ct == "text/event-stream"
187}
188
189pub fn make_body_preview(bytes: &[u8], content_type: Option<&str>, max: usize) -> BodyPreview {
190    let original_len = bytes.len();
191    let take = original_len.min(max);
192    let truncated = original_len > take;
193    let slice = &bytes[..take];
194
195    if is_textual_content_type(content_type) {
196        let text = String::from_utf8_lossy(slice).into_owned();
197        return BodyPreview {
198            content_type: normalize_content_type(content_type).map(|s| s.to_string()),
199            encoding: "utf8".to_string(),
200            data: text,
201            truncated,
202            original_len,
203        };
204    }
205
206    let b64 = base64::engine::general_purpose::STANDARD.encode(slice);
207    BodyPreview {
208        content_type: normalize_content_type(content_type).map(|s| s.to_string()),
209        encoding: "base64".to_string(),
210        data: b64,
211        truncated,
212        original_len,
213    }
214}
215
216#[derive(Debug, Serialize, Clone)]
217pub struct HttpDebugLog {
218    #[serde(skip_serializing_if = "Option::is_none")]
219    pub request_body_len: Option<usize>,
220    #[serde(skip_serializing_if = "Option::is_none")]
221    pub upstream_request_body_len: Option<usize>,
222    /// Time spent waiting for upstream response headers (ms), measured from just before sending the upstream request.
223    #[serde(skip_serializing_if = "Option::is_none")]
224    pub upstream_headers_ms: Option<u64>,
225    /// Time to first upstream response body chunk (ms), measured from just before sending the upstream request.
226    #[serde(skip_serializing_if = "Option::is_none")]
227    pub upstream_first_chunk_ms: Option<u64>,
228    /// Time spent reading upstream response body to completion (ms). Only meaningful for non-stream responses.
229    #[serde(skip_serializing_if = "Option::is_none")]
230    pub upstream_body_read_ms: Option<u64>,
231    /// A coarse classification for upstream non-2xx responses (e.g. Cloudflare challenge).
232    #[serde(skip_serializing_if = "Option::is_none")]
233    pub upstream_error_class: Option<String>,
234    /// A human-readable hint to help diagnose upstream non-2xx responses.
235    #[serde(skip_serializing_if = "Option::is_none")]
236    pub upstream_error_hint: Option<String>,
237    /// Cloudflare request id when present (from `cf-ray` response header).
238    #[serde(skip_serializing_if = "Option::is_none")]
239    pub upstream_cf_ray: Option<String>,
240    pub client_uri: String,
241    pub target_url: String,
242    pub client_headers: Vec<HeaderEntry>,
243    pub upstream_request_headers: Vec<HeaderEntry>,
244    #[serde(skip_serializing_if = "Option::is_none")]
245    pub auth_resolution: Option<AuthResolutionLog>,
246    #[serde(skip_serializing_if = "Option::is_none")]
247    pub client_body: Option<BodyPreview>,
248    #[serde(skip_serializing_if = "Option::is_none")]
249    pub upstream_request_body: Option<BodyPreview>,
250    #[serde(skip_serializing_if = "Option::is_none")]
251    pub upstream_response_headers: Option<Vec<HeaderEntry>>,
252    #[serde(skip_serializing_if = "Option::is_none")]
253    pub upstream_response_body: Option<BodyPreview>,
254    #[serde(skip_serializing_if = "Option::is_none")]
255    pub upstream_error: Option<String>,
256}
257
258#[derive(Debug, Serialize, Deserialize, Clone, Default, PartialEq, Eq)]
259pub struct ServiceTierLog {
260    #[serde(skip_serializing_if = "Option::is_none")]
261    pub requested: Option<String>,
262    #[serde(skip_serializing_if = "Option::is_none")]
263    pub effective: Option<String>,
264    #[serde(skip_serializing_if = "Option::is_none")]
265    pub actual: Option<String>,
266}
267
268fn service_tier_log_is_empty(value: &ServiceTierLog) -> bool {
269    value.requested.is_none() && value.effective.is_none() && value.actual.is_none()
270}
271
272#[derive(Debug, Serialize, Deserialize, Clone, Default, PartialEq, Eq)]
273pub struct CodexBridgeLog {
274    pub patch_mode: String,
275    #[serde(default, skip_serializing_if = "bool_is_false")]
276    pub remote_compaction_v1_request: bool,
277    #[serde(default, skip_serializing_if = "bool_is_false")]
278    pub remote_compaction_v2_request: bool,
279    #[serde(default, skip_serializing_if = "bool_is_false")]
280    pub downgraded_to_responses_compact: bool,
281    #[serde(default, skip_serializing_if = "bool_is_false")]
282    pub responses_websocket_request: bool,
283    #[serde(default, skip_serializing_if = "bool_is_false")]
284    pub strips_client_auth: bool,
285}
286
287#[derive(Debug, Serialize)]
288pub struct RequestLog<'a> {
289    pub timestamp_ms: u64,
290    #[serde(skip_serializing_if = "Option::is_none")]
291    pub request_id: Option<u64>,
292    #[serde(skip_serializing_if = "Option::is_none")]
293    pub trace_id: Option<String>,
294    pub service: &'a str,
295    pub method: &'a str,
296    pub path: &'a str,
297    pub status_code: u16,
298    pub duration_ms: u64,
299    /// Time to first byte / first chunk from the upstream (ms).
300    /// - For streaming responses: measured to the first response body chunk.
301    /// - For non-streaming responses: measured to response headers.
302    #[serde(skip_serializing_if = "Option::is_none")]
303    pub ttfb_ms: Option<u64>,
304    #[serde(skip_serializing_if = "Option::is_none")]
305    pub station_name: Option<&'a str>,
306    #[serde(skip_serializing_if = "Option::is_none")]
307    pub provider_id: Option<String>,
308    #[serde(skip_serializing_if = "Option::is_none")]
309    pub endpoint_id: Option<String>,
310    #[serde(skip_serializing_if = "Option::is_none")]
311    pub provider_endpoint_key: Option<String>,
312    pub upstream_base_url: &'a str,
313    #[serde(skip_serializing_if = "Option::is_none")]
314    pub session_id: Option<String>,
315    #[serde(skip_serializing_if = "Option::is_none")]
316    pub session_identity_source: Option<SessionIdentitySource>,
317    #[serde(skip_serializing_if = "Option::is_none")]
318    pub cwd: Option<String>,
319    #[serde(skip_serializing_if = "Option::is_none")]
320    pub model: Option<String>,
321    #[serde(skip_serializing_if = "Option::is_none")]
322    pub reasoning_effort: Option<String>,
323    #[serde(skip_serializing_if = "service_tier_log_is_empty", default)]
324    pub service_tier: ServiceTierLog,
325    #[serde(skip_serializing_if = "Option::is_none")]
326    pub codex_bridge: Option<CodexBridgeLog>,
327    #[serde(skip_serializing_if = "Option::is_none")]
328    pub usage: Option<UsageMetrics>,
329    #[serde(skip_serializing_if = "Option::is_none")]
330    pub http_debug: Option<HttpDebugLog>,
331    #[serde(skip_serializing_if = "Option::is_none")]
332    pub http_debug_ref: Option<HttpDebugRef>,
333    #[serde(skip_serializing_if = "Option::is_none")]
334    pub route_decision: Option<RouteDecisionProvenance>,
335    #[serde(skip_serializing_if = "Option::is_none")]
336    pub retry: Option<RetryInfo>,
337    #[serde(default, skip_serializing_if = "provider_signals_is_empty")]
338    pub provider_signals: Vec<ProviderSignal>,
339    #[serde(default, skip_serializing_if = "policy_actions_is_empty")]
340    pub policy_actions: Vec<PolicyAction>,
341}
342
343#[derive(Debug, Serialize, Clone)]
344pub struct HttpDebugRef {
345    pub id: String,
346    pub file: String,
347}
348
349fn route_attempts_is_empty(value: &[RouteAttemptLog]) -> bool {
350    value.is_empty()
351}
352
353fn route_attempt_avoid_for_station_is_empty(value: &[usize]) -> bool {
354    value.is_empty()
355}
356
357fn route_attempt_avoided_candidate_indices_is_empty(value: &[usize]) -> bool {
358    value.is_empty()
359}
360
361fn route_attempt_route_path_is_empty(value: &[String]) -> bool {
362    value.is_empty()
363}
364
365fn provider_signals_is_empty(value: &[ProviderSignal]) -> bool {
366    value.is_empty()
367}
368
369fn policy_actions_is_empty(value: &[PolicyAction]) -> bool {
370    value.is_empty()
371}
372
373fn provider_signals_from_retry(retry: Option<&RetryInfo>) -> Vec<ProviderSignal> {
374    retry
375        .into_iter()
376        .flat_map(|retry| retry.route_attempts.iter())
377        .flat_map(|attempt| attempt.provider_signals.iter().cloned())
378        .collect()
379}
380
381fn policy_actions_from_retry(retry: Option<&RetryInfo>) -> Vec<PolicyAction> {
382    retry
383        .into_iter()
384        .flat_map(|retry| retry.route_attempts.iter())
385        .flat_map(|attempt| attempt.policy_actions.iter().cloned())
386        .collect()
387}
388
389fn bool_is_false(value: &bool) -> bool {
390    !*value
391}
392
393#[derive(Debug, Serialize, Deserialize, Clone, PartialEq, Eq, Default)]
394pub struct RouteAttemptLog {
395    pub attempt_index: u32,
396    #[serde(skip_serializing_if = "Option::is_none")]
397    pub provider_id: Option<String>,
398    #[serde(skip_serializing_if = "Option::is_none")]
399    pub endpoint_id: Option<String>,
400    #[serde(skip_serializing_if = "Option::is_none")]
401    pub provider_endpoint_key: Option<String>,
402    #[serde(skip_serializing_if = "Option::is_none")]
403    pub preference_group: Option<u32>,
404    #[serde(default, skip_serializing_if = "route_attempt_route_path_is_empty")]
405    pub route_path: Vec<String>,
406    #[serde(skip_serializing_if = "Option::is_none")]
407    pub provider_attempt: Option<u32>,
408    #[serde(skip_serializing_if = "Option::is_none")]
409    pub upstream_attempt: Option<u32>,
410    #[serde(skip_serializing_if = "Option::is_none")]
411    pub provider_max_attempts: Option<u32>,
412    #[serde(skip_serializing_if = "Option::is_none")]
413    pub upstream_max_attempts: Option<u32>,
414    #[serde(default, skip_serializing)]
415    pub station_name: Option<String>,
416    #[serde(skip_serializing_if = "Option::is_none")]
417    pub upstream_base_url: Option<String>,
418    #[serde(default, skip_serializing)]
419    pub upstream_index: Option<usize>,
420    #[serde(
421        default,
422        skip_serializing_if = "route_attempt_avoid_for_station_is_empty"
423    )]
424    pub avoid_for_station: Vec<usize>,
425    #[serde(
426        default,
427        skip_serializing_if = "route_attempt_avoided_candidate_indices_is_empty"
428    )]
429    pub avoided_candidate_indices: Vec<usize>,
430    #[serde(skip_serializing_if = "Option::is_none")]
431    pub avoided_total: Option<usize>,
432    #[serde(skip_serializing_if = "Option::is_none")]
433    pub total_upstreams: Option<usize>,
434    pub decision: String,
435    #[serde(default, skip_serializing_if = "Option::is_none")]
436    pub code: Option<String>,
437    #[serde(skip_serializing_if = "Option::is_none")]
438    pub reason: Option<String>,
439    #[serde(skip_serializing_if = "Option::is_none")]
440    pub status_code: Option<u16>,
441    #[serde(skip_serializing_if = "Option::is_none")]
442    pub error_class: Option<String>,
443    #[serde(skip_serializing_if = "Option::is_none")]
444    pub model: Option<String>,
445    #[serde(skip_serializing_if = "Option::is_none")]
446    pub upstream_headers_ms: Option<u64>,
447    #[serde(skip_serializing_if = "Option::is_none")]
448    pub duration_ms: Option<u64>,
449    #[serde(skip_serializing_if = "Option::is_none")]
450    pub cooldown_secs: Option<u64>,
451    #[serde(skip_serializing_if = "Option::is_none")]
452    pub cooldown_reason: Option<String>,
453    #[serde(default, skip_serializing_if = "provider_signals_is_empty")]
454    pub provider_signals: Vec<ProviderSignal>,
455    #[serde(default, skip_serializing_if = "policy_actions_is_empty")]
456    pub policy_actions: Vec<PolicyAction>,
457    #[serde(default, skip_serializing_if = "bool_is_false")]
458    pub skipped: bool,
459    pub raw: String,
460}
461
462#[derive(Debug, Serialize, Deserialize, Clone, PartialEq, Eq)]
463pub struct RetryInfo {
464    pub attempts: u32,
465    pub upstream_chain: Vec<String>,
466    #[serde(default, skip_serializing_if = "route_attempts_is_empty")]
467    pub route_attempts: Vec<RouteAttemptLog>,
468}
469
470impl RouteAttemptLog {
471    pub fn stable_code(&self) -> &str {
472        self.code.as_deref().unwrap_or_else(|| {
473            route_attempt_code(
474                self.decision.as_str(),
475                self.error_class.as_deref(),
476                self.reason.as_deref(),
477                self.skipped,
478            )
479        })
480    }
481
482    pub fn refresh_code(&mut self) {
483        self.code = Some(
484            route_attempt_code(
485                self.decision.as_str(),
486                self.error_class.as_deref(),
487                self.reason.as_deref(),
488                self.skipped,
489            )
490            .to_string(),
491        );
492    }
493}
494
495impl RetryInfo {
496    pub fn route_attempts_or_derived(&self) -> Vec<RouteAttemptLog> {
497        if self.route_attempts.is_empty() {
498            parse_route_attempts_from_chain(&self.upstream_chain)
499        } else {
500            self.route_attempts.clone()
501        }
502    }
503
504    pub fn touches_station(&self, station_name: &str) -> bool {
505        let station_name = station_name.trim();
506        if station_name.is_empty() {
507            return false;
508        }
509        self.route_attempts_or_derived()
510            .iter()
511            .any(|attempt| attempt.station_name.as_deref() == Some(station_name))
512    }
513
514    pub fn touched_other_station(&self, final_station: Option<&str>) -> bool {
515        let Some(final_station) = final_station
516            .map(str::trim)
517            .filter(|station| !station.is_empty())
518        else {
519            return false;
520        };
521
522        self.route_attempts_or_derived()
523            .iter()
524            .filter_map(|attempt| attempt.station_name.as_deref())
525            .any(|station| station != final_station)
526    }
527}
528
529pub(crate) fn parse_route_attempts_from_chain(chain: &[String]) -> Vec<RouteAttemptLog> {
530    chain
531        .iter()
532        .enumerate()
533        .map(|(idx, raw)| parse_route_attempt_from_chain_entry(raw, idx as u32))
534        .collect()
535}
536
537fn parse_route_attempt_from_chain_entry(raw: &str, attempt_index: u32) -> RouteAttemptLog {
538    let raw = raw.trim();
539    let mut attempt = RouteAttemptLog {
540        attempt_index,
541        decision: "observed".to_string(),
542        raw: raw.to_string(),
543        ..Default::default()
544    };
545
546    if raw.starts_with("all_upstreams_avoided") {
547        attempt.decision = "all_upstreams_avoided".to_string();
548        attempt.reason = route_chain_value(raw, "total").map(|total| format!("total={total}"));
549        attempt.skipped = true;
550        attempt.refresh_code();
551        return attempt;
552    }
553
554    let (target, metadata, upstream_index) = split_route_chain_entry(raw);
555    attempt.upstream_index = upstream_index;
556    if let Some(target) = target {
557        let (station_name, upstream_base_url) = parse_route_chain_target(target);
558        attempt.station_name = station_name;
559        attempt.upstream_base_url = upstream_base_url;
560    }
561    apply_route_chain_identity_metadata(&mut attempt, raw);
562
563    if let Some(status_code) =
564        route_chain_value(metadata, "status").and_then(|value| value.parse::<u16>().ok())
565    {
566        attempt.status_code = Some(status_code);
567        attempt.decision = if (200..300).contains(&status_code) {
568            "completed".to_string()
569        } else {
570            "failed_status".to_string()
571        };
572    }
573
574    if let Some(error_class) =
575        route_chain_value(metadata, "class").filter(|value| !value.eq_ignore_ascii_case("-"))
576    {
577        if matches!(
578            error_class.as_str(),
579            "reasoning_guard_triggered" | "reasoning_guard_blocked"
580        ) {
581            attempt.decision = "failed_reasoning_guard".to_string();
582        }
583        attempt.error_class = Some(error_class);
584    }
585    if let Some(reason) = route_chain_value(metadata, "reason") {
586        attempt.reason = Some(reason);
587    }
588    if let Some(model) = route_chain_value(metadata, "model") {
589        attempt.model = Some(model);
590    }
591
592    if let Some(model) = route_chain_value(metadata, "skipped_unsupported_model") {
593        attempt.decision = "skipped_capability_mismatch".to_string();
594        attempt.reason = Some("unsupported_model".to_string());
595        attempt.model = Some(model);
596        attempt.skipped = true;
597    }
598
599    if let Some(error) = route_chain_value(metadata, "transport_error") {
600        attempt.decision = "failed_transport".to_string();
601        attempt.reason = Some(error);
602        attempt.error_class = Some("upstream_transport_error".to_string());
603    }
604
605    if let Some(error) = route_chain_value(metadata, "target_build_error") {
606        attempt.decision = "failed_target_build".to_string();
607        attempt.reason = Some(error);
608        attempt.error_class = Some("target_build_error".to_string());
609    }
610
611    if let Some(error) = route_chain_value(metadata, "body_read_error") {
612        attempt.decision = "failed_body_read".to_string();
613        attempt.reason = Some(error);
614        attempt.error_class = Some("upstream_body_read_error".to_string());
615    }
616    if let Some(error) = route_chain_value(metadata, "body_too_large") {
617        attempt.decision = "failed_body_too_large".to_string();
618        attempt.reason = Some(error);
619        attempt.error_class = Some("upstream_response_body_too_large".to_string());
620    }
621
622    attempt.refresh_code();
623    attempt
624}
625
626fn route_attempt_code(
627    decision: &str,
628    error_class: Option<&str>,
629    reason: Option<&str>,
630    skipped: bool,
631) -> &'static str {
632    if matches!(
633        error_class,
634        Some("reasoning_guard_triggered" | "reasoning_guard_blocked")
635    ) {
636        return "failed_reasoning_guard";
637    }
638    if skipped && reason == Some("unsupported_model") {
639        return "skipped_capability_mismatch";
640    }
641    match decision {
642        "selected" => "selected",
643        "observed" => "observed",
644        "completed" => "completed",
645        "failed_status" => "failed_status",
646        "failed_client_request" => "failed_client_request",
647        "failed_reasoning_guard" => "failed_reasoning_guard",
648        "failed_transport" => "failed_transport",
649        "failed_target_build" => "failed_target_build",
650        "failed_body_read" => "failed_body_read",
651        "failed_body_too_large" => "failed_body_too_large",
652        "skipped_capability_mismatch" => "skipped_capability_mismatch",
653        "all_upstreams_avoided" => "all_upstreams_avoided",
654        "route_unavailable" => "route_unavailable",
655        _ => "legacy_route_attempt",
656    }
657}
658
659fn apply_route_chain_identity_metadata(attempt: &mut RouteAttemptLog, raw: &str) {
660    if let Some(station) = route_chain_value(raw, "station") {
661        attempt.station_name = non_empty_str(station.as_str()).map(ToOwned::to_owned);
662    }
663    if let Some(provider_endpoint_key) = route_chain_value(raw, "endpoint") {
664        let provider_endpoint_key = provider_endpoint_key.trim().to_string();
665        if !provider_endpoint_key.is_empty() && provider_endpoint_key != "-" {
666            let parts = provider_endpoint_key.split('/').collect::<Vec<_>>();
667            if parts.len() >= 3 {
668                attempt.provider_id = non_empty_str(parts[1]).map(ToOwned::to_owned);
669                attempt.endpoint_id = non_empty_str(parts[2]).map(ToOwned::to_owned);
670            }
671            attempt.provider_endpoint_key = Some(provider_endpoint_key);
672        }
673    }
674    if let Some(group) = route_chain_value(raw, "group").and_then(|value| value.parse::<u32>().ok())
675    {
676        attempt.preference_group = Some(group);
677    }
678    if let Some(station) = route_chain_value(raw, "compat_station") {
679        attempt.station_name = non_empty_str(station.as_str()).map(ToOwned::to_owned);
680    }
681    if let Some(index) =
682        route_chain_value(raw, "upstream_index").and_then(|value| value.parse::<usize>().ok())
683    {
684        attempt.upstream_index = Some(index);
685    }
686    if let Some(url) = route_chain_value(raw, "url") {
687        attempt.upstream_base_url = non_empty_str(url.as_str()).map(ToOwned::to_owned);
688    }
689    if let Some(indices) = route_chain_value(raw, "avoid_candidates") {
690        attempt.avoided_candidate_indices = parse_usize_list(indices.as_str());
691    }
692    if let Some(indices) = route_chain_value(raw, "avoid") {
693        attempt.avoid_for_station = parse_usize_list(indices.as_str());
694    }
695}
696
697fn parse_usize_list(raw: &str) -> Vec<usize> {
698    raw.split(',')
699        .filter_map(|part| part.trim().parse::<usize>().ok())
700        .collect()
701}
702
703fn split_route_chain_entry(raw: &str) -> (Option<&str>, &str, Option<usize>) {
704    if let Some(idx_start) = raw.find(" (idx=") {
705        let target = raw[..idx_start].trim();
706        let after_idx = &raw[idx_start + " (idx=".len()..];
707        if let Some(idx_end) = after_idx.find(')') {
708            let upstream_index = after_idx[..idx_end].trim().parse::<usize>().ok();
709            let metadata = after_idx[idx_end + 1..].trim();
710            return (non_empty_str(target), metadata, upstream_index);
711        }
712        return (non_empty_str(target), after_idx.trim(), None);
713    }
714
715    if let Some(metadata_start) = first_route_chain_key_start(raw) {
716        let target = raw[..metadata_start].trim();
717        let metadata = raw[metadata_start..].trim();
718        return (non_empty_str(target), metadata, None);
719    }
720
721    (non_empty_str(raw), "", None)
722}
723
724fn parse_route_chain_target(target: &str) -> (Option<String>, Option<String>) {
725    let target = target.trim();
726    if target.is_empty() {
727        return (None, None);
728    }
729    if target.starts_with("http://") || target.starts_with("https://") {
730        return (None, Some(target.to_string()));
731    }
732
733    if let Some(pos) = target.find(":http://").or_else(|| target.find(":https://")) {
734        let station = target[..pos].trim();
735        let base_url = target[pos + 1..].trim();
736        return (
737            non_empty_str(station).map(ToOwned::to_owned),
738            non_empty_str(base_url).map(ToOwned::to_owned),
739        );
740    }
741
742    (None, Some(target.to_string()))
743}
744
745fn first_route_chain_key_start(raw: &str) -> Option<usize> {
746    ROUTE_CHAIN_KEYS
747        .iter()
748        .filter_map(|key| find_route_chain_key(raw, format!("{key}=").as_str()))
749        .min()
750}
751
752fn route_chain_value(raw: &str, key: &str) -> Option<String> {
753    let needle = format!("{key}=");
754    let start = find_route_chain_key(raw, needle.as_str())?;
755    let value_start = start + needle.len();
756    let value_end = ROUTE_CHAIN_KEYS
757        .iter()
758        .filter(|candidate| **candidate != key)
759        .filter_map(|candidate| {
760            raw[value_start..]
761                .find(&format!(" {candidate}="))
762                .map(|offset| value_start + offset)
763        })
764        .min()
765        .unwrap_or(raw.len());
766    non_empty_str(raw[value_start..value_end].trim()).map(ToOwned::to_owned)
767}
768
769fn find_route_chain_key(raw: &str, needle: &str) -> Option<usize> {
770    let mut offset = 0usize;
771    while let Some(pos) = raw[offset..].find(needle) {
772        let absolute = offset + pos;
773        if absolute == 0 || raw[..absolute].ends_with(' ') {
774            return Some(absolute);
775        }
776        offset = absolute + needle.len();
777    }
778    None
779}
780
781fn non_empty_str(value: &str) -> Option<&str> {
782    let value = value.trim();
783    if value.is_empty() { None } else { Some(value) }
784}
785
786const ROUTE_CHAIN_KEYS: &[&str] = &[
787    "status",
788    "class",
789    "model",
790    "transport_error",
791    "target_build_error",
792    "body_read_error",
793    "body_too_large",
794    "skipped_unsupported_model",
795    "total",
796    "station",
797    "endpoint",
798    "group",
799    "compat_station",
800    "upstream_index",
801    "url",
802    "avoid_candidates",
803    "avoid",
804];
805
806#[derive(Debug, Serialize)]
807struct HttpDebugLogEntry<'a> {
808    pub id: &'a str,
809    pub timestamp_ms: u64,
810    #[serde(skip_serializing_if = "Option::is_none")]
811    pub request_id: Option<u64>,
812    #[serde(skip_serializing_if = "Option::is_none")]
813    pub trace_id: Option<String>,
814    pub service: &'a str,
815    pub method: &'a str,
816    pub path: &'a str,
817    pub status_code: u16,
818    pub duration_ms: u64,
819    #[serde(skip_serializing_if = "Option::is_none")]
820    pub ttfb_ms: Option<u64>,
821    #[serde(skip_serializing_if = "Option::is_none")]
822    pub station_name: Option<&'a str>,
823    #[serde(skip_serializing_if = "Option::is_none")]
824    pub provider_id: Option<String>,
825    #[serde(skip_serializing_if = "Option::is_none")]
826    pub endpoint_id: Option<String>,
827    #[serde(skip_serializing_if = "Option::is_none")]
828    pub provider_endpoint_key: Option<String>,
829    pub upstream_base_url: &'a str,
830    #[serde(skip_serializing_if = "Option::is_none")]
831    pub session_id: Option<String>,
832    #[serde(skip_serializing_if = "Option::is_none")]
833    pub session_identity_source: Option<SessionIdentitySource>,
834    #[serde(skip_serializing_if = "Option::is_none")]
835    pub cwd: Option<String>,
836    #[serde(skip_serializing_if = "Option::is_none")]
837    pub model: Option<String>,
838    #[serde(skip_serializing_if = "Option::is_none")]
839    pub reasoning_effort: Option<String>,
840    #[serde(skip_serializing_if = "service_tier_log_is_empty", default)]
841    pub service_tier: ServiceTierLog,
842    #[serde(skip_serializing_if = "Option::is_none")]
843    pub codex_bridge: Option<CodexBridgeLog>,
844    #[serde(skip_serializing_if = "Option::is_none")]
845    pub usage: Option<UsageMetrics>,
846    #[serde(skip_serializing_if = "Option::is_none")]
847    pub route_decision: Option<RouteDecisionProvenance>,
848    #[serde(skip_serializing_if = "Option::is_none")]
849    pub retry: Option<RetryInfo>,
850    pub http_debug: HttpDebugLog,
851}
852
853#[derive(Debug, Clone, Copy)]
854struct RequestLogOptions {
855    retention: LogRetention,
856    only_errors: bool,
857}
858
859pub fn request_log_path() -> PathBuf {
860    proxy_home_dir().join("logs").join("requests.jsonl")
861}
862
863fn debug_log_path() -> PathBuf {
864    proxy_home_dir().join("logs").join("requests_debug.jsonl")
865}
866
867fn log_lock() -> &'static Mutex<()> {
868    static LOCK: OnceLock<Mutex<()>> = OnceLock::new();
869    LOCK.get_or_init(|| Mutex::new(()))
870}
871
872fn http_debug_split_enabled() -> bool {
873    // When HTTP debug is enabled for all requests, splitting is strongly recommended to keep
874    // the main request log lightweight. Users can also enable splitting explicitly.
875    env_bool_default("CODEX_HELPER_HTTP_DEBUG_SPLIT", true) || http_debug_options().all
876}
877
878fn request_log_options() -> RequestLogOptions {
879    static OPT: OnceLock<RequestLogOptions> = OnceLock::new();
880    *OPT.get_or_init(|| {
881        let retention = LogRetention::from_env(
882            "CODEX_HELPER_REQUEST_LOG_MAX_BYTES",
883            "CODEX_HELPER_REQUEST_LOG_MAX_FILES",
884            50 * 1024 * 1024,
885            10,
886        );
887        let only_errors = env_bool("CODEX_HELPER_REQUEST_LOG_ONLY_ERRORS");
888        RequestLogOptions {
889            retention,
890            only_errors,
891        }
892    })
893}
894
895pub fn request_log_retention() -> LogRetention {
896    request_log_options().retention
897}
898
899fn append_json_line(path: &PathBuf, opt: RequestLogOptions, line: &str) -> bool {
900    append_line(path, opt.retention, line).is_ok()
901}
902
903#[allow(clippy::too_many_arguments)]
904pub fn log_request_with_debug(
905    request_id: Option<u64>,
906    service: &str,
907    method: &str,
908    path: &str,
909    status_code: u16,
910    duration_ms: u64,
911    ttfb_ms: Option<u64>,
912    station_name: Option<&str>,
913    provider_id: Option<String>,
914    endpoint_id: Option<String>,
915    provider_endpoint_key: Option<String>,
916    upstream_base_url: &str,
917    session_id: Option<String>,
918    session_identity_source: Option<SessionIdentitySource>,
919    cwd: Option<String>,
920    model: Option<String>,
921    reasoning_effort: Option<String>,
922    service_tier: ServiceTierLog,
923    codex_bridge: Option<CodexBridgeLog>,
924    usage: Option<UsageMetrics>,
925    route_decision: Option<RouteDecisionProvenance>,
926    retry: Option<RetryInfo>,
927    http_debug: Option<HttpDebugLog>,
928) {
929    let opt = request_log_options();
930    if opt.only_errors && (200..300).contains(&status_code) {
931        return;
932    }
933
934    let ts = now_ms();
935    let trace_id = request_id.map(|id| request_trace_id(service, id));
936
937    static DEBUG_SEQ: AtomicU64 = AtomicU64::new(0);
938    let mut http_debug_for_main = http_debug;
939    let mut http_debug_ref: Option<HttpDebugRef> = None;
940
941    let log_file_path = request_log_path();
942
943    let _guard = match log_lock().lock() {
944        Ok(g) => g,
945        Err(e) => e.into_inner(),
946    };
947
948    // Optional: write large http_debug blobs to a separate file and keep only a reference in requests.jsonl.
949    if http_debug_split_enabled()
950        && let Some(h) = http_debug_for_main.take()
951    {
952        let seq = DEBUG_SEQ.fetch_add(1, Ordering::Relaxed);
953        let id = format!("{ts}-{seq}");
954        let debug_entry = HttpDebugLogEntry {
955            id: &id,
956            timestamp_ms: ts,
957            request_id,
958            trace_id: trace_id.clone(),
959            service,
960            method,
961            path,
962            status_code,
963            duration_ms,
964            ttfb_ms,
965            station_name,
966            provider_id: provider_id.clone(),
967            endpoint_id: endpoint_id.clone(),
968            provider_endpoint_key: provider_endpoint_key.clone(),
969            upstream_base_url,
970            session_id: session_id.clone(),
971            session_identity_source,
972            cwd: cwd.clone(),
973            model: model.clone(),
974            reasoning_effort: reasoning_effort.clone(),
975            service_tier: service_tier.clone(),
976            codex_bridge: codex_bridge.clone(),
977            usage: usage.clone(),
978            route_decision: route_decision.clone(),
979            retry: retry.clone(),
980            http_debug: h,
981        };
982
983        let debug_path = debug_log_path();
984        let mut wrote_debug = false;
985        if let Ok(line) = serde_json::to_string(&debug_entry) {
986            wrote_debug = append_json_line(&debug_path, opt, &line);
987        }
988
989        if wrote_debug {
990            http_debug_ref = Some(HttpDebugRef {
991                id,
992                file: "requests_debug.jsonl".to_string(),
993            });
994        } else {
995            // If we failed to write the debug entry, fall back to inline logging to avoid losing data.
996            let HttpDebugLogEntry { http_debug, .. } = debug_entry;
997            http_debug_for_main = Some(http_debug);
998        }
999    }
1000
1001    let provider_signals = provider_signals_from_retry(retry.as_ref());
1002    let policy_actions = policy_actions_from_retry(retry.as_ref());
1003
1004    let entry = RequestLog {
1005        timestamp_ms: ts,
1006        request_id,
1007        trace_id,
1008        service,
1009        method,
1010        path,
1011        status_code,
1012        duration_ms,
1013        ttfb_ms,
1014        station_name,
1015        provider_id,
1016        endpoint_id,
1017        provider_endpoint_key,
1018        upstream_base_url,
1019        session_id,
1020        session_identity_source,
1021        cwd,
1022        model,
1023        reasoning_effort,
1024        service_tier,
1025        codex_bridge,
1026        usage,
1027        http_debug: http_debug_for_main,
1028        http_debug_ref,
1029        route_decision,
1030        retry,
1031        provider_signals,
1032        policy_actions,
1033    };
1034
1035    if let Ok(line) = serde_json::to_string(&entry) {
1036        let _ = append_json_line(&log_file_path, opt, &line);
1037    }
1038
1039    if let Ok(payload) = serde_json::to_value(&entry) {
1040        append_control_trace_payload(
1041            opt,
1042            "request_completed",
1043            Some(service),
1044            request_id,
1045            Some("request_completed"),
1046            ts,
1047            payload,
1048        );
1049    }
1050}
1051
1052#[cfg(test)]
1053#[path = "logging/tests.rs"]
1054mod tests;
codex_helper_core/logging.rs

codex_helper_core/
logging.rs
