From 021baab744ef5de0c1143e1e10dc18882a5eb711 Mon Sep 17 00:00:00 2001 From: Wuming Gong Date: Fri, 9 Oct 2026 22:06:12 -0700 Subject: [PATCH 1/3] fix(codex): log the empty-completion retries and the final 503 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An empty Codex completion is currently invisible in serve-$PORT.log. The retry loop writes nothing on any of its exits, so an operator holding a client-side `503 Codex completed without producing output` and a request id has no server-side record to correlate it with, and no way to tell the ~157 s wait apart from a hang, a proxy timeout or a network fault. Three warn records, no behavior change: - `codex_empty_completion_retry`, buffered path, per retry — reqId, transport, model, failedAttempt, maxAttempts, delayMs, ms. Same shape as the existing `buffered_transport_retry` record. - `codex_empty_completion_retry`, live path, once per empty terminal event, with `stream: true`. - `codex_empty_completion_exhausted` on give-up — reqId, transport, model, attempts, reason, ms. `reason` separates `max_attempts` from `backoff_budget`; both produce the same 503, so the log is the only place the difference shows. Every other upstream failure on this code path is already logged — the transport-error arm twenty lines above emits a full `codex_upstream_request_failed` — so this one was the outlier. Closes #177 Co-Authored-By: Claude Opus 5 (1M context) --- src/providers/codex/mod.rs | 104 +++++++++++++++++++++++++++++++++++++ 1 file changed, 104 insertions(+) diff --git a/src/providers/codex/mod.rs b/src/providers/codex/mod.rs index 280f9d34..2d993a8f 100644 --- a/src/providers/codex/mod.rs +++ b/src/providers/codex/mod.rs @@ -404,16 +404,56 @@ impl CodexProvider { let error = empty_buffered_completion_error(); drop_live_continuation_for_retry(&mut continuation); if attempt >= MAX_EMPTY_COMPLETION_RETRIES { + log.warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &req_id, + transport, + &resolved.model, + attempt + 1, + "max_attempts", + upstream_started_at.elapsed().as_millis(), + )), + ); abort_compaction_attempt(ctx.session_id.as_deref(), compaction_attempt); abort_continuation_for_owner(&request_continuation); return map_codex_error_to_response(&error); } let delay = compute_backoff_delay(attempt, None); if delay.exceeds_budget { + log.warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &req_id, + transport, + &resolved.model, + attempt + 1, + "backoff_budget", + upstream_started_at.elapsed().as_millis(), + )), + ); abort_compaction_attempt(ctx.session_id.as_deref(), compaction_attempt); abort_continuation_for_owner(&request_continuation); return map_codex_error_to_response(&error); } + log.warn( + "codex_empty_completion_retry", + Some(serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(&req_id)), + ("transport".to_string(), serde_json::json!(transport)), + ("model".to_string(), serde_json::json!(&resolved.model)), + ("failedAttempt".to_string(), serde_json::json!(attempt + 1)), + ( + "maxAttempts".to_string(), + serde_json::json!(MAX_EMPTY_COMPLETION_RETRIES + 1), + ), + ("delayMs".to_string(), serde_json::json!(delay.wait_ms)), + ( + "ms".to_string(), + serde_json::json!(upstream_started_at.elapsed().as_millis()), + ), + ])), + ); attempt += 1; sleep(delay.wait_ms).await; }; @@ -943,6 +983,18 @@ async fn live_stream_response_once( && is_codex_success_terminal_event(&payload) && !translator.has_semantic_output() { + create_logger("codex").warn( + "codex_empty_completion_retry", + Some(serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(&ctx.req_id)), + ( + "transport".to_string(), + serde_json::json!(config::codex_transport().as_str()), + ), + ("model".to_string(), serde_json::json!(model)), + ("stream".to_string(), serde_json::json!(true)), + ])), + ); return provider_retry(&upstream_events, empty_live_completion_error()); } if translator.has_semantic_output() && !pending_chunk.is_empty() { @@ -1265,6 +1317,30 @@ where (headers, Body::from_stream(stream)).into_response() } +/// Log fields for giving up on an empty completion, on either exit. +/// +/// `reason` separates the two: `"max_attempts"` when the retry budget ran +/// out, `"backoff_budget"` when the next delay would have exceeded the +/// backoff budget. They produce the same 503, so the log is the only place +/// the difference is visible. +fn empty_completion_exhausted_fields( + req_id: &str, + transport: &str, + model: &str, + attempts: u32, + reason: &str, + elapsed_ms: u128, +) -> serde_json::Map { + serde_json::Map::from_iter([ + ("reqId".to_string(), serde_json::json!(req_id)), + ("transport".to_string(), serde_json::json!(transport)), + ("model".to_string(), serde_json::json!(model)), + ("attempts".to_string(), serde_json::json!(attempts)), + ("reason".to_string(), serde_json::json!(reason)), + ("ms".to_string(), serde_json::json!(elapsed_ms)), + ]) +} + fn empty_buffered_completion_error() -> client::CodexError { client::CodexError { status: 503, @@ -2181,6 +2257,34 @@ mod tests { assert_eq!(response.headers()["x-should-retry"], "false"); } + #[test] + fn empty_completion_exhausted_fields_distinguish_the_two_give_up_reasons() { + let max = empty_completion_exhausted_fields( + "req-1", + "websocket", + "gpt-6-sol", + 11, + "max_attempts", + 157_000, + ); + assert_eq!(max["reqId"], "req-1"); + assert_eq!(max["transport"], "websocket"); + assert_eq!(max["model"], "gpt-6-sol"); + assert_eq!(max["attempts"], 11); + assert_eq!(max["reason"], "max_attempts"); + assert_eq!(max["ms"], 157_000); + + let budget = empty_completion_exhausted_fields( + "req-1", + "websocket", + "gpt-6-sol", + 4, + "backoff_budget", + 20_000, + ); + assert_eq!(budget["reason"], "backoff_budget"); + } + #[test] fn live_start_statusless_websocket_handshake_error_is_retryable() { let err = client::CodexError { From 2b46661175008624b34aec7a259ca90a0d08c976 Mon Sep 17 00:00:00 2001 From: Wuming Gong Date: Sat, 10 Oct 2026 10:21:44 -0700 Subject: [PATCH 2/3] fix(codex): log the give-up on the live path too, not just the retries MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first commit added `codex_empty_completion_exhausted` only on the buffered path. The live path logs each retry but then gives up in `live_stream_response`'s `LiveStreamStart::Retry` arm, which emitted nothing, so a streamed request that exhausted its budget produced a 503 with no give-up record. Caught by the patch's own output: six hours of real traffic produced four requests with 11 `codex_empty_completion_retry` records each — the ceiling, so all four returned the 503 — and zero `exhausted` records. `is_empty_completion_error` keys off `EMPTY_CODEX_COMPLETION_DETAIL` so the record fires only for the empty-completion case and not for the other retryable errors sharing that loop. `live_stream_response` gains a `started_at` so `ms` is a real elapsed time rather than a placeholder. Co-Authored-By: Claude Opus 5 (1M context) --- src/providers/codex/mod.rs | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/src/providers/codex/mod.rs b/src/providers/codex/mod.rs index 2d993a8f..ca0583ac 100644 --- a/src/providers/codex/mod.rs +++ b/src/providers/codex/mod.rs @@ -766,6 +766,7 @@ async fn live_stream_response( transport: config::CodexTransport, ) -> Response { let model = model.to_string(); + let started_at = Instant::now(); let request_continuation = continuation.clone(); let mut cleanup = LiveRequestStateCleanup::new( request_continuation.clone(), @@ -865,11 +866,37 @@ async fn live_stream_response( continue; } if attempt >= MAX_RETRYABLE_LIVE_STREAM_RETRIES { + if is_empty_completion_error(&error) { + create_logger("codex").warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &ctx.req_id, + transport.as_str(), + &model, + attempt + 1, + "max_attempts", + started_at.elapsed().as_millis(), + )), + ); + } cleanup.abort(); return map_codex_error_to_response(&error); } let delay = compute_backoff_delay(attempt, error.retry_after.as_deref()); if delay.exceeds_budget { + if is_empty_completion_error(&error) { + create_logger("codex").warn( + "codex_empty_completion_exhausted", + Some(empty_completion_exhausted_fields( + &ctx.req_id, + transport.as_str(), + &model, + attempt + 1, + "backoff_budget", + started_at.elapsed().as_millis(), + )), + ); + } cleanup.abort(); return map_codex_error_to_response(&error); } @@ -1317,6 +1344,12 @@ where (headers, Body::from_stream(stream)).into_response() } +/// True when *error* is the empty-completion 503 rather than some other +/// retryable failure sharing the live-stream retry loop. +fn is_empty_completion_error(error: &client::CodexError) -> bool { + error.detail.as_deref() == Some(EMPTY_CODEX_COMPLETION_DETAIL) +} + /// Log fields for giving up on an empty completion, on either exit. /// /// `reason` separates the two: `"max_attempts"` when the retry budget ran From 664f511acc96c930dd1bc7baf3dba75e458fa774 Mon Sep 17 00:00:00 2001 From: Raine Virta Date: Sun, 25 Oct 2026 14:18:30 +0200 Subject: [PATCH 3/3] label configured transport in empty-completion logs The new diagnostics report the configured transport rather than implying the selected upstream transport. In auto mode, logging the setting as `configuredTransport` avoids confusing it with the HTTP or WebSocket route that actually handled a request. The live retry log now uses the transport value captured for that request instead of rereading configuration. This only changes diagnostic fields and their regression coverage; request routing and retry behavior are unchanged. --- src/providers/codex/mod.rs | 24 +++++++++++++++++------- 1 file changed, 17 insertions(+), 7 deletions(-) diff --git a/src/providers/codex/mod.rs b/src/providers/codex/mod.rs index ca0583ac..c97cf22f 100644 --- a/src/providers/codex/mod.rs +++ b/src/providers/codex/mod.rs @@ -440,7 +440,10 @@ impl CodexProvider { "codex_empty_completion_retry", Some(serde_json::Map::from_iter([ ("reqId".to_string(), serde_json::json!(&req_id)), - ("transport".to_string(), serde_json::json!(transport)), + ( + "configuredTransport".to_string(), + serde_json::json!(transport), + ), ("model".to_string(), serde_json::json!(&resolved.model)), ("failedAttempt".to_string(), serde_json::json!(attempt + 1)), ( @@ -837,6 +840,7 @@ async fn live_stream_response( request_continuation.clone(), request_body.clone(), compaction, + transport, ) .await { @@ -928,6 +932,7 @@ async fn live_stream_response_once( request_continuation: ContinuationReservation, request_body: translate::request::ResponsesRequest, compaction: LiveStreamCompaction, + configured_transport: config::CodexTransport, ) -> LiveStreamStart { let estimated_input_tokens = count_translated_tokens(&request_body); let mut translator = LiveStreamTranslator::with_estimated_input_tokens( @@ -1015,8 +1020,8 @@ async fn live_stream_response_once( Some(serde_json::Map::from_iter([ ("reqId".to_string(), serde_json::json!(&ctx.req_id)), ( - "transport".to_string(), - serde_json::json!(config::codex_transport().as_str()), + "configuredTransport".to_string(), + serde_json::json!(configured_transport.as_str()), ), ("model".to_string(), serde_json::json!(model)), ("stream".to_string(), serde_json::json!(true)), @@ -1358,7 +1363,7 @@ fn is_empty_completion_error(error: &client::CodexError) -> bool { /// the difference is visible. fn empty_completion_exhausted_fields( req_id: &str, - transport: &str, + configured_transport: &str, model: &str, attempts: u32, reason: &str, @@ -1366,7 +1371,10 @@ fn empty_completion_exhausted_fields( ) -> serde_json::Map { serde_json::Map::from_iter([ ("reqId".to_string(), serde_json::json!(req_id)), - ("transport".to_string(), serde_json::json!(transport)), + ( + "configuredTransport".to_string(), + serde_json::json!(configured_transport), + ), ("model".to_string(), serde_json::json!(model)), ("attempts".to_string(), serde_json::json!(attempts)), ("reason".to_string(), serde_json::json!(reason)), @@ -2117,6 +2125,7 @@ mod tests { compact_boundary: false, attempt: None, }, + config::CodexTransport::Http, ) .await { @@ -2294,14 +2303,15 @@ mod tests { fn empty_completion_exhausted_fields_distinguish_the_two_give_up_reasons() { let max = empty_completion_exhausted_fields( "req-1", - "websocket", + "auto", "gpt-6-sol", 11, "max_attempts", 157_000, ); assert_eq!(max["reqId"], "req-1"); - assert_eq!(max["transport"], "websocket"); + assert_eq!(max["configuredTransport"], "auto"); + assert!(max.get("transport").is_none()); assert_eq!(max["model"], "gpt-6-sol"); assert_eq!(max["attempts"], 11); assert_eq!(max["reason"], "max_attempts");