codex_helper_core/
logging.rs

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

codex_helper_core/
logging.rs
