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(skip_serializing_if = "Option::is_none")]
436    pub reason: Option<String>,
437    #[serde(skip_serializing_if = "Option::is_none")]
438    pub status_code: Option<u16>,
439    #[serde(skip_serializing_if = "Option::is_none")]
440    pub error_class: Option<String>,
441    #[serde(skip_serializing_if = "Option::is_none")]
442    pub model: Option<String>,
443    #[serde(skip_serializing_if = "Option::is_none")]
444    pub upstream_headers_ms: Option<u64>,
445    #[serde(skip_serializing_if = "Option::is_none")]
446    pub duration_ms: Option<u64>,
447    #[serde(skip_serializing_if = "Option::is_none")]
448    pub cooldown_secs: Option<u64>,
449    #[serde(skip_serializing_if = "Option::is_none")]
450    pub cooldown_reason: Option<String>,
451    #[serde(default, skip_serializing_if = "provider_signals_is_empty")]
452    pub provider_signals: Vec<ProviderSignal>,
453    #[serde(default, skip_serializing_if = "policy_actions_is_empty")]
454    pub policy_actions: Vec<PolicyAction>,
455    #[serde(default, skip_serializing_if = "bool_is_false")]
456    pub skipped: bool,
457    pub raw: String,
458}
459
460#[derive(Debug, Serialize, Deserialize, Clone, PartialEq, Eq)]
461pub struct RetryInfo {
462    pub attempts: u32,
463    pub upstream_chain: Vec<String>,
464    #[serde(default, skip_serializing_if = "route_attempts_is_empty")]
465    pub route_attempts: Vec<RouteAttemptLog>,
466}
467
468impl RetryInfo {
469    pub fn route_attempts_or_derived(&self) -> Vec<RouteAttemptLog> {
470        if self.route_attempts.is_empty() {
471            parse_route_attempts_from_chain(&self.upstream_chain)
472        } else {
473            self.route_attempts.clone()
474        }
475    }
476
477    pub fn touches_station(&self, station_name: &str) -> bool {
478        let station_name = station_name.trim();
479        if station_name.is_empty() {
480            return false;
481        }
482        self.route_attempts_or_derived()
483            .iter()
484            .any(|attempt| attempt.station_name.as_deref() == Some(station_name))
485    }
486
487    pub fn touched_other_station(&self, final_station: Option<&str>) -> bool {
488        let Some(final_station) = final_station
489            .map(str::trim)
490            .filter(|station| !station.is_empty())
491        else {
492            return false;
493        };
494
495        self.route_attempts_or_derived()
496            .iter()
497            .filter_map(|attempt| attempt.station_name.as_deref())
498            .any(|station| station != final_station)
499    }
500}
501
502pub(crate) fn parse_route_attempts_from_chain(chain: &[String]) -> Vec<RouteAttemptLog> {
503    chain
504        .iter()
505        .enumerate()
506        .map(|(idx, raw)| parse_route_attempt_from_chain_entry(raw, idx as u32))
507        .collect()
508}
509
510fn parse_route_attempt_from_chain_entry(raw: &str, attempt_index: u32) -> RouteAttemptLog {
511    let raw = raw.trim();
512    let mut attempt = RouteAttemptLog {
513        attempt_index,
514        decision: "observed".to_string(),
515        raw: raw.to_string(),
516        ..Default::default()
517    };
518
519    if raw.starts_with("all_upstreams_avoided") {
520        attempt.decision = "all_upstreams_avoided".to_string();
521        attempt.reason = route_chain_value(raw, "total").map(|total| format!("total={total}"));
522        attempt.skipped = true;
523        return attempt;
524    }
525
526    let (target, metadata, upstream_index) = split_route_chain_entry(raw);
527    attempt.upstream_index = upstream_index;
528    if let Some(target) = target {
529        let (station_name, upstream_base_url) = parse_route_chain_target(target);
530        attempt.station_name = station_name;
531        attempt.upstream_base_url = upstream_base_url;
532    }
533    apply_route_chain_identity_metadata(&mut attempt, raw);
534
535    if let Some(status_code) =
536        route_chain_value(metadata, "status").and_then(|value| value.parse::<u16>().ok())
537    {
538        attempt.status_code = Some(status_code);
539        attempt.decision = if (200..300).contains(&status_code) {
540            "completed".to_string()
541        } else {
542            "failed_status".to_string()
543        };
544    }
545
546    if let Some(error_class) =
547        route_chain_value(metadata, "class").filter(|value| !value.eq_ignore_ascii_case("-"))
548    {
549        if matches!(
550            error_class.as_str(),
551            "reasoning_guard_triggered" | "reasoning_guard_blocked"
552        ) {
553            attempt.decision = "failed_reasoning_guard".to_string();
554        }
555        attempt.error_class = Some(error_class);
556    }
557    if let Some(reason) = route_chain_value(metadata, "reason") {
558        attempt.reason = Some(reason);
559    }
560    if let Some(model) = route_chain_value(metadata, "model") {
561        attempt.model = Some(model);
562    }
563
564    if let Some(model) = route_chain_value(metadata, "skipped_unsupported_model") {
565        attempt.decision = "skipped_capability_mismatch".to_string();
566        attempt.reason = Some("unsupported_model".to_string());
567        attempt.model = Some(model);
568        attempt.skipped = true;
569    }
570
571    if let Some(error) = route_chain_value(metadata, "transport_error") {
572        attempt.decision = "failed_transport".to_string();
573        attempt.reason = Some(error);
574        attempt.error_class = Some("upstream_transport_error".to_string());
575    }
576
577    if let Some(error) = route_chain_value(metadata, "target_build_error") {
578        attempt.decision = "failed_target_build".to_string();
579        attempt.reason = Some(error);
580        attempt.error_class = Some("target_build_error".to_string());
581    }
582
583    if let Some(error) = route_chain_value(metadata, "body_read_error") {
584        attempt.decision = "failed_body_read".to_string();
585        attempt.reason = Some(error);
586        attempt.error_class = Some("upstream_body_read_error".to_string());
587    }
588    if let Some(error) = route_chain_value(metadata, "body_too_large") {
589        attempt.decision = "failed_body_too_large".to_string();
590        attempt.reason = Some(error);
591        attempt.error_class = Some("upstream_response_body_too_large".to_string());
592    }
593
594    attempt
595}
596
597fn apply_route_chain_identity_metadata(attempt: &mut RouteAttemptLog, raw: &str) {
598    if let Some(station) = route_chain_value(raw, "station") {
599        attempt.station_name = non_empty_str(station.as_str()).map(ToOwned::to_owned);
600    }
601    if let Some(provider_endpoint_key) = route_chain_value(raw, "endpoint") {
602        let provider_endpoint_key = provider_endpoint_key.trim().to_string();
603        if !provider_endpoint_key.is_empty() && provider_endpoint_key != "-" {
604            let parts = provider_endpoint_key.split('/').collect::<Vec<_>>();
605            if parts.len() >= 3 {
606                attempt.provider_id = non_empty_str(parts[1]).map(ToOwned::to_owned);
607                attempt.endpoint_id = non_empty_str(parts[2]).map(ToOwned::to_owned);
608            }
609            attempt.provider_endpoint_key = Some(provider_endpoint_key);
610        }
611    }
612    if let Some(group) = route_chain_value(raw, "group").and_then(|value| value.parse::<u32>().ok())
613    {
614        attempt.preference_group = Some(group);
615    }
616    if let Some(station) = route_chain_value(raw, "compat_station") {
617        attempt.station_name = non_empty_str(station.as_str()).map(ToOwned::to_owned);
618    }
619    if let Some(index) =
620        route_chain_value(raw, "upstream_index").and_then(|value| value.parse::<usize>().ok())
621    {
622        attempt.upstream_index = Some(index);
623    }
624    if let Some(url) = route_chain_value(raw, "url") {
625        attempt.upstream_base_url = non_empty_str(url.as_str()).map(ToOwned::to_owned);
626    }
627    if let Some(indices) = route_chain_value(raw, "avoid_candidates") {
628        attempt.avoided_candidate_indices = parse_usize_list(indices.as_str());
629    }
630    if let Some(indices) = route_chain_value(raw, "avoid") {
631        attempt.avoid_for_station = parse_usize_list(indices.as_str());
632    }
633}
634
635fn parse_usize_list(raw: &str) -> Vec<usize> {
636    raw.split(',')
637        .filter_map(|part| part.trim().parse::<usize>().ok())
638        .collect()
639}
640
641fn split_route_chain_entry(raw: &str) -> (Option<&str>, &str, Option<usize>) {
642    if let Some(idx_start) = raw.find(" (idx=") {
643        let target = raw[..idx_start].trim();
644        let after_idx = &raw[idx_start + " (idx=".len()..];
645        if let Some(idx_end) = after_idx.find(')') {
646            let upstream_index = after_idx[..idx_end].trim().parse::<usize>().ok();
647            let metadata = after_idx[idx_end + 1..].trim();
648            return (non_empty_str(target), metadata, upstream_index);
649        }
650        return (non_empty_str(target), after_idx.trim(), None);
651    }
652
653    if let Some(metadata_start) = first_route_chain_key_start(raw) {
654        let target = raw[..metadata_start].trim();
655        let metadata = raw[metadata_start..].trim();
656        return (non_empty_str(target), metadata, None);
657    }
658
659    (non_empty_str(raw), "", None)
660}
661
662fn parse_route_chain_target(target: &str) -> (Option<String>, Option<String>) {
663    let target = target.trim();
664    if target.is_empty() {
665        return (None, None);
666    }
667    if target.starts_with("http://") || target.starts_with("https://") {
668        return (None, Some(target.to_string()));
669    }
670
671    if let Some(pos) = target.find(":http://").or_else(|| target.find(":https://")) {
672        let station = target[..pos].trim();
673        let base_url = target[pos + 1..].trim();
674        return (
675            non_empty_str(station).map(ToOwned::to_owned),
676            non_empty_str(base_url).map(ToOwned::to_owned),
677        );
678    }
679
680    (None, Some(target.to_string()))
681}
682
683fn first_route_chain_key_start(raw: &str) -> Option<usize> {
684    ROUTE_CHAIN_KEYS
685        .iter()
686        .filter_map(|key| find_route_chain_key(raw, format!("{key}=").as_str()))
687        .min()
688}
689
690fn route_chain_value(raw: &str, key: &str) -> Option<String> {
691    let needle = format!("{key}=");
692    let start = find_route_chain_key(raw, needle.as_str())?;
693    let value_start = start + needle.len();
694    let value_end = ROUTE_CHAIN_KEYS
695        .iter()
696        .filter(|candidate| **candidate != key)
697        .filter_map(|candidate| {
698            raw[value_start..]
699                .find(&format!(" {candidate}="))
700                .map(|offset| value_start + offset)
701        })
702        .min()
703        .unwrap_or(raw.len());
704    non_empty_str(raw[value_start..value_end].trim()).map(ToOwned::to_owned)
705}
706
707fn find_route_chain_key(raw: &str, needle: &str) -> Option<usize> {
708    let mut offset = 0usize;
709    while let Some(pos) = raw[offset..].find(needle) {
710        let absolute = offset + pos;
711        if absolute == 0 || raw[..absolute].ends_with(' ') {
712            return Some(absolute);
713        }
714        offset = absolute + needle.len();
715    }
716    None
717}
718
719fn non_empty_str(value: &str) -> Option<&str> {
720    let value = value.trim();
721    if value.is_empty() { None } else { Some(value) }
722}
723
724const ROUTE_CHAIN_KEYS: &[&str] = &[
725    "status",
726    "class",
727    "model",
728    "transport_error",
729    "target_build_error",
730    "body_read_error",
731    "body_too_large",
732    "skipped_unsupported_model",
733    "total",
734    "station",
735    "endpoint",
736    "group",
737    "compat_station",
738    "upstream_index",
739    "url",
740    "avoid_candidates",
741    "avoid",
742];
743
744#[derive(Debug, Serialize)]
745struct HttpDebugLogEntry<'a> {
746    pub id: &'a str,
747    pub timestamp_ms: u64,
748    #[serde(skip_serializing_if = "Option::is_none")]
749    pub request_id: Option<u64>,
750    #[serde(skip_serializing_if = "Option::is_none")]
751    pub trace_id: Option<String>,
752    pub service: &'a str,
753    pub method: &'a str,
754    pub path: &'a str,
755    pub status_code: u16,
756    pub duration_ms: u64,
757    #[serde(skip_serializing_if = "Option::is_none")]
758    pub ttfb_ms: Option<u64>,
759    #[serde(skip_serializing_if = "Option::is_none")]
760    pub station_name: Option<&'a str>,
761    #[serde(skip_serializing_if = "Option::is_none")]
762    pub provider_id: Option<String>,
763    #[serde(skip_serializing_if = "Option::is_none")]
764    pub endpoint_id: Option<String>,
765    #[serde(skip_serializing_if = "Option::is_none")]
766    pub provider_endpoint_key: Option<String>,
767    pub upstream_base_url: &'a str,
768    #[serde(skip_serializing_if = "Option::is_none")]
769    pub session_id: Option<String>,
770    #[serde(skip_serializing_if = "Option::is_none")]
771    pub session_identity_source: Option<SessionIdentitySource>,
772    #[serde(skip_serializing_if = "Option::is_none")]
773    pub cwd: Option<String>,
774    #[serde(skip_serializing_if = "Option::is_none")]
775    pub model: Option<String>,
776    #[serde(skip_serializing_if = "Option::is_none")]
777    pub reasoning_effort: Option<String>,
778    #[serde(skip_serializing_if = "service_tier_log_is_empty", default)]
779    pub service_tier: ServiceTierLog,
780    #[serde(skip_serializing_if = "Option::is_none")]
781    pub codex_bridge: Option<CodexBridgeLog>,
782    #[serde(skip_serializing_if = "Option::is_none")]
783    pub usage: Option<UsageMetrics>,
784    #[serde(skip_serializing_if = "Option::is_none")]
785    pub route_decision: Option<RouteDecisionProvenance>,
786    #[serde(skip_serializing_if = "Option::is_none")]
787    pub retry: Option<RetryInfo>,
788    pub http_debug: HttpDebugLog,
789}
790
791#[derive(Debug, Clone, Copy)]
792struct RequestLogOptions {
793    retention: LogRetention,
794    only_errors: bool,
795}
796
797pub fn request_log_path() -> PathBuf {
798    proxy_home_dir().join("logs").join("requests.jsonl")
799}
800
801fn debug_log_path() -> PathBuf {
802    proxy_home_dir().join("logs").join("requests_debug.jsonl")
803}
804
805fn log_lock() -> &'static Mutex<()> {
806    static LOCK: OnceLock<Mutex<()>> = OnceLock::new();
807    LOCK.get_or_init(|| Mutex::new(()))
808}
809
810fn http_debug_split_enabled() -> bool {
811    // When HTTP debug is enabled for all requests, splitting is strongly recommended to keep
812    // the main request log lightweight. Users can also enable splitting explicitly.
813    env_bool_default("CODEX_HELPER_HTTP_DEBUG_SPLIT", true) || http_debug_options().all
814}
815
816fn request_log_options() -> RequestLogOptions {
817    static OPT: OnceLock<RequestLogOptions> = OnceLock::new();
818    *OPT.get_or_init(|| {
819        let retention = LogRetention::from_env(
820            "CODEX_HELPER_REQUEST_LOG_MAX_BYTES",
821            "CODEX_HELPER_REQUEST_LOG_MAX_FILES",
822            50 * 1024 * 1024,
823            10,
824        );
825        let only_errors = env_bool("CODEX_HELPER_REQUEST_LOG_ONLY_ERRORS");
826        RequestLogOptions {
827            retention,
828            only_errors,
829        }
830    })
831}
832
833pub fn request_log_retention() -> LogRetention {
834    request_log_options().retention
835}
836
837fn append_json_line(path: &PathBuf, opt: RequestLogOptions, line: &str) -> bool {
838    append_line(path, opt.retention, line).is_ok()
839}
840
841#[allow(clippy::too_many_arguments)]
842pub fn log_request_with_debug(
843    request_id: Option<u64>,
844    service: &str,
845    method: &str,
846    path: &str,
847    status_code: u16,
848    duration_ms: u64,
849    ttfb_ms: Option<u64>,
850    station_name: Option<&str>,
851    provider_id: Option<String>,
852    endpoint_id: Option<String>,
853    provider_endpoint_key: Option<String>,
854    upstream_base_url: &str,
855    session_id: Option<String>,
856    session_identity_source: Option<SessionIdentitySource>,
857    cwd: Option<String>,
858    model: Option<String>,
859    reasoning_effort: Option<String>,
860    service_tier: ServiceTierLog,
861    codex_bridge: Option<CodexBridgeLog>,
862    usage: Option<UsageMetrics>,
863    route_decision: Option<RouteDecisionProvenance>,
864    retry: Option<RetryInfo>,
865    http_debug: Option<HttpDebugLog>,
866) {
867    let opt = request_log_options();
868    if opt.only_errors && (200..300).contains(&status_code) {
869        return;
870    }
871
872    let ts = now_ms();
873    let trace_id = request_id.map(|id| request_trace_id(service, id));
874
875    static DEBUG_SEQ: AtomicU64 = AtomicU64::new(0);
876    let mut http_debug_for_main = http_debug;
877    let mut http_debug_ref: Option<HttpDebugRef> = None;
878
879    let log_file_path = request_log_path();
880
881    let _guard = match log_lock().lock() {
882        Ok(g) => g,
883        Err(e) => e.into_inner(),
884    };
885
886    // Optional: write large http_debug blobs to a separate file and keep only a reference in requests.jsonl.
887    if http_debug_split_enabled()
888        && let Some(h) = http_debug_for_main.take()
889    {
890        let seq = DEBUG_SEQ.fetch_add(1, Ordering::Relaxed);
891        let id = format!("{ts}-{seq}");
892        let debug_entry = HttpDebugLogEntry {
893            id: &id,
894            timestamp_ms: ts,
895            request_id,
896            trace_id: trace_id.clone(),
897            service,
898            method,
899            path,
900            status_code,
901            duration_ms,
902            ttfb_ms,
903            station_name,
904            provider_id: provider_id.clone(),
905            endpoint_id: endpoint_id.clone(),
906            provider_endpoint_key: provider_endpoint_key.clone(),
907            upstream_base_url,
908            session_id: session_id.clone(),
909            session_identity_source,
910            cwd: cwd.clone(),
911            model: model.clone(),
912            reasoning_effort: reasoning_effort.clone(),
913            service_tier: service_tier.clone(),
914            codex_bridge: codex_bridge.clone(),
915            usage: usage.clone(),
916            route_decision: route_decision.clone(),
917            retry: retry.clone(),
918            http_debug: h,
919        };
920
921        let debug_path = debug_log_path();
922        let mut wrote_debug = false;
923        if let Ok(line) = serde_json::to_string(&debug_entry) {
924            wrote_debug = append_json_line(&debug_path, opt, &line);
925        }
926
927        if wrote_debug {
928            http_debug_ref = Some(HttpDebugRef {
929                id,
930                file: "requests_debug.jsonl".to_string(),
931            });
932        } else {
933            // If we failed to write the debug entry, fall back to inline logging to avoid losing data.
934            let HttpDebugLogEntry { http_debug, .. } = debug_entry;
935            http_debug_for_main = Some(http_debug);
936        }
937    }
938
939    let provider_signals = provider_signals_from_retry(retry.as_ref());
940    let policy_actions = policy_actions_from_retry(retry.as_ref());
941
942    let entry = RequestLog {
943        timestamp_ms: ts,
944        request_id,
945        trace_id,
946        service,
947        method,
948        path,
949        status_code,
950        duration_ms,
951        ttfb_ms,
952        station_name,
953        provider_id,
954        endpoint_id,
955        provider_endpoint_key,
956        upstream_base_url,
957        session_id,
958        session_identity_source,
959        cwd,
960        model,
961        reasoning_effort,
962        service_tier,
963        codex_bridge,
964        usage,
965        http_debug: http_debug_for_main,
966        http_debug_ref,
967        route_decision,
968        retry,
969        provider_signals,
970        policy_actions,
971    };
972
973    if let Ok(line) = serde_json::to_string(&entry) {
974        let _ = append_json_line(&log_file_path, opt, &line);
975    }
976
977    if let Ok(payload) = serde_json::to_value(&entry) {
978        append_control_trace_payload(
979            opt,
980            "request_completed",
981            Some(service),
982            request_id,
983            Some("request_completed"),
984            ts,
985            payload,
986        );
987    }
988}
989
990#[cfg(test)]
991#[path = "logging/tests.rs"]
992mod tests;
codex_helper_core/logging.rs

codex_helper_core/
logging.rs
